[infinispan-dev] More verbose logging

Sanne Grinovero sanne at infinispan.org
Wed Feb 20 04:57:47 EST 2013 

+1 for using categories

We could even experiment combining multiple categories, for example in
this case you could have a "RPCDispatcher" category and also have a
"RPCDispatcher.includeCacheEntries" which will make descriptions
more/less verbose.

Sanne

On 19 February 2013 17:19, David M. Lloyd <david.lloyd at redhat.com> wrote:
> This is one reason why I recommend logging using categories versus class
> names.  If you confine types of trace logging to specific categories
> which correspond to logical processes, then this allows the user to
> surgically select what information they wish to receive.  It is very
> often the case that one class is involved in several such logical processes.
>
> On 02/19/2013 10:35 AM, Manik Surtani wrote:
>> I also see this - 3 lines per segment, per cache!
>>
>> 2013-02-19 16:22:13,990 TRACE [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Received keys [] for segment 0 of cache ___defaultcache from node NodeA-62578
>> 2013-02-19 16:22:13,990 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Finished applying state for segment 0 of cache ___defaultcache
>> 2013-02-19 16:22:13,991 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Applying new state for segment 1 of cache ___defaultcache from node NodeA-62578: received 0 cache entries
>> 2013-02-19 16:22:13,991 TRACE [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Received keys [] for segment 1 of cache ___defaultcache from node NodeA-62578
>> 2013-02-19 16:22:13,991 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Finished applying state for segment 1 of cache ___defaultcache
>> 2013-02-19 16:22:13,992 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Applying new state for segment 2 of cache ___defaultcache from node NodeA-62578: received 0 cache entries
>> 2013-02-19 16:22:13,992 TRACE [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Received keys [] for segment 2 of cache ___defaultcache from node NodeA-62578
>> 2013-02-19 16:22:13,992 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Finished applying state for segment 2 of cache ___defaultcache
>> 2013-02-19 16:22:13,992 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Applying new state for segment 3 of cache ___defaultcache from node NodeA-62578: received 0 cache entries
>> 2013-02-19 16:22:13,993 TRACE [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Received keys [] for segment 3 of cache ___defaultcache from node NodeA-62578
>> 2013-02-19 16:22:13,993 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Finished applying state for segment 3 of cache ___defaultcache
>> 2013-02-19 16:22:13,993 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Applying new state for segment 4 of cache ___defaultcache from node NodeA-62578: received 0 cache entries
>> 2013-02-19 16:22:13,993 TRACE [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Received keys [] for segment 4 of cache ___defaultcache from node NodeA-62578
>> 2013-02-19 16:22:13,994 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Finished applying state for segment 4 of cache ___defaultcache
>>
>> Another candidate for a -Dinfinispan.logging.verbose guard?
>>
>> - M
>>
>>
>> On 19 Feb 2013, at 16:29, Manik Surtani <msurtani at redhat.com> wrote:
>>
>>> Guys,
>>>
>>> I see this emitted by the CommandAwareRpcDispatcher:
>>>
>>> 2013-02-19 16:22:13,988 TRACE [CommandAwareRpcDispatcher] (OOB-1,ISPN,NodeB-11464) Attempting to execute command: StateResponseCommand{cache=___defaultcache, origin=NodeA-62578, topologyId=1, stateChunks=[StateChunk{segmentId=0, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=1, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=2, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=3, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=4, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=5, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=6, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=7, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=8, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=9, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=10, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=11, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=12, cacheEntries=[], isLastChunk=true}!
>  ,!
>>    StateChunk{segmentId=13, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=14, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=15, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=17, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=16, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=19, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=18, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=21, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=20, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=23, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=22, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=25, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=24, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=27, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=26, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=29, cacheEntries=[], isLastChunk=true}, StateChu!
>  nk{!
>>   segmentId=28, cacheEntries=[], isLastChunk=true}, StateChunk{s!
>>   egmentId
>> =31, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=30, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=34, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=35, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=32, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=33, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=38, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=39, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=36, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=37, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=42, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=43, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=40, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=41, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=46, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=47, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=44, cacheE!
>  nt!
>>   ries=[], isLastChunk=true}, StateChunk{segmentId=45, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=51, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=50, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=49, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=48, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=55, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=54, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=53, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=52, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=59, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=58, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=57, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=56, cacheEntries=[], isLastChunk=true}]} [sender=NodeA-62578]
>>>
>>>
>>> Again, just 3 nodes, default segment size, but with TRACE level logging.
>>>
>>> a) This would explode to something huge if we have, say, a cluster of 100+ nodes with, say, 5000 segments.
>>> b) Each StateChunk is listing all of its entries!  Again, here this is fine since the cache is empty; but a running system with a few hundred GB of data would make enabling TRACE logging akin to a DoS attack.
>>>
>>> I agree that TRACE level logging on a running system is not recommended, and generally will slow things down a lot, but this has potential to bring a cluster down.  I imagine such information is only really useful in a lab or test environment when tracing edge-case consistency issues - so maybe we need a separate flag?  Perhaps a -Dinfinispan.logging.verbose=true, which would alter the output of StateResponseCommand.toString() accordingly?
>>>
>>> - M
>>>
>>> --
>>> Manik Surtani
>>> manik at jboss.org
>>> twitter.com/maniksurtani
>>>
>>> Platform Architect, JBoss Data Grid
>>> http://red.ht/data-grid
>>>
>>
>> --
>> Manik Surtani
>> manik at jboss.org
>> twitter.com/maniksurtani
>>
>> Platform Architect, JBoss Data Grid
>> http://red.ht/data-grid
>>
>>
>> _______________________________________________
>> infinispan-dev mailing list
>> infinispan-dev at lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>
>
> --
> - DML
> _______________________________________________
> infinispan-dev mailing list
> infinispan-dev at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/infinispan-dev

On 19 February 2013 17:19, David M. Lloyd <david.lloyd at redhat.com> wrote:
> This is one reason why I recommend logging using categories versus class
> names.  If you confine types of trace logging to specific categories
> which correspond to logical processes, then this allows the user to
> surgically select what information they wish to receive.  It is very
> often the case that one class is involved in several such logical processes.
>
> On 02/19/2013 10:35 AM, Manik Surtani wrote:
>> I also see this - 3 lines per segment, per cache!
>>
>> 2013-02-19 16:22:13,990 TRACE [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Received keys [] for segment 0 of cache ___defaultcache from node NodeA-62578
>> 2013-02-19 16:22:13,990 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Finished applying state for segment 0 of cache ___defaultcache
>> 2013-02-19 16:22:13,991 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Applying new state for segment 1 of cache ___defaultcache from node NodeA-62578: received 0 cache entries
>> 2013-02-19 16:22:13,991 TRACE [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Received keys [] for segment 1 of cache ___defaultcache from node NodeA-62578
>> 2013-02-19 16:22:13,991 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Finished applying state for segment 1 of cache ___defaultcache
>> 2013-02-19 16:22:13,992 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Applying new state for segment 2 of cache ___defaultcache from node NodeA-62578: received 0 cache entries
>> 2013-02-19 16:22:13,992 TRACE [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Received keys [] for segment 2 of cache ___defaultcache from node NodeA-62578
>> 2013-02-19 16:22:13,992 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Finished applying state for segment 2 of cache ___defaultcache
>> 2013-02-19 16:22:13,992 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Applying new state for segment 3 of cache ___defaultcache from node NodeA-62578: received 0 cache entries
>> 2013-02-19 16:22:13,993 TRACE [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Received keys [] for segment 3 of cache ___defaultcache from node NodeA-62578
>> 2013-02-19 16:22:13,993 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Finished applying state for segment 3 of cache ___defaultcache
>> 2013-02-19 16:22:13,993 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Applying new state for segment 4 of cache ___defaultcache from node NodeA-62578: received 0 cache entries
>> 2013-02-19 16:22:13,993 TRACE [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Received keys [] for segment 4 of cache ___defaultcache from node NodeA-62578
>> 2013-02-19 16:22:13,994 DEBUG [StateConsumerImpl] (OOB-1,ISPN,NodeB-11464) Finished applying state for segment 4 of cache ___defaultcache
>>
>> Another candidate for a -Dinfinispan.logging.verbose guard?
>>
>> - M
>>
>>
>> On 19 Feb 2013, at 16:29, Manik Surtani <msurtani at redhat.com> wrote:
>>
>>> Guys,
>>>
>>> I see this emitted by the CommandAwareRpcDispatcher:
>>>
>>> 2013-02-19 16:22:13,988 TRACE [CommandAwareRpcDispatcher] (OOB-1,ISPN,NodeB-11464) Attempting to execute command: StateResponseCommand{cache=___defaultcache, origin=NodeA-62578, topologyId=1, stateChunks=[StateChunk{segmentId=0, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=1, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=2, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=3, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=4, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=5, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=6, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=7, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=8, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=9, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=10, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=11, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=12, cacheEntries=[], isLastChunk=true}!
>  ,!
>>    StateChunk{segmentId=13, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=14, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=15, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=17, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=16, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=19, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=18, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=21, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=20, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=23, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=22, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=25, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=24, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=27, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=26, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=29, cacheEntries=[], isLastChunk=true}, StateChu!
>  nk{!
>>   segmentId=28, cacheEntries=[], isLastChunk=true}, StateChunk{s!
>>   egmentId
>> =31, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=30, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=34, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=35, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=32, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=33, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=38, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=39, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=36, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=37, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=42, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=43, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=40, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=41, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=46, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=47, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=44, cacheE!
>  nt!
>>   ries=[], isLastChunk=true}, StateChunk{segmentId=45, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=51, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=50, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=49, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=48, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=55, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=54, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=53, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=52, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=59, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=58, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=57, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=56, cacheEntries=[], isLastChunk=true}]} [sender=NodeA-62578]
>>>
>>>
>>> Again, just 3 nodes, default segment size, but with TRACE level logging.
>>>
>>> a) This would explode to something huge if we have, say, a cluster of 100+ nodes with, say, 5000 segments.
>>> b) Each StateChunk is listing all of its entries!  Again, here this is fine since the cache is empty; but a running system with a few hundred GB of data would make enabling TRACE logging akin to a DoS attack.
>>>
>>> I agree that TRACE level logging on a running system is not recommended, and generally will slow things down a lot, but this has potential to bring a cluster down.  I imagine such information is only really useful in a lab or test environment when tracing edge-case consistency issues - so maybe we need a separate flag?  Perhaps a -Dinfinispan.logging.verbose=true, which would alter the output of StateResponseCommand.toString() accordingly?
>>>
>>> - M
>>>
>>> --
>>> Manik Surtani
>>> manik at jboss.org
>>> twitter.com/maniksurtani
>>>
>>> Platform Architect, JBoss Data Grid
>>> http://red.ht/data-grid
>>>
>>
>> --
>> Manik Surtani
>> manik at jboss.org
>> twitter.com/maniksurtani
>>
>> Platform Architect, JBoss Data Grid
>> http://red.ht/data-grid
>>
>>
>> _______________________________________________
>> infinispan-dev mailing list
>> infinispan-dev at lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>
>
> --
> - DML
> _______________________________________________
> infinispan-dev mailing list
> infinispan-dev at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/infinispan-dev

More information about the infinispan-dev mailing list