On May 23, 2010, at 2:27 AM, Ralph Goers wrote:
>
> On May 22, 2010, at 8:13 PM, Curt Arnold wrote:
>
>>
>> On May 22, 2010, at 10:50 AM, Ralph Goers wrote:
>>>
>>>>
>>>> Also, I have had an issue where the I wanted the toString() method on the
>>>> object to be logged to be delayed as much as possible (somewhat helped
>>>> with the {}-construct in slf4j). This might be doable with a specific log
>>>> interface.
>>>
>>> That is exactly what Message does.
>>>
>>
>>
>> My thoughts, but not sure how much of this got into my earlier code, was to
>> have a distinct extraction phase that occur synchronously with the logging
>> call that would extract all info needed for a completion phase that could
>> occur either immediately or be deferred. The extraction phase would need to
>> extract any info from the call into immutable objects so state change, for
>> example mutable message parameters, before the completion stage would not
>> change the resulting log.
>
> There is no point in doing this in simple use cases such as using the
> FileAppender to write to a log file.
Usually not the simple cases that dictate the design.
>
>>
>> A example where this would be useful is logging floating point numbers. It
>> can be surprisingly expensive to format floating point numbers, so it is
>> highly beneficial to extract all the pieces needed for the formatting into
>> an immutable package during the synchronous extraction phase and then do the
>> formatting in the asynchronous completion phase.
>
> This assumes there is an asynchronous phase. In my audit logging use cases I
> do not want asynchronous logging because I want any exceptions that occur to
> be thrown back to the caller. An awful lot of logs just write Strings and
> simple values. While we should support use cases like what you are suggesting
> I think it would be unwise to optimize for them at the expense of typical
> usage.
If the framework allows for clear separation between required to be synchronous
and allowed to be asynchronous, then doing everything synchronous is easy as
immediately invoking run() on the returned Runnable. Might come with a
performance cost when running purely synchronous, but without some
experimentation can't quantity if it is significant.
>
>>
>> The AsynchronousAppender in log4j requires trying to freeze LoggingEvent
>> which is still subject to message objects changing underneath it. Also it
>> generally perform unnecessary actions in freezing everything in the
>> LoggingEvent even though much of it will not be used.
>>
>> The framework should be designed to separate the parts required to be
>> synchronous (that is anything dealing with external objects) from the parts
>> that can be deferred.
>
> I don't think I really agree with this, at least the way you are expressing
> it. Typically, the "parts required to be synchronous" are also the ones that
> are expensive to resolve. What you are suggesting is that somehow it is
> easier to deal with a LogEvent that has a reference to another object that
> contains the references to the "synchronous objects" than to just copy the
> whole LogEvent. But copying simple object references like Strings doesn't
> cost all that much and may not even be worth doing if the appender needs some
> sort of serialized version of the LogEvent instead (SyslogAppender using
> either the serialized logging event or the IETFSyslogLayout that I haven't
> added yet).
The summary in the second sentence feels the antithesis of what I'm suggesting.
Copying the "whole log event" so that the copy is not affected by any potential
changes is complicated, expensive and error-prone as seen in log4j's
AsyncAppender. The message parameter or any value in the MDC or NDC in the
log4j API can be any arbitrary object. If it is immutable, then you are fine.
If not and the object is serializable or clonable, you could clonable.
Otherwise, you are subject to changes that could occur after the logging call.
Restricting message, MDC and NDC parameters to strings is not desirable. log4j
allows it and there are reasonable and worthwhile reasons to use them.
AsyncAppender does a not totally satisfactory clone of a LoggingEvent and then
runs the nested appender later on that clone, none of the nested appenders code
runs during the synchronous phase. The alternative I'm suggesting is to allow
appenders to see the LoggingEvent in the extraction phase, get all the
information that it needs (or possibly do the whole action) and then leave a
Runnable to complete the action. If fully synchronous, the runnable would be
immediately executed, if not, then sent to a queue for later execution.
>
> In looking at Log4jLogEvent really the only fields that deal with external
> objects are the Message and the Throwable. I suppose a Throwable could be a
> problem if the caller has created their own exception type and added odd
> stuff to it (complex object references), although I can't say I've ever run
> across an Exception that does that. The Message can be solved by a) doing
> new SimpleMessage(message.getFormattedMessage()), b) serializing the message
> and deserializing it, or c) adding another method to the Message interface
> like "prepareForAsynch".
"prepareForAsynch" has the same problem as serializing the logging event.
There is no bulletproof way to make an invariant copy of every arbitrary
objects and some may be extraordinary expensive. It seems to me to be much
clearer to have a phase where you have access to the LoggingEvent interface in
the scope of the logging call, but anything deferred must act on what was
extracted from that call. At the simplest, it could be to run the layout in
the extraction phase and hold the string for the completion phase.
If I have an "itch" for log4j 2.0, this is it. I'm not sure where the path
would lead, but it is the path that I want to explore.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
