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@slf4j.org
http://www.slf4j.org/mailman/listinfo/user
_______________________________________________
user mailing list
user@slf4j.org
http://www.slf4j.org/mailman/listinfo/user
