[logback-dev] Logback 0.9.12 ?

[Joern Huxhorn]

Hi Ceki,

Unfortunately, I wasn't able to quickly create a patch because
ThrowableDataPoint is used in code that I'm not familiar with, yet, and
I don't dare to change so many files...

ThrowableDataPoint(String) is currently used at two places in
ThrowableToDataPointArray:

extract(List<ThrowableDataPoint> tdpList, Throwable
t,StackTraceElement[] parentSTE)
    new ThrowableDataPoint("\t... "+numberOfcommonFrames + " common
frames omitted"));
   
firstLineToDataPoint(Throwable t, StackTraceElement[] parentSTE)
    String prefix = "";
    if (parentSTE != null) {
      prefix = CoreConstants.CAUSED_BY;
    }

    String result = prefix + t.getClass().getName();
    if (t.getMessage() != null) {
      result += ": " + t.getMessage();
    }
    return new ThrowableDataPoint(result);

In both cases new Strings are created - with the following downsides:
    a) it's a relatively expensive operation
    b) it increases the size of the serialized event because the
formatted data is serialized instead of just the raw data.
    c) it actually contains less accessible information compared to the
raw data because the information about the Throwable class, the message,
the number of omitted frames and the Throwable cause hierarchy is
"hidden" in the String.
    d) if the "hidden" information is needed, as in my case, it needs to
be parsed from the String which is - again - a relatively expensive
operation.

Beside the use as a String container, ThrowableDataPoint simply contains
a StackTraceElementProxy.

I'd therefore suggest to get rid of ThrowableDataPoint altogether and
replace it's usage in ThrowableProxy with the following attributes:

String throwableClassName
String message
int ommittedFrames
ThrowableProxy cause

This would remove issue a)-d) and would therefore actually be faster
than before.

Beside that, the code that is currently contained in
PackagingDataCalculator will likely get less complex because - if I
understand the code correctly - findSTEStartIndex and getSTEPArray task
is, more or less, the recreation of the Throwable hierarchy or at least
the separation of the previously chained StackTraceElements of the
different Throwables. The method getSTEPArray createss another Array
which, again, is likely unnecessary heat.

I just read your email and will try to explain some of my personal
motives a little more...

Lilith currently accepts the normal Logback logging events on the usual
port. Those events are converted to Lilith logging events after
receiving them which would include the parsing mentioned on the Lilith side.

Beside that, Lilith does also accept events from my own appender
implementation - my multiplex-appenders.

Concerning logging events (in contrast to access events), there are
primarily two types of multiplex-appenders:
multiplex-classic-appender: sends Lilith events
multiplex-classic-appender-xml: sends Lilith events as XML.
(there's also a third one, a zero-terminated xml-appender, that I
implemented solely to test the receiving end of zero-terminate XML
Lilith events that will someday be sent from Flash but that is of no
concern for our discussion)

The multiplex appenders have the following additional features compared
to the original Logback SocketAppender:
- they serialize the event once and send it to a list of various servers.
- a stale server will *never* block a logging application because
there's a TimeoutOutputStream involved that will close such a stale
connection after a certain time. This can happen with the normal
SocketAppender and was freezing our webapp.
- Lilith events have an applicationIdentifier that can be set during
configuration of the appender.
- it sends a heartbeat so the server has a way to know if the connection
is still active.
- the raw serialized bytes can optionally be gzipped.

The XML version has been implemented to enable other languages beside
Java to send logging events to Lilith, e.g. C#, Flash, whatever.

It does contain, as well as the Lilith logging event Java class, the
Throwable as described above.

The rationale for "yet another Logging event" structure that ultimately
resulted in the Lilith event was:
- keep the Throwable hierarchy intact to be able to use the infos in
dedicated filters and be able to format it in a different way.
- I wanted to save some bytes because of the formattedMessage issue that
has since been changed in Logback
- I wanted to decouple Logback changes from Lilith changes in the hope
that I could eventually keep my events compatible even in case of a
change to the Logback event. I use serialized gzipped Lilith events as
the native file format of Lilith so this would have been nice.
Unfortunately, this didn't work out (yet?) :p

Oh, I just read your other mail ;)

So I guess I'll just stop writing now and send this mail. I hope all
this explains my point a bit better...

Good night, I'll get some sleep now,
Joern.


Ceki Gulcu wrote:
> I just read this in the Lilith FAQ:
>
> Why is Lilith still only supporting Logback 0.9.9?
>
> Logback 0.9.10 introduced new version information in the
> StackTraceElement string representation. This breaks my current
> implementation of parsing. Since I parse the STEs both during
> receiving of original Logback events and during creation of Lilith
> events in the multiplex appender, the parsing means a significant
> performance impact. Previously, I circumvented this by using a hack
> and accessing the STEs directly but this would noe have the downside
> that I wouldn't be able to retrieve the formerly mentioned version
> information.<br/> Because of that, I suggested a change to the Logback
> codebase that would make my life quite a bit easier while it wouldn't
> have a negative impact on the rest. It could even increase the general
> logging speed a bit. I hope that Ceki will be able to implement it in
> time for Logback 0.9.12.<br/> Feel free to take a look at <a
> href="http://jira.qos.ch/browse/LBCLASSIC-46">LBCLASSIC-46</a> if you
> like more specific informations.
>
>
>
> Ceki Gulcu wrote:
>   
>> Hi Joern,
>>
>> I am missing the bug picture here. Assuming Lilith receives serialized
>> LoggingEvents, why do you need to transform the ThrowableProxy?
>> Moreover, for exceptions, you don't need to worry about performance. By
>> definition, exceptions are comparatively much rarer than vanilla log
>> statements.
>>
>> I am guessing that you have your own implementation of ThrowableProxy
>> which is self-nested (on cause). It may be a little obtuse on my part
>> but why don't you implement your ThrowableProxy the way logback's
>> ThrowableProxy does? Is it to isolate Lilith from changes in logback?
>> I would expect logback's ThrowableProxy to be perfectly usable by a
>> GUI, and since we are talking about exceptions, performance should not
>> matter that much.
>>
>>
>> Joern Huxhorn wrote:
>>     
>>> Hi Ceki,
>>>
>>> Unfortunately, I'm very, *very* occupied during normal working hours  
>>> because we're in a hot phase of some of
>>> our projects (until february!) so we'd have to arrange a call at  
>>> around 21:00 or something like that.
>>>
>>> One very important point about LBCLASSIC-46 is that you should ignore  
>>> everything before my "29/Oct/08 10:58 AM" comment because it's  
>>> essentially outdated.
>>> I'll try to write up a understandable ;) summary of what I'm trying to  
>>> achieve with my suggestion... it's mainly about increasing performance  
>>> in both Logback and Lilith.
>>>
>>> I'll probably just implement it and attach a patch so you can just see  
>>> for yourself what I mean.
>>>
>>> Regards,
>>> Joern.
>>>
>>>       
>>     
>
>