MDC performance concerns
Hello, I am interested in converting my application to logback, but I have some performance concerns about its MDC implementation. My application uses MDC extensively for async IO, so it may call MDC.put and MDC.remove extremely frequently, because each thread may be handling 1000s of interleaved connections using state machines. I see in the source for LogbackMDCAdapter that for every call to MDC.put and MDC.remove, the HashMap is cloned. Could this clone potentially be handled during the creation of LoggingEvents instead of the call to MDC? The creation of logging events is expected to entail memory allocation, so it seems that it would be a better fit there, even if some applications might have a very low number of calls to MDC versus logging calls. It seems that the same energy expended in minimizing log statement impact when logging is turned off should also apply to MDC calls. Thanks Matt
Hello Matthew, Yikes! The MDC implementation in logback is not intended to be called in hot spots. You call it when a request arrives. If requests arrive hundreds of times each milisecond, then there might be a performance concerns as you point out. The cloning is done for sake of serialization. I think cloning is necessary for correct serialization of MDC values. As you point out, cloning could be done within LoggingEvent. If you deem that logback's implementation of MDC is too slow for your purposes (I'd check if that is really true), you could write your own implementation of MDC and have it interpreted by your own MDCConverter. In logback, it is rather easy to register your own pattern converters. Holler if you decide to go down this road and you need help. If the above does not work for you, then please kindly enter a bug report. There is a reasonably good chance that your proposal will be implemented. Matthew Finn wrote:
Hello,
I am interested in converting my application to logback, but I have some performance concerns about its MDC implementation.
My application uses MDC extensively for async IO, so it may call MDC.put and MDC.remove extremely frequently, because each thread may be handling 1000s of interleaved connections using state machines.
I see in the source for LogbackMDCAdapter that for every call to MDC.put and MDC.remove, the HashMap is cloned. Could this clone potentially be handled during the creation of LoggingEvents instead of the call to MDC? The creation of logging events is expected to entail memory allocation, so it seems that it would be a better fit there, even if some applications might have a very low number of calls to MDC versus logging calls. It seems that the same energy expended in minimizing log statement impact when logging is turned off should also apply to MDC calls.
Thanks
Matt
-- Ceki Gülcü QOS.ch is looking to hire talented developers in Switzerland. If interested, please contact c e k i AT q o s . c h
Ceki, MDC can't be called per request in my app because each individual packet during a connection could potentially be handled by a different thread in a thread pool. This type of scenario is common with any type of asynchronous network library, where the general goal is to decouple connections from threads. Any of the libraries out there based on java.nio would be affected in the same way: Apache MINA: http://mina.apache.org/ Coconut AIO: http://coconut.codehaus.org/ IBM AIO: http://www.alphaworks.ibm.com/tech/aio4j I suppose I can go the route of creating my own MDC implementation, but I do think that the way MDC was handled in log4j originally (which appears to have been authored by you :) is more correct, cloning the HashMap in LoggingEvent and InheritableThreadLocal.childValue. I have posted bug #150 with a patch :) http://bugzilla.qos.ch/show_bug.cgi?id=150 Thanks Matt On Apr 25, 2008, at 4:20 PM, Ceki Gulcu wrote:
Hello Matthew,
Yikes! The MDC implementation in logback is not intended to be called in hot spots. You call it when a request arrives. If requests arrive hundreds of times each milisecond, then there might be a performance concerns as you point out.
The cloning is done for sake of serialization. I think cloning is necessary for correct serialization of MDC values. As you point out, cloning could be done within LoggingEvent.
If you deem that logback's implementation of MDC is too slow for your purposes (I'd check if that is really true), you could write your own implementation of MDC and have it interpreted by your own MDCConverter. In logback, it is rather easy to register your own pattern converters. Holler if you decide to go down this road and you need help.
If the above does not work for you, then please kindly enter a bug report. There is a reasonably good chance that your proposal will be implemented.
Matthew Finn wrote:
Hello, I am interested in converting my application to logback, but I have some performance concerns about its MDC implementation. My application uses MDC extensively for async IO, so it may call MDC.put and MDC.remove extremely frequently, because each thread may be handling 1000s of interleaved connections using state machines. I see in the source for LogbackMDCAdapter that for every call to MDC.put and MDC.remove, the HashMap is cloned. Could this clone potentially be handled during the creation of LoggingEvents instead of the call to MDC? The creation of logging events is expected to entail memory allocation, so it seems that it would be a better fit there, even if some applications might have a very low number of calls to MDC versus logging calls. It seems that the same energy expended in minimizing log statement impact when logging is turned off should also apply to MDC calls. Thanks Matt
-- Ceki Gülcü QOS.ch is looking to hire talented developers in Switzerland. If interested, please contact c e k i AT q o s . c h
_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user
participants (2)
-
Ceki Gulcu -
Matthew Finn