users@glassfish.java.net

poor throughput while using org.apache.log4j.Logger on Glassfish.

From: Russ Petruzzelli <Russ.Petruzzelli_at_Sun.COM>
Date: Sat, 20 Sep 2008 22:04:07 -0700

My team is developing a web product that uses org.apache.log4j.Logger.

While conducting performance tests we found that the webapp throughput
varies by a factor of ** 15 ** from having logging OFF to level INFO.

(Sun Appserver 9.1 u1 aka Glassfish v2 u2)

Disk IO did not appear to be a factor in the tests. CPU -- at the
highest logging level (INFO) -- stops at around 38%. If logging is set
to OFF, the system can be driven to 100% CPU. This last fact seems to
indicate to me a threading issue (race/syncronization). VisualVM
reported no deadlocks but did find all my worker threads blocked by
org.apache.log4j.Logger.

An httpSSLWorkerThread == An appserver request-processing thread. In my
case set to max of 32. All 32 were blocked at higher loads:


    "httpSSLWorkerThread-8080-0" nid=71 state=BLOCKED
        - waiting on <0x7efd57e2> (a org.apache.log4j.Logger)
        - locked <0x7efd57e2> (a org.apache.log4j.Logger)

With logging OFF, at 100% CPU, only 4 request-processing threads were
even created. None blocked.

Possible bug? Any other ideas about this?

(I also sent this email to log4j-dev_at_logging.apache.org, but so far have
received no response.)

Thanks,
Russ