Details
-
Type:
Bug
-
Status:
Resolved
-
Priority:
Critical
-
Resolution: Fixed
-
Affects Version/s: 0.9.9
-
Fix Version/s: 0.9.11
-
Component/s: None
-
Labels:None
-
Environment:Hide
JVM: Sun 1.5.0_16-b02
Architecture: i386
OS: Ubuntu 8.10
Classpath: /home/rwinch/workspaces/perf4j/bug-example/target/classes:/home/rwinch/.m2/repository/log4j/log4j/1.2.14/log4j-1.2.14.jar:/home/rwinch/.m2/repository/org/perf4j/perf4j/0.9.9/perf4j-0.9.9.jarShowJVM: Sun 1.5.0_16-b02 Architecture: i386 OS: Ubuntu 8.10 Classpath: /home/rwinch/workspaces/perf4j/bug-example/target/classes:/home/rwinch/.m2/repository/log4j/log4j/1.2.14/log4j-1.2.14.jar:/home/rwinch/.m2/repository/org/perf4j/perf4j/0.9.9/perf4j-0.9.9.jar
-
Number of attachments :
Description
I haven't really had any time to look at this issue myself, but it does not appear that the last time slice is getting logged. The easiest way to reproduce this is to use the attached configuration and example that was modified from one of the development guide "Using the log4j Appenders to Generate Real-Time Performance Information" examples.
When I run this I get a file named perfStats.log as expected. However, the contents of the file are missing all (i.e. the file is empty) or some events. The smaller the time slice the more likely it is for it to log the events.
I finally took some time and found out a few things:
A) If the JVM terminates, the last timeslice is not visible
1) If AsyncCoalescingStatisticsAppender.stopDrainingThread is called before the JVM terminates it logs out all the events.
2) It does not appear that AsyncCoalescingStatisticsAppender.close is being called. I looked to see if log4j had some sort of Runtime shut down hook for Log4j, but did not find anything (perhaps someone knows something I don't).
3) If log4j does have a shutdown hook, calling LogManager.shutdown() seems to cause problems because the downstream appender(s) that AsynchCoalescingStatisticsAppender delegates to may shutdown before it gets a chance to flush out the remaining statistics. This gives the following error: "log4j:ERROR Attempted to append to closed appender named [appenderName]."
4) I'm not sure what if anything should be done about this issue. A shutdown hook, a Servelt or Listener for J2EE environments. Thoughts?
B) StopWatch outside of timeslice only thing to cause old timeslice to be sent to downstream appenders.
1) While the appender is not closed, the only thing that triggers events to be pushed to downstream appenders is a logging event outside of the timeslice. This would mean that in a non active JVM you may never see the latest statistics. You would essentially need to trigger logs to flush them out. This can be difficult if using a clustered machine in a J2EE environment.
The reason this happens is all the events get into the statsIterator [1]. However, the time slice will not be flushed out to the downstream appenders until the next timer is added to the queue. This is because a take() is performed on the loggedMessages which does not stop blocking until a new message appears in it [2].
2) I have submitted a patch for this based upon the 0.9.9 tag. The patch contains a test and modified code to correct the issue. My goal in this patch was to fix the issue while remaining as passive as possible.
Regards,
Rob
[1] http://perf4j.codehaus.org/xref/org/perf4j/log4j/AsyncCoalescingStatisticsAppender.html#319
[2] http://perf4j.codehaus.org/xref/org/perf4j/log4j/AsyncCoalescingStatisticsAppender.html#404