[infinispan-dev] More verbose logging

Tue Feb 19 11:35:31 EST 2013

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}, StateChunk{segmentId=28, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=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, cacheEntries=[], 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