It seems to be a performance problem in the java.util.loggingLogRecord class
which impacts Google servers. This needs to be fixed in update releases as well.
There is still a question about exact update releases which should be fixed.
Please, see a email from Josh below.

----------------------------------------------------------------
Serguei,

On 1/5/07, Serguei Spitsyn <###@###.###> wrote:

    Hi Josh,

    Joshua Bloch wrote:
    > Serguei,
    >
    > Hi. Martin Buchholz tells me that you're currently in charge of the
    > java.util.logging. We were profiling one of our servers, and were
    > surprised to find that it was spending ten percent of its time in
    > java.lang.Throwable.getStackTraceElement . On further analysis, this
    > call is coming from a temporary Throwable created in the LogRecord
    > class, solely for the purpose of finding the class and method name of
    > the class doing the logging.  I suspect that the performance could be
    > greatly improved with a small change to
    > java.util.logging.LogRecord.inferCaller .  Here is how the method
    > currently looks:
    >
    >     // Private method to infer the caller's class and method names
    >     private void inferCaller() {
    >         needToInferCaller = false;
    >         // Get the stack trace.
    >         StackTraceElement stack[] = (new Throwable()).getStackTrace();
    >         // First, search back to a method in the Logger class.
    >         int ix = 0;
    >         while (ix < stack.length) {
    >             StackTraceElement frame = stack[ix];
    >             String cname = frame.getClassName();
    >             if (cname.equals("java.util.logging.Logger ")) {
    >                 break;
    >             }
    >             ix++;
    >         }
    >         // Now search for the first frame before the "Logger" class.
    >         while (ix < stack.length) {
    >             StackTraceElement frame = stack[ix];
    >             String cname = frame.getClassName();
    >             if (!cname.equals("java.util.logging.Logger")) {
    >                 // We've found the relevant frame.
    >                 setSourceClassName(cname);
    >                 setSourceMethodName(frame.getMethodName());
    >                 return;
    >             }
    >             ix++;
    >         }
    >         // We haven't found a suitable frame, so just punt.  This is
    >         // OK as we are only committed to making a "best effort" here.
    >     }
    >
    > The idea is to remove the call to (new Throwable()).getStackTrace(), and
    > instead call the underlying native methods directly.  Before the loop
    > call java.lang.Throwable.getStackTraceDepth.  In each iteration of the
    > loop, call java.lang.Throwable.getStackTraceElement, and stop when you get
    > the name you're looking for.

    You said that it was spending ten percent of its time in the native method
    java.lang.Throwable.getStackTraceElement.
    If so, then I'm afraid that direct call to the getStackTraceElement
    is going to spend the same ten percent.


Nope.  The idea is that calling (new Throwable()).getStackTrace(); calls the native method for each frame in the *entire* stack.  By calling it directly in the loop, you only call it for as much of the stack as necessary.

    But most likely, I've missed your point here.
    Is your idea to have less calls to getStackTraceElement? 

Yes, exactly.  I suspect that this will make a big difference!

    > This still strikes me as a bit of a band-aid: it shouldn't really be
    > necessary to paw through the stack trace to find the method name.

    Right.
    I need some time to check why it was implemented this way.
    It looks strange a little bit.
    Especially, because method getStackTraceElement calls to
    JVM_GetStackTraceElement which may trigger a safepoint.
    At least, there is a comment in the JVM_GetStackTraceElement saying about it. 


Yeah, and also it's not guaranteed ot work, as  there is only a best-effort guarantee on the accuracy of the stack track trace. As I said, I think the reason they did it that way is that there is no clear alternative that doesn't involve changing the language:(  It's frustrating, because the compiler (javac) knows the the class at the logging site, but has no way to pass it in.  This is the sort of problem that is solved with macros containing __FILE__ and __LINE__ in C.

    > But I'm afraid that a better solution would take a lot more work, and I
    > suspect that this will do a lot to ease the problem.  One minor piece of
    > "fine print": The native methods (getStackTraceDepth and
    > getStackTraceElement) are in the wrong package (java.lang instead of
    > java.util.logging).  As a consequence, you'll need to do some minor
    > trickery to call them efficiently without exposing them.  If you don't
    > know the trick ask Ken Russell, who showed it to me when I implemented
    > the library support for annotations.

    I'm not a fun of tricks. :)

Me neither, but this trick needs to be done once per package, and I suspect that it's already been done for java.lang , so all you have to do is add another method to an existing interface.

    It would be nice to find a better solution.
    Would you like me to file a bug or you prefer do it yourself?

Well, since I don't work for Sun any more, I can't file it myself.

    It would be nice if you have any test demonstraiting this problem.

OK, I'll bash something out and send it to you.

    What priority this bug should be?

Well, I guess someone at Sun should decide.  My suspicion is P3, but I'd really like to see a fix in a maintenance release.  I don't know what the process is like these days.  Do P3's get fixed in maintenance releases?

Thank you, and happy new year to you as well.

           Josh
Here is a small java program written by Rob Siemborski demonstrates the problem:

import java.io.OutputStream;
import java.util.logging.*;

/**
 * Class that demonstrates the logging performance problem we are experiencing.
 *
 * @author Rob Siemborski <###@###.###>
 */
public class LoggingPerf {
  static final int LOG_MESSAGES = 500000;
  static final int STACK_SIZE = 20;

  public static void main(String args[]) {
    System.out.println("Beginning fast test");
    long fastTime = runTest(getLogger(false));
    System.out.println("Beginning slow test");
    long slowTime = runTest(getLogger(true));
    System.out.println("slow / fast = " + (slowTime / fastTime));
  }

  /**
   * Returns a simple logger object that uses the test formatter and
   * a NullOutputStream (so we aren't relying on actual I/O in our test).
   */
  private static Logger getLogger(boolean beSlow) {
    Logger logger = Logger.getLogger("mylogger");
    logger.setUseParentHandlers(false);
    logger.addHandler(new StreamHandler(new NullOutputStream(),
                                        new TestFormatter(beSlow)));
    return logger;
  }

  /**
   * Recursive method to generate a stack trace of a reasonable size, so that
   * we can see the impact of a larger stack size on the time the formatter
   * takes to run.
   */
  private static void bigStack(int sizeLeft, long counter, Logger logger) {
    if (--sizeLeft > 0) {
      bigStack(sizeLeft, counter, logger);
    } else {
      // Must be high enough log level to cause StreamHandler to call formatter
      logger.info("log message " + counter);
    }
  }

  /**
   * Runs test and returns number of nanoseconds the test took to execute.
   */
  private static long runTest(Logger logger) {
    long startTime = System.nanoTime();
    for(long i = 0; i < LOG_MESSAGES; i++) {
      bigStack(STACK_SIZE, i, logger);
    }
    long endTime = System.nanoTime();
    long testTook = endTime - startTime;
    System.out.println("Run took: " + testTook + " ns");
    return testTook;
  }
};

/**
 * Simple OutputStream implementation that just ignores all the input.
 */
class NullOutputStream extends OutputStream {
  public void close() {}
  public void flush() {}
  public void write(byte b[]) {}
  public void write(byte b[], int off, int len) {}
  public void write(int b) {}
}

/**
 * Very simple log message formatter that will either call the slow
 * code that can generate the source and method names or not, depending
 * on which test we are running.
 */
class TestFormatter extends Formatter {
  private boolean beSlow;

  public TestFormatter(boolean beSlow) {
    this.beSlow = beSlow;
  }

  @Override
  public String format(LogRecord rec) {
    final StringBuilder buf = new StringBuilder();

    // Timestamp
    buf.append(rec.getMillis());
    buf.append(": ");

    if (beSlow) {
      // Information about the source of the exception.
      // The first call to getSource* is the slow part.
      buf.append(" [");
      buf.append(rec.getSourceClassName());
      buf.append(".");
      buf.append(rec.getSourceMethodName());
      buf.append("] ");
    }

    // The actual message
    buf.append(formatMessage(rec));
    buf.append("\n");

    return buf.toString();
  }
}