JB, I set the logging levels you identified and repeated the exercise of deleting a kar from the deploy folder and then later adding the same kar back to the deploy folder.
The associated section of the karaf log with trace entries is here - https://www.dropbox.com/s/t2odu2k7w5e6rwy/deploy%20delay%20karaf.log?dl=0 I notice lots of repeated logging like this: 2019-04-17T09:12:30,458 | DEBUG | downloader-6-thread-6 | AetherBasedResolver | 2 - org.ops4j.pax.url.mvn - 2.6.1 | Adding repo from inside multi dir: file:/C:/data/ksr-1.0.0/data/kar/FeedStorage-1.0.0-SNAPSHOT/@id=FeedStorage-1.0.0-SNAPSHOT The relevant times to look at in the log are: 1/ undeploy kar @ 2019-04-17T09:12:30,337 - downloader thread tracing stops @ 2019-04-17T09:12:59,043 (30 second delay) - dependency analysis complete @ 019-04-17T09:14:00,074 (60 second delay) - for some reason lots of other unrelated features are stopped/restarted at this time including activemq? - restarted features are all active again @ 2019-04-17T09:14:17,636 (17 second delay) 2/ deploy kar @ 2019-04-17T09:23:43,585 - downloader thread tracing stops @ 2019-04-17T09:23:45,925 (2 second delay) - dependency analysis complete @ 2019-04-17T09:24:39,063 (55 second delay) - dependent bundles installed and started @ 2019-04-17T09:24:39,306 (no delay) - downloader thread tracing stops @ 2019-04-17T09:24:39,311 (no delay) - feature install analysis complete @ 2019-04-17T09:26:37,875 (120 second delay) - new feature active @ 2019-04-17T09:26:39,893 (2 second delay) Thanks Steve -----Original Message----- From: Jean-Baptiste Onofré <[email protected]> Sent: Wednesday, 17 April 2019 12:53 AM To: [email protected] Subject: Re: Delay when adding or removing features? Thanks, as Karaf works fine at restart, the installation of the features itself once resolved seems pretty fast (and it checks the current status of the kar). I will take a look on the thread dumps. In the mean time, in etc/org.ops4j.pax.logging.cfg, you can enable trace on Pax URL and Aether: log4j2.logger.aether.name = shaded.org.eclipse.aether log4j2.logger.aether.level = TRACE log4j2.logger.http-headers.name = shaded.org.apache.http.headers log4j2.logger.http-headers.level = DEBUG log4j2.logger.maven.name = org.ops4j.pax.url.mvn log4j2.logger.maven.level = TRACE Regards JB On 16/04/2019 13:04, [email protected] wrote: > JB, > > Thanks for your reply. > > The kar/s are small - approx. 13KB. > > The transitive dependencies are all retrieved from a nexus server installed > on my laptop, same place as the karaf instance so I don’t think that can be > the issue. Also I see delays on deploy and undeploy and don’t think there > would be any download for the later. > > I tried a stop and start of karaf an it starts fine with all (5 kar based > modules) active in 25seconds. > > I was not sure how to set debug logging for pax-url - tried updating the > logging config to add a logger (name and level) for org.ops4j.pax.url with > level debug but that didn't seem to do the trick. > > I took some thread dumps during the delays and zipped them up along > with the karaf log covering the period and the kar file that I > undeployed and then re-deployed. The zip file is here > https://www.dropbox.com/s/7dja3qmxgbvfyva/deployprob.zip?dl=0 > > Regards > Steve > > -----Original Message----- > From: Jean-Baptiste Onofré <[email protected]> > Sent: Tuesday, 16 April 2019 9:06 PM > To: [email protected] > Subject: Re: Delay when adding or removing features? > > Hi Steve, > > is your kar large ? > > Don't you have transitive features that need to be downloaded ? > > 1. Can you try to just do a restart of karaf (without removing the > data > folder) once the kar is installed to see if it takes time just to start your > features ? > 2. Maybe add debug for the pax-url to identify potential download 3. Maybe > take a thread dump that you can send to me to identify where we spend time. > > Regards > JB > > On 16/04/2019 10:58, [email protected] wrote: >> Any assistance for this slow behaviour of my karaf 4.2.4 distribution >> for deploy/redeploy of a kar file? The delays are becoming painful. >> >> Can anyone suggest how I can diagnose the root cause? Is there some >> module I should enable debug logging on to see what is causing the delay? >> >> Once again the issue is that when I drop a kar file into the deploy >> folder there seem to be consistent 2 long delays to complete the >> deploy. The first delay is typically 45seconds while the karaf >> deployer identifies the changes that need to be performed to provide the >> feature dependencies of the kar. >> The second delay is typically 90seconds while the karaf deployer >> identifies the changes to perform to complete the install of the >> kar's feature. In both cases the actual deploy action is quick, it is >> only the deploy analysis that is slow, i.e. the time to install and >> start bundles once the reqd changes are known is quick. >> >> Thanks >> Steve >> >> >> -----Original Message----- >> From: AoteaSteve <[email protected]> >> Sent: Thursday, 28 March 2019 12:29 PM >> To: [email protected] >> Subject: Delay when adding or removing features? >> >> I have a Karaf 4.2.4 distribution. >> >> I find that when I drop a kar file into the deploy folder there is a >> constant long delay first while the changes to perform for the >> feature dependencies are identified and then while the changes to >> perform to complete the install of the kar's feature. >> >> I dont see anything in the log to indicate waht is happening but do >> know the processor is heavily used during these delays. >> >> Any advice on how I can investigate this? >> >> Example log snippet follows - see the delay from 11:24:13 - 11:24:54 >> for "adding features" - "changes to perform". Also the delay from >> 11:24:54 - >> 11:26:14 for "done" - "changes to perform": >> >> 11:24:13.834 INFO [fileinstall-C:\data\ksr-1.0.0/deploy] Found a .kar >> file to deploy. >> 11:24:13.838 INFO [fileinstall-C:\data\ksr-1.0.0/deploy] Installing >> KAR file C:\data\ksr-1.0.0\deploy\feed-storage-1.0.0-SNAPSHOT.kar >> 11:24:13.985 INFO [fileinstall-C:\data\ksr-1.0.0/deploy] Added >> feature repository >> 'mvn:com.clogic.newswire/feed-storage/1.0.0-SNAPSHOT/xml/features' >> 11:24:13.989 INFO [fileinstall-C:\data\ksr-1.0.0/deploy] Adding features: >> feed-storage/[1.0.0.SNAPSHOT,1.0.0.SNAPSHOT] >> 11:24:54.420 INFO [features-3-thread-1] Changes to perform: >> 11:24:54.421 INFO [features-3-thread-1] Region: root >> 11:24:54.423 INFO [features-3-thread-1] Bundles to install: >> 11:24:54.424 INFO [features-3-thread-1] >> mvn:org.apache.camel/camel-mongodb3/2.23.1 >> 11:24:54.424 INFO [features-3-thread-1] >> mvn:org.eclipse.jetty/jetty-http/9.4.12.v20180830 >> 11:24:54.425 INFO [features-3-thread-1] >> mvn:org.eclipse.jetty.websocket/websocket-common/9.4.12.v20180830 >> 11:24:54.426 INFO [features-3-thread-1] >> mvn:org.mongodb/mongo-java-driver/3.9.0 >> 11:24:54.427 INFO [features-3-thread-1] Installing bundles: >> 11:24:54.428 INFO [features-3-thread-1] >> mvn:org.apache.camel/camel-mongodb3/2.23.1 >> 11:24:54.492 INFO [features-3-thread-1] >> mvn:org.eclipse.jetty/jetty-http/9.4.12.v20180830 >> 11:24:54.494 INFO [features-3-thread-1] >> mvn:org.eclipse.jetty.websocket/websocket-common/9.4.12.v20180830 >> 11:24:54.495 INFO [features-3-thread-1] >> mvn:org.mongodb/mongo-java-driver/3.9.0 >> 11:24:54.548 INFO [features-3-thread-1] Starting bundles: >> 11:24:54.549 INFO [features-3-thread-1] >> org.mongodb.mongo-java-driver/3.9.0 >> 11:24:54.556 INFO [features-3-thread-1] >> org.apache.camel.camel-mongodb3/2.23.1 >> 11:24:54.569 INFO [features-3-thread-1] Done. >> 11:26:14.180 INFO [features-3-thread-1] Changes to perform: >> 11:26:14.181 INFO [features-3-thread-1] Region: root >> 11:26:14.183 INFO [features-3-thread-1] Bundles to install: >> 11:26:14.183 INFO [features-3-thread-1] >> mvn:com.clogic.newswire/feed-storage/1.0.0-SNAPSHOT >> 11:26:14.184 INFO [features-3-thread-1] >> mvn:org.eclipse.jetty/jetty-http/9.4.12.v20180830 >> 11:26:14.185 INFO [features-3-thread-1] >> mvn:org.eclipse.jetty.websocket/websocket-common/9.4.12.v20180830 >> 11:26:14.186 INFO [features-3-thread-1] Installing bundles: >> 11:26:14.186 INFO [features-3-thread-1] >> mvn:com.clogic.newswire/feed-storage/1.0.0-SNAPSHOT >> 11:26:14.245 INFO [features-3-thread-1] >> mvn:org.eclipse.jetty/jetty-http/9.4.12.v20180830 >> 11:26:14.247 INFO [features-3-thread-1] >> mvn:org.eclipse.jetty.websocket/websocket-common/9.4.12.v20180830 >> 11:26:14.273 INFO [features-3-thread-1] Starting bundles: >> 11:26:14.274 INFO [features-3-thread-1] feed-storage/1.0.0.SNAPSHOT >> 11:26:14.577 INFO [features-3-thread-1] Cluster created with settings >> {hosts=[localhost:27017], mode=SINGLE, requiredClusterType=UNKNOWN, >> serverSelectionTimeout='30000 ms', maxWaitQueueSize=500} >> 11:26:14.620 INFO [features-3-thread-1] Blueprint bundle >> feed-storage/1.0.0.SNAPSHOT has been started >> 11:26:14.621 INFO [Blueprint Event Dispatcher: 1] Attempting to start >> CamelContext: feed-storage >> 11:26:14.623 INFO [Blueprint Event Dispatcher: 1] Apache Camel 2.23.1 >> (CamelContext: feed-storage) is starting >> 11:26:14.623 INFO [Blueprint Event Dispatcher: 1] StreamCaching is >> enabled on CamelContext: feed-storage >> >> >> >> -- >> Sent from: http://karaf.922171.n3.nabble.com/Karaf-User-f930749.html >> > > -- > Jean-Baptiste Onofré > [email protected] > http://blog.nanthrax.net > Talend - http://www.talend.com > -- Jean-Baptiste Onofré [email protected] http://blog.nanthrax.net Talend - http://www.talend.com
