+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(a)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(a)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(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
>
--
- DML
_______________________________________________
infinispan-dev mailing list
infinispan-dev(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/infinispan-dev
On 19 February 2013 17:19, David M. Lloyd <david.lloyd(a)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(a)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(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
>
--
- DML
_______________________________________________
infinispan-dev mailing list
infinispan-dev(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/infinispan-dev