[slf4j-user] Why is there no NDC?
Joern Huxhorn
jhuxhorn at googlemail.com
Fri Jan 23 21:04:32 CET 2009
On 23.01.2009, at 17:53, Ceki Gulcu wrote:
>
>
> Joern Huxhorn wrote:
>> Ceki Gulcu wrote:
>>> Hello Joern,
>>>
>>> Did you know that NDC can be implemented on top of MDC? I just added
>>> such an implementation into slf4j-ext. You can view it at:
>>>
>>> http://svn.slf4j.org/viewvc?view=rev&revision=1268
>>>
>> I'd implement NDC by using MDC the same way but it's obviously much
>> less
>> efficient than using a dedicated Stack (or ArrayList ) like in the
>> log4j
>> NDC.
>
> It is indeed less efficient, and increasingly so as the stack size
> grows. In the tests I have performed, for a stack size of 3, I got
> the following results:
>
> 3.9 microseconds on average for direct calls to log4j's NDC with 3
> pushes followed 3 pops
> 9.4 microseconds on average for NDC implemented via lMDC for 3
> pushes followed 3 pops
>
> For a stack size of 4,
> direct log4j NDC: 5.6 microseconds on average for 4 push followed by
> 4 pop
> indirectly via MDC: 17 microseconds on average for 4 push followed
> by 4 pops
>
> Under logback, the performance is very similar, 17 microseconds for
> 4 pushes followed by 4 pops.
>
> So, the cost is clearly higher but not appalling so.
I haven't benchmarked this myself but the relatively small difference
could be caused by the log4j implementation which isn't optimal
either. It's using a Stack as the backend which extends Vector. Both
synchronize their methods which is absolutely unnecessary in our use
case because the instance is thread-local anyway. An ArrayList would
be suited much better.
>
>
>> Moreover, it kind of "pollutes" the MDC by mixing MDC and NDC
>> together.
>
> Indeed. For example, MDC.clear() would also affect NDC.
>
>> Well, I don't use NDC but I'd really like to :)
>> It's not about which one is better but about which one is more
>> suitable
>> for a certain use case.
>
> OK.
>
>> They supplement each other. The NDC is something like a contextual
>> stack
>> trace while the MDC is a snapshot of some of the application data.
>> In our application, for example, we use the MDC to store the
>> username,
>> thee URL, the request-parameters and some other state information.
>> We write a proprietary CMS system where content can include other
>> content and each of these have certain dynamic parts which need to be
>> resolved. Therefore one use case for NDC would be to keep the
>> nesting of
>> the contents as well as informations about the various dynamic
>> resolvers
>> that could, again, load other contents..
>> An actual NDC would look something like this:
>> Loading content A
>> Loading content B
>> Resolving dynamic values for X
>> Loading content C
>> which would be of great use for us. Really. ;)
>
> Thank you for clarifying this point.
>
> Let me respond by observing that if you print the whole NDC stack on
> each log, they will take a lot of space (on each line), eventually
> causing eye sore.
I wouldn't output the NDC in the console or in log files but I would
show them in Lilith.
The table would only show the latest message while the details view
and the popup of the table cell would show the entire NDC.
>
>
> If you think of it, NDC is just a thread local stack accessible by a
> conversion pattern of the underlying logging system. In logback, it
> is quite easy to register your own conversion pattern and conversion
> words. Search for "Creating a custom conversion specifier" in http://logback.qos.ch/manual/layouts.html
>
> Given that you are using logback, you could create your own NDC
> implementation and associated conversion specifier. Once you have
> done that, you could print (log) NDC data at convenient times, for
> example every time the NDC data changes. (Your NDC code would use
> its own logger.)
>
> Come to think of it, you don't even need your own conversion
> specifier. Your NDC implementation would simply convert the NDC
> stack into a string and log that as a message at appropriate times,
> for example when NDC changes.
>
>> For example, if the loading of C failed we'd have the additional
>> information that it could be related to the resolving of X that was
>> done
>> before.
>> Using the NDC like this would also mean that we would push and pop
>> quite
>> often. Therefore the implementation of size(), which is called both
>> in
>> push and pop, would have a significant performance impact und would
>> certainly perform *much* worse than just adding/removing to/from a
>> thread-local List.
>
> Although, it is true that there is a significant impact on
> performance, depends on what you mean by *much* worse. Anyway, I
> tend to agree with you.
>
> [snip]
>> I also suggested an NDC with lazy message formatting similar to
>> logback
>> logging messages. This would make a big difference if there was a
>> place
>> to globally disable NDC evaluation altogether or if NDC wasn't
>> disabled
>> but isn't used in any appender.
>
> I think that writing your own NDC implementation would be the way to
> go in the use case you describe.
I'll probably do that because I'll implement support to keep the NDC
stack in my Lilith LoggingEvent anyway just to be able to import log4j
xml logs without loss of information.
If i do that it would mean that events logged using my multiplex-
appender would support my NDC while using the logback appender would
result in no NDC entries.
That's a bit unfortunate because the logback appender is better suited
for shortly running application like commandline tools or unit tests
while the multiplex-appender is better suited for long-running
applications like web-applications or server software. The reason for
that is that my appender is somewhat asynchronous using a buffer of n
events. This reduces blocking of the application in case of event
bursts now and then but does also mean that some events will get lost
if the application is shut down.
I'd feel much better if this could be implemented in SLF4J/Logback,
though.
Partly because I don't want to deviate too much from Logback (that was
never my intention but is already the case because I implemented http://bugzilla.slf4j.org/show_bug.cgi?id=70
and http://bugzilla.slf4j.org/show_bug.cgi?id=112 in my appender)
and partly because I think that you seriously underestimate the power
of this feature.
Beside my closure example that was only applicable (for the time
being) to people that use SLF4J in conjunction with Groovy, another
use case for the NDC would be dynamic weaving using an AOP around
advice [1].
An example would look like this:
===============================
@Aspect
public class AroundExample
{
@Around("com.xyz.myapp.SystemArchitecture.businessService()")
public Object pushOnNdc(ProceedingJoinPoint pjp) throws
Throwable
{
NDC.push("We are entering businessService!");
try
{
return pjp.proceed();
}
finally
{
NDC.pop();
}
}
}
===============================
The way described in [2] is even better but [1[ is better suited for a
simple example.
That way, the NDC use is configured at runtime. The classes that are
woven don't have to know anything about it.
You'd also have the ability to evaluate arguments given to the called
method, using them in the messagePattern in case of an implementation
like the one I suggested.
Again, like in the closure example, the cleanup would be automatic in
any case, whether an exception is thrown or not. I just point this out
- again - because it is something that is easily overlooked when
coding manually.
All in all, I think that the NDC is a feature that would be of general
use for the average developer.
Have a nice weekend,
Joern.
[1] http://static.springframework.org/spring/docs/2.0.x/reference/aop.html#aop-ataspectj-around-advice
[2] http://static.springframework.org/spring/docs/2.0.x/reference/aop.html#aop-schema-advice-around
>
>
>> Joern.
>
> --
> Ceki Gülcü
> Logback: The reliable, generic, fast and flexible logging framework
> for Java.
> http://logback.qos.ch
> _______________________________________________
> user mailing list
> user at slf4j.org
> http://www.slf4j.org/mailman/listinfo/user
More information about the slf4j-user
mailing list