ansaurus

Question

Why are my Log4j log file timestamps out of order, and how do I fix it?

Answer 1

+1 A:

Are the two log statements occurring on different threads.

(Thread 1) 2009-02-19 14:54:27,429 INFO [com.catalystwms.tms.services.background.purge.PurgeManager]
(Thread 2) 2009-02-19 14:47:01,288 DEBUG [com.catalystwms.core.services.ServiceLocator

I believe the log statements time accurrately gives the time when the event occurred but are just written out of order because thread 2 is waiting to get the lock. I believe wrapping your appender in a org.apache.log4j.AsyncAppender should fix the issue.

richs 2009-02-25 17:11:55

Yes.multiple threads are running.Do I need to use AsyncAppender instaed of RollingFileAppender?

2009-02-25 17:51:42

You can keep the RollingFileAppender just wrap a AsyncAppender around it. i don't know how to do it in the config but in code AsyncAppender has a method:public void addAppender(org.apache.log4j.Appender newAppender)

richs 2009-02-25 18:38:38

Answer 2

A:

The date format is designed to allow the a simple character based sort to order it correctly.

sort server.log | more

EDIT: This is useful for use on existing log files (not for configuring log4j).

Chris Nava 2009-02-25 17:49:28

How can I use that in log4j.xml?please clarify

2009-02-25 17:59:35

You don't use it in log4j, You use it on the log afterwards (when you are reading it, perhaps).

Bill K 2009-02-25 18:20:03

I have n't idea where that entry should go?My log is dynamically constructed.

2009-02-25 18:41:01

It isn't an entry, it's a shell command. Basically he's just saying to sort the lines later, when you look at the log.

Adam Jaskiewicz 2009-02-25 19:04:03

Thanks.I can't sort like that. 'rm.log' is a text file having all logs and some of the log timestamps are out of order. if some exceptions occur the loga are logging into rm.log file.

2009-02-25 19:14:07

Answer 3

A:

You probably won't be able to fix it before the log is written. You could try modifying log4J to call .flush() after every write, but that will make your code a good deal slower and @Chris Nava's solution is more appropriate.

Bill K 2009-02-25 18:22:27

Answer 4

+1 A:

You have two different processes logging to the same log file with a rolling appender. Log4j does not allow this. In the past, I've resolved this in a clustered web app by adding a server name to the log file: appname-server1.log and appname-server2.log with each server configured to write to their own log.

This can also be useful to track down bugs that are specific to one machine's configuration vs. another.

All of the above also works if you have two different applications writing to the same log file by naming the files based on the application being executed.

Alex B 2009-02-25 18:45:45

Answer 5

A:

In response to @andy:
(Thread 1) 2009-02-19 14:54:27,429 INFO [com.catalystwms.tms.services.background.purge.PurgeManager]
(Thread 2) 2009-02-19 14:47:01,288 DEBUG [com.catalystwms.core.services.ServiceLocator

what i believe may be happening is thread 2 creates a logRecord at 14:47:01,288 when it attempts to write, it needs to get a lock for the Logger's list of appenders, but another thread has the lock and is busy doing IO so thread 2 waits. thread 1 creates logRecord at 14:54:27,429 it attempts to get the same lock and also waits. When the lock is freed the OS gives it to thread 1 and it prints.

If this is true the other big issue is one of performance. Code paths could block on logging IO.

richs 2009-02-25 19:05:25

Answer 6

A:

Is there simple solution? What I have to do finally?

2009-02-25 21:14:59

ansaurus

tags:

views:

answers:

Why are my Log4j log file timestamps out of order, and how do I fix it?

related questions