[jsword-devel] Loggers

[DM Smith]

My answers were a bit short. Here's a bit of history. (As best I can remember ;)

When creating an application from scratch, it is wise to start with some frameworks: logging, internationalization, memory management, ...

When I started w/ JSword 8.5 years ago, these already in place. (Thanks Joe!)

At that time we were using Java 1.3.

Loggers at that time were being strongly debated as who's was the best, and log4j was used for JSword. Java did not have a logger. But wrapped by our logger class.

IIRC: At that time there was no support in any logging package for stack tracing, which is critical for debugging. 

One of the problems with generating a stack trace is that we want it to show where the problem occurred (class, method and line where the logger was called), not one starting inside of the logger in some distant package. So, we put a static logger object in each class that did logging. The logger was then part of that class and would properly show that class as the originator for the log message. To get the method and the line number of where the logger was called required a stack trace to dig through.

We then figured out how to get the calling class by digging into the call stack. (See CallContext).

Then we changed from log4j to Java logging. The names we had for our logger needed to map to the logging levels in Java. We kept our old names and documented the mapping.

Regarding Java Logging, I don't know the full capabilities. Here is what we need for good logging:
1) Class where the logging took place. Always.
2) Method and line of where the event took place. The place where the logger is called might be the closest place that we can get. This is needed for debugging errors. It is probably not needed for fine levels of detail.
3) Stack trace. Needed for understanding errors. It is not sufficient to know the class, method and line, but need the context of the event.

So we probably have baggage from the past and Java Logging probably has caught up. So, if there are better ways to get method and line, that'd be great. It might make sense to use the provided throwable (when not null).

Enough for now.

In Him,
	DM

On Feb 6, 2013, at 6:39 AM, Chris Burrell <chris at burrell.me.uk> wrote:

> And on the above, is it not just a matter of configuring the Java Logger to output the stack trace? when logging? (forgive my ignore on the java loggers)
> 
> 
> On 6 February 2013 11:24, Chris Burrell <chris at burrell.me.uk> wrote:
> I guess my more general question is why "We want that when we are handling errors. Maybe we don't want to do it for all levels of logging. I.e. configure it."
> 
> Doesn't the Java Logger do that? Given we're wrapping around java.util.loggin.Logger anyway, why not just use those directly. The only reason I can find is that someone preferred the log4j api to the java.util.logging api. With Slf4j a developer of a third-party application can change the way these logs are output anyway, so I can configure a java.util.logging.Logger via a "log4j.properties" file using the bindings provided by slf4j.
> 
> When I've tried configuring the Loggers occasionally for JSword I have to say I've found it pretty difficult to work out, for 2 main reasons. Everything looks like it's using log4j, but the .properties file uses the java.util.logging.Logger style. My problem was then two-fold: i haven't used that much, and without digging into the implementation, it's difficult to know how the log levels match up to the log4j log levels.
> 
> Anyhow, just a thought. 
> 
> Chris
> 
> 
> 
> On 6 February 2013 09:37, Chris Burrell <chris at burrell.me.uk> wrote:
> Yeah, i think that will help. I can do the first one. I'm not promising I go through the whole code base to do the others.
> 
> Chris
> 
> 
> 
> On 5 February 2013 23:38, DM Smith <dmsmith at crosswire.org> wrote:
> Logger.doLogging needs to change to test the level against set level and bail if it is not going to be recorded.
> 
> There will still be some building of messages outside. We can add a boolean shouldLog(logLevel) to help one determine on whether to construct a log message.
> 
> Will that help?
> 
> -- DM
> 
> On Feb 5, 2013, at 6:22 PM, Chris Burrell <chris at burrell.me.uk> wrote:
> 
>> The 10% logging was debug logging, perhaps that was exacerbated during profiling, but i'd expect it to be exacerbated uniformly-sh.
>> 
>> The JSword logger doesn't define a isDebugEnabled as far as I can see. Also, showLocation is true by default, so lots of work happens every time. The logger implementation seems to rely on the underlying functionality as to whether it is logged out to a screen/stream/file/etc. but by then all the work has been done.
>> 
>> Due to the missing isDebugEnable type functions, JSword methods across the board presumably do quite a lot of concatenation before even calling the logger, i.e. passing a concatenation of parameters. (not sure whether the profiler would wrap that into the log call, or the caller method, probably the caller)
>> 
>> Unfortunately, the third party is not in charge of showLocation. And can't change it as the moment except on a per logger basis. Perhaps it was the particular operation. It's partly because of String concatenations.
>> 
>> Cheers
>> Chris
>> 
>> 
>> 
>> On 5 February 2013 23:04, DM Smith <dmsmith at crosswire.org> wrote:
>> 
>> On Feb 5, 2013, at 3:37 PM, Chris Burrell <chris at burrell.me.uk> wrote:
>> 
>> > Hi
>> >
>> > I was doing a bit of performance tuning for STEP earlier, to see how I could speed up some of the searches. I found that possibly up to 10% of the time could be spent logging.
>> 
>> Seem strange that 10 percent of the time is managing errors. (You need to look into configuring the logger to only log errors, if you aren't already). Then the calls to logger are lightweight. Pretty much a no-op.
>> 
>> There's a bug in changing the LogLevel and in specifying the logger config. But I don't remember.
>> 
>> >
>> > I'm guessing that's because of the bit that tries to throw an Exception to capture the stack trace.
>> 
>> We want that when we are handling errors. Maybe we don't want to do it for all levels of logging. I.e. configure it.
>> 
>> See the "showLocation" part of the getLogger() call.
>> 
>> >
>> > Is there any reason why we're not using the java loggers directly?
>> 
>> We are using the java loggers. We don't use it directly since we were using a different logger before the java loggers.
>> 
>> > Or why we're not using log4j (i see there's a not about keeping it small)
>> 
>> That's what we were using.
>> 
>> The philosophy of JSword architecture is to:
>> define an abstract interface
>> create a basic implementation of the abstraction
>> use a plugin to define which implementation is being used. (Not used wrt logging)
>> 
>> By hiding behind the concrete abstraction, we were able to swap out implementations.
>> 
>> Hope this helps,
>>         DM
>> 
>> 
>> 
> 
> 
> 
> 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.crosswire.org/pipermail/jsword-devel/attachments/20130206/59bdf170/attachment.html>