Log4J time order problem [RePost]

[oops <oo...@telcoware.com>]

Hello.
 
I also have the below problem.
I don't use ASYNC file appender
I just use DailyRollingFIleAppender.
My log4j.properties is below..
 
======================================================================
log4j.appender.R=org.apache.log4j.DailyRollingFileAppender
log4j.appender.R.File=/home1/useraccount/log/TMCSWEB/tmcsweb.log
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%d{HH:mm:ss} [%5p] (%F:%L) [%M] -
%m%n ======================================================================
 
When I test the application , everything is ok.
but when somebody do the performance test
I had the same problem
 
this is web application.
 
When multiful threads access the same function, 
the timestamp is not ordered by time.
( one thread write the log as time sequence. but I has plenty many threads.
and the timestamp is not ordered )
 
my sample log is like this
=========================================================================
15:13:57 [DEBUG] (RecruitBasicAction.java:123) [formToEntiry] - 
15:13:57 [DEBUG] (RecruitBasicAction.java:144) [formToEntiry] - 
15:13:57 [DEBUG] (RecruitBasicDAO.java:52) [update] - 
15:13:58 [DEBUG] (RecruitBasicAction.java:144) [formToEntiry] -
=> this line is not ordered by time.
15:13:57 [DEBUG] (RecruitBasicDAO.java:52) [update] - 
15:13:57 [DEBUG] (RecruitBasicDAO.java:52) [update] - 
=======================================================================

Can I have the log ordered by time ?
 

-----Original Message-----
From: Ceki G?c [mailto:ceki@qos.ch] 
Sent: Wednesday, January 12, 2005 12:09 AM
To: Log4J Users List
Subject: Re: Log4J date/time output problem
 
 
 
Yoval,
 
One possible explanation is the order in which AsyncAppender wakes up one of
threads waiting to push events on AsyncAppender's buffer, when this buffer
is full.
 
 <http://java.sun.com/j2se/1.3/docs/api/java/lang/Object.html#notify>
http://java.sun.com/j2se/1.3/docs/api/java/lang/Object.html#notify()
 
public final void notify()
 
   Wakes up a single thread that is waiting on this object's monitor. If
   any threads are waiting on this object, one of them is chosen to be
   awakened. The choice is ARBITRARY and occurs at the discretion of the
   implementation. A thread waits on an object's monitor by calling one
   of the wait methods.
 
Assuming logs are generated at a fast face, the AsyncAppender's buffer will
become full fairly quickly and frequently.
 
If you would like me to investigate this further, then could you please
provide a sample of the logs? I am only interested in the timestamps, the
logger names and the thread names. A few dozen logs surrounding the
unorderly behavior should suffice.
 
At 03:32 PM 1/11/2005, you wrote:
>Hello,
>I'm using Log4J 1.2.6 with the following
>configuration:
>AsyncAppender writing to
>RollingFileAppender which is using PatternLayout with conversion
>pattern "%p | %d{ISO8601} | %t | %x | %c | %m%n".
>My platform is JDK 1.4.2 on Linux redhat 9.0 .
>
>Lately, when I loaded my system to check performence,
>I noticed that some lines in the log file have
>incosistent time values:
>Sometimes, one line had a timestamp smaller then the
>line before it.
>I also noticed that the Thread source name for these
>lines is always different (so, in the context of one
>thread, there is no problem).
>
>What can be the source of this behavior?
>
>Thanks,
>Yuval
 
-- 
Ceki Gülcü
 
   The complete log4j manual:  <http://www.qos.ch/log4j/>
http://www.qos.ch/log4j/
 

Re: Log4J time order problem [RePost]

[Curt Arnold <ca...@apache.org>]

On Sep 2, 2005, at 2:13 AM, oops wrote:

>
> Hello.
>
> I also have the below problem.
> I don't use ASYNC file appender
> I just use DailyRollingFIleAppender.


The issue affects almost all appenders, it is just more easily  
observed with AsyncAppenders when the buffer gets filled.  If there  
is any lock acquisition after the LoggingEvent is constructed (and  
the timestamp is acquired), there is a chance that multiple threads  
will block and the order that the threads will restart is  
indeterminate resulting in LoggingEvents processed in a different  
sequence.

There is not any reliable means of correcting the sequence once  
multiple threads block.  It would require something like holding all  
events till application shutdown and then sorting on timestamp and  
that would require large amounts of memory and be susceptible to  
application crashes.

If this is a concern to you, the best approach is to avoid situations  
that cause thread blocking.  During the time period around the out-of- 
sequence timestamps, it is likely multiple threads are awaiting for  
an IO action to complete.  With a RFA, this would be most pronounced  
during a rollover, though that does not appear to be the case here.

Using an AsyncAppender can be beneficial as long as the bufferSize is  
set sufficiently large to avoid having the buffer filled.  As long as  
the buffer is not filled, the AsyncAppender will have a much shorter  
lock than the underlying IO bound appender and the chance of multiple  
threads blocking is greatly reduced. 
  

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org