You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@camel.apache.org by Victor NOËL <vi...@linagora.com> on 2015/12/17 09:37:08 UTC
Very long processing of the Consumer in the file component…
Hi,
I set-up a route with the following consumer URI:
from("file:///tmp/junit6150402493774267253/in?initialDelay=500")...
At one point in the log I get the following information:
2015/12/16 18:11:26,278 GMT+0100 FINE
[org.apache.camel.impl.DefaultScheduledPollConsumerScheduler] :
Scheduling poll (fixed delay) with initialDelay: 500, delay: 500
(milliseconds) for:
Endpoint[file:///tmp/junit6150402493774267253/in?initialDelay=500]
2015/12/16 18:11:26,282 GMT+0100 INFO
[org.apache.camel.impl.DefaultCamelContext] : Route: route3 started and
consuming from:
Endpoint[file:///tmp/junit6150402493774267253/in?initialDelay=500]
Just after starting it, I simply move a file into the following directory.
Then more or less 500ms after the first log, later there is the first poll:
2015/12/16 18:11:26,910 GMT+0100 FINE
[org.apache.camel.component.file.FileConsumer] : Took 0.006 seconds to
poll: /tmp/junit6150402493774267253/in
And then after that, 3 seconds later, I get this message (which
according to the code is logged before the Exchange are sent…)
2015/12/16 18:11:29,191 GMT+0100 FINE
[org.apache.camel.component.file.FileConsumer] : Total 1 files to consume
How come 3 seconds passes before the exchange is sent into the route?
Thank you for your help (I'm using Camel 2.16.0).
Re: Very long processing of the Consumer in the file component…
Posted by Victor NOËL <vi...@linagora.com>.
Thanks for your answer.
The problem is that it happens on our CI infrastructure (and not all the
times), so it's difficult to debug it. On my machine everything works as
desired!
Well, at least if another person gets this problem, now she knows she is
not alone :)
I will switch to another component to do my tests, it wasn't very
important to use file for me.
Thanks
Le 18/12/2015 22:22, Jon Anstey a écrit :
> Hmm not sure what is up here. Haven't seen this myself :-) Maybe try taking
> a few thread dumps during this 3 second period to see if anything is
> holding up the processing?
> On Dec 17, 2015 5:09 AM, "Victor NOËL" <vi...@linagora.com> wrote:
>
>> Also, to complete, there is this log just before the poll related to the
>> locking, it is maybe linked:
>>
>> 2015/12/16 18:11:26,790 GMT+0100 FINE
>> [org.apache.camel.component.file.FileEndpoint] : Parameters for Generic
>> file process strategy {readLockMinAge=0, readLockMarkerFile=true,
>> readLock=markerFile, readLockRemoveOnCommit=false, readLockTimeout=10000,
>> readLockRemoveOnRollback=true, readLockLoggingLevel=WARN,
>> readLockDeleteOrphanLockFiles=true, readLockMinLength=1,
>> readLockCheckInterval=1000}
>> 2015/12/16 18:11:26,901 GMT+0100 FINE
>> [org.apache.camel.component.file.FileEndpoint] : Using Generic file process
>> strategy:
>> org.apache.camel.component.file.strategy.GenericFileRenameProcessStrategy@4266b6
>> 2015/12/16 18:11:26,903 GMT+0100 FINE
>> [org.apache.camel.component.file.strategy.MarkerFileExclusiveReadLockStrategy]
>> : Prepare on startup by deleting orphaned lock files from:
>> /tmp/junit6150402493774267253/in
>>
>> Also the problem does not happen all the time and on all my machines…
>>
>>
>> Le 17/12/2015 09:37, Victor NOËL a écrit :
>>
>>> Hi,
>>>
>>> I set-up a route with the following consumer URI:
>>> from("file:///tmp/junit6150402493774267253/in?initialDelay=500")...
>>>
>>> At one point in the log I get the following information:
>>> 2015/12/16 18:11:26,278 GMT+0100 FINE
>>> [org.apache.camel.impl.DefaultScheduledPollConsumerScheduler] : Scheduling
>>> poll (fixed delay) with initialDelay: 500, delay: 500 (milliseconds) for:
>>> Endpoint[file:///tmp/junit6150402493774267253/in?initialDelay=500]
>>> 2015/12/16 18:11:26,282 GMT+0100 INFO
>>> [org.apache.camel.impl.DefaultCamelContext] : Route: route3 started and
>>> consuming from:
>>> Endpoint[file:///tmp/junit6150402493774267253/in?initialDelay=500]
>>>
>>> Just after starting it, I simply move a file into the following directory.
>>>
>>> Then more or less 500ms after the first log, later there is the first
>>> poll:
>>> 2015/12/16 18:11:26,910 GMT+0100 FINE
>>> [org.apache.camel.component.file.FileConsumer] : Took 0.006 seconds to
>>> poll: /tmp/junit6150402493774267253/in
>>>
>>> And then after that, 3 seconds later, I get this message (which according
>>> to the code is logged before the Exchange are sent…)
>>> 2015/12/16 18:11:29,191 GMT+0100 FINE
>>> [org.apache.camel.component.file.FileConsumer] : Total 1 files to consume
>>>
>>> How come 3 seconds passes before the exchange is sent into the route?
>>>
>>> Thank you for your help (I'm using Camel 2.16.0).
>>>
>>
Re: Very long processing of the Consumer in the file component…
Posted by Jon Anstey <ja...@gmail.com>.
Hmm not sure what is up here. Haven't seen this myself :-) Maybe try taking
a few thread dumps during this 3 second period to see if anything is
holding up the processing?
On Dec 17, 2015 5:09 AM, "Victor NOËL" <vi...@linagora.com> wrote:
> Also, to complete, there is this log just before the poll related to the
> locking, it is maybe linked:
>
> 2015/12/16 18:11:26,790 GMT+0100 FINE
> [org.apache.camel.component.file.FileEndpoint] : Parameters for Generic
> file process strategy {readLockMinAge=0, readLockMarkerFile=true,
> readLock=markerFile, readLockRemoveOnCommit=false, readLockTimeout=10000,
> readLockRemoveOnRollback=true, readLockLoggingLevel=WARN,
> readLockDeleteOrphanLockFiles=true, readLockMinLength=1,
> readLockCheckInterval=1000}
> 2015/12/16 18:11:26,901 GMT+0100 FINE
> [org.apache.camel.component.file.FileEndpoint] : Using Generic file process
> strategy:
> org.apache.camel.component.file.strategy.GenericFileRenameProcessStrategy@4266b6
> 2015/12/16 18:11:26,903 GMT+0100 FINE
> [org.apache.camel.component.file.strategy.MarkerFileExclusiveReadLockStrategy]
> : Prepare on startup by deleting orphaned lock files from:
> /tmp/junit6150402493774267253/in
>
> Also the problem does not happen all the time and on all my machines…
>
>
> Le 17/12/2015 09:37, Victor NOËL a écrit :
>
>> Hi,
>>
>> I set-up a route with the following consumer URI:
>> from("file:///tmp/junit6150402493774267253/in?initialDelay=500")...
>>
>> At one point in the log I get the following information:
>> 2015/12/16 18:11:26,278 GMT+0100 FINE
>> [org.apache.camel.impl.DefaultScheduledPollConsumerScheduler] : Scheduling
>> poll (fixed delay) with initialDelay: 500, delay: 500 (milliseconds) for:
>> Endpoint[file:///tmp/junit6150402493774267253/in?initialDelay=500]
>> 2015/12/16 18:11:26,282 GMT+0100 INFO
>> [org.apache.camel.impl.DefaultCamelContext] : Route: route3 started and
>> consuming from:
>> Endpoint[file:///tmp/junit6150402493774267253/in?initialDelay=500]
>>
>> Just after starting it, I simply move a file into the following directory.
>>
>> Then more or less 500ms after the first log, later there is the first
>> poll:
>> 2015/12/16 18:11:26,910 GMT+0100 FINE
>> [org.apache.camel.component.file.FileConsumer] : Took 0.006 seconds to
>> poll: /tmp/junit6150402493774267253/in
>>
>> And then after that, 3 seconds later, I get this message (which according
>> to the code is logged before the Exchange are sent…)
>> 2015/12/16 18:11:29,191 GMT+0100 FINE
>> [org.apache.camel.component.file.FileConsumer] : Total 1 files to consume
>>
>> How come 3 seconds passes before the exchange is sent into the route?
>>
>> Thank you for your help (I'm using Camel 2.16.0).
>>
>
>
Re: Very long processing of the Consumer in the file component…
Posted by Victor NOËL <vi...@linagora.com>.
Also, to complete, there is this log just before the poll related to the
locking, it is maybe linked:
2015/12/16 18:11:26,790 GMT+0100 FINE
[org.apache.camel.component.file.FileEndpoint] : Parameters for Generic
file process strategy {readLockMinAge=0, readLockMarkerFile=true,
readLock=markerFile, readLockRemoveOnCommit=false,
readLockTimeout=10000, readLockRemoveOnRollback=true,
readLockLoggingLevel=WARN, readLockDeleteOrphanLockFiles=true,
readLockMinLength=1, readLockCheckInterval=1000}
2015/12/16 18:11:26,901 GMT+0100 FINE
[org.apache.camel.component.file.FileEndpoint] : Using Generic file
process strategy:
org.apache.camel.component.file.strategy.GenericFileRenameProcessStrategy@4266b6
2015/12/16 18:11:26,903 GMT+0100 FINE
[org.apache.camel.component.file.strategy.MarkerFileExclusiveReadLockStrategy]
: Prepare on startup by deleting orphaned lock files from:
/tmp/junit6150402493774267253/in
Also the problem does not happen all the time and on all my machines…
Le 17/12/2015 09:37, Victor NOËL a écrit :
> Hi,
>
> I set-up a route with the following consumer URI:
> from("file:///tmp/junit6150402493774267253/in?initialDelay=500")...
>
> At one point in the log I get the following information:
> 2015/12/16 18:11:26,278 GMT+0100 FINE
> [org.apache.camel.impl.DefaultScheduledPollConsumerScheduler] :
> Scheduling poll (fixed delay) with initialDelay: 500, delay: 500
> (milliseconds) for:
> Endpoint[file:///tmp/junit6150402493774267253/in?initialDelay=500]
> 2015/12/16 18:11:26,282 GMT+0100 INFO
> [org.apache.camel.impl.DefaultCamelContext] : Route: route3 started
> and consuming from:
> Endpoint[file:///tmp/junit6150402493774267253/in?initialDelay=500]
>
> Just after starting it, I simply move a file into the following
> directory.
>
> Then more or less 500ms after the first log, later there is the first
> poll:
> 2015/12/16 18:11:26,910 GMT+0100 FINE
> [org.apache.camel.component.file.FileConsumer] : Took 0.006 seconds to
> poll: /tmp/junit6150402493774267253/in
>
> And then after that, 3 seconds later, I get this message (which
> according to the code is logged before the Exchange are sent…)
> 2015/12/16 18:11:29,191 GMT+0100 FINE
> [org.apache.camel.component.file.FileConsumer] : Total 1 files to consume
>
> How come 3 seconds passes before the exchange is sent into the route?
>
> Thank you for your help (I'm using Camel 2.16.0).