On Apr 14, 2005, at 10:30 PM, Rohit Sonalkar wrote:
Hi,
Is it possible in a multi-threaded application that log statements
appear in the output log file out of sequence w.r.t. the timestamps of
the logging events? If the timestamp is generated at the time the
logging method is invoked, then under what conditions would this happen?
Would it happen if a logger generated a logging event, but by the time
it found its way to its parent categories' appender through additivity,
the logger directly attached to that appender gets in a logging event?
Yes. The time stamp is generated at the construction of the LoggingEvent which occurs during the call to Logger.log after checking the thresholds but before dispatching the LoggingEvent to the appropriate appenders. The appenders have synchronization blocks and if multiple threads are waiting for a lock, the Java VM makes no promises on the order that the waiting threads will get the lock.
If while event 1 is being processed by appender 1 on thread 1, threads 2 and 3 make log requests and block due to appender 1 when event 1 is finished processing, either event 2 or 3 may be next. The effect is most noticeable with AsyncAppenders which will block when their buffer is filled.
These scenarios have been discussed in depth on the log4j-dev list (search for sequenceNumber and be ready to read 30 messages to follow the ious positions). There does not appear to be any simple solution other than making your AsyncAppender big enough that you don't block and accept that if you are multi-threaded that timestamps may still appear out of sequence. Changing the timestamps so that they reflect the time of appending instead of the time of request would remove the cosmetic issues, however it would disguise the true sequence of the requests.
--------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
