Re: [infinispan-dev] More verbose logging

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(a)redhat.com&gt; 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!

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!

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(a)jboss.org > twitter.com/maniksurtani > > Platform Architect, JBoss Data Grid > http://red.ht/data-grid > -- Manik Surtani manik(a)jboss.org twitter.com/maniksurtani Platform Architect, JBoss Data Grid http://red.ht/data-grid _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev