2

Our Java (Web) Application runs in JBoss 6x. When slowness was reported:

  1. Thread Stack Dump was taken(Details below)
  2. Memory was examined - Memory usage was found to be very high, almost touching Max Allowed Heap Size, but no Out of Memory.

The Thread Stack Dump shows most threads blocked on Logging with these kind of errors:

waiting for monitor entry [0x000000004b6be000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:59)
    - waiting to lock <0x00002aaac9a2de68> (a java.lang.Object)
    at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:64)

And like this:

   java.lang.Thread.State: BLOCKED (on object monitor)
    at java.io.PrintStream.println(PrintStream.java:756)
- waiting to lock <0x00002aaac9817a08> (a com.whatever.SomeClass)
at com.something.ThatClass.thatMethod(ThatClass.java:169)

The com.whatever.SomeClass uses org.apache.log4j.Logger
We use Log4j for logging.

It appears the threads are all blocked on some logging operation. This problem has occurred in the past too, and appears to be random, and it slows down/halts the application.

Any ideas?

Jasper
  • 8,440
  • 31
  • 92
  • 133
  • possible that any file operations on .log file are happening in parallel – TheWhiteRabbit Feb 07 '13 at 08:40
  • Also note that recently for RollingFileAppender in log4j.xml, MaxBackupIndex size has been set to 1000 (MaxFileSize is 5MB). Could such a high value for MaxBackupIndex be a cause of this concern/problem? – – Jasper Feb 07 '13 at 10:39

1 Answers1

3

Jasper, all logging frameworks have a synchronized block where they write the data to disk. This is to prevent garbling the log when more than 1 thread is writing to the log (you posted an example of this - the BLOCKED thread on java.io.PrintStream.println).

But there's a solution, which is to use an asynchronous appender. At work we have some high throughput / low latency applications, and we had to configure this to prevent thread contention.

One thing you need to take into account when you're using the async appender, is that if your app crashes or is terminated forcefully, you won't see the last logging statements in the logs, as they probably weren't written to disk.

Augusto
  • 28,839
  • 5
  • 58
  • 88
  • 1
    See http://stackoverflow.com/a/13144054/603516 on AsyncAppender issues and tip for further reducing contention. – Vadzim Feb 07 '13 at 08:51
  • Most logging frameworks have sychronized block where the log entry is queued to a log write thread. Locking over complete disk write operations would be very poor. – Martin James Feb 07 '13 at 09:53
  • Martin, that's only true if you use an Async appender. If you use a normal File or Console appender, then the logging framework will block synchronously any other logging operation. This is why there's an async appender, which in turn wraps around another appender. – Augusto Feb 07 '13 at 10:05