You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@karaf.apache.org by AoteaSteve <st...@gmail.com> on 2019/03/27 23:29:06 UTC
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
Re: Delay when adding or removing features?
Posted by AoteaSteve <st...@gmail.com>.
JB,
[resending - ignore the duplicate message if it turns up]
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
--
Sent from: http://karaf.922171.n3.nabble.com/Karaf-User-f930749.html
RE: Delay when adding or removing features?
Posted by st...@gmail.com.
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é <jb...@nanthrax.net>
Sent: Wednesday, 17 April 2019 12:53 AM
To: user@karaf.apache.org
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, steve.g.chapman@gmail.com 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é <jb...@nanthrax.net>
> Sent: Tuesday, 16 April 2019 9:06 PM
> To: user@karaf.apache.org
> 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, steve.g.chapman@gmail.com 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 <st...@gmail.com>
>> Sent: Thursday, 28 March 2019 12:29 PM
>> To: user@karaf.apache.org
>> 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é
> jbonofre@apache.org
> http://blog.nanthrax.net
> Talend - http://www.talend.com
>
--
Jean-Baptiste Onofré
jbonofre@apache.org
http://blog.nanthrax.net
Talend - http://www.talend.com
Re: Delay when adding or removing features?
Posted by Jean-Baptiste Onofré <jb...@nanthrax.net>.
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, steve.g.chapman@gmail.com 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é <jb...@nanthrax.net>
> Sent: Tuesday, 16 April 2019 9:06 PM
> To: user@karaf.apache.org
> 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, steve.g.chapman@gmail.com 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 <st...@gmail.com>
>> Sent: Thursday, 28 March 2019 12:29 PM
>> To: user@karaf.apache.org
>> 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é
> jbonofre@apache.org
> http://blog.nanthrax.net
> Talend - http://www.talend.com
>
--
Jean-Baptiste Onofré
jbonofre@apache.org
http://blog.nanthrax.net
Talend - http://www.talend.com
RE: Delay when adding or removing features?
Posted by st...@gmail.com.
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é <jb...@nanthrax.net>
Sent: Tuesday, 16 April 2019 9:06 PM
To: user@karaf.apache.org
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, steve.g.chapman@gmail.com 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 <st...@gmail.com>
> Sent: Thursday, 28 March 2019 12:29 PM
> To: user@karaf.apache.org
> 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é
jbonofre@apache.org
http://blog.nanthrax.net
Talend - http://www.talend.com
Re: Delay when adding or removing features?
Posted by Jean-Baptiste Onofré <jb...@nanthrax.net>.
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, steve.g.chapman@gmail.com 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 <st...@gmail.com>
> Sent: Thursday, 28 March 2019 12:29 PM
> To: user@karaf.apache.org
> 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é
jbonofre@apache.org
http://blog.nanthrax.net
Talend - http://www.talend.com
RE: Delay when adding or removing features?
Posted by st...@gmail.com.
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 <st...@gmail.com>
Sent: Thursday, 28 March 2019 12:29 PM
To: user@karaf.apache.org
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