[infinispan-dev] More verbose logging

Tue Feb 19 12:19:17 EST 2013

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