customer % /java/re/jdk/1.5.0_08/promoted/latest/binaries/solaris-i586/bin/java -Xprof
Usage: java [-options] class [args...]
           (to execute a class)
   or  java [-options] -jar jarfile [args...]
           (to execute a jar file)

where options include:
<snip>

Flat profile of 0.07 secs (1 total ticks): main

  Thread-local ticks:
100.0%     1             Blocked (of total)


Global summary of 0.07 seconds:
100.0%     1             Received ticks


And the 'latest' Mustang bits (B99):

% /java/re/jdk/1.6.0/promoted/latest/binaries/solaris-i586/bin/java -XprofUsage: java [-options] class [args...]
           (to execute a class)
   or  java [-options] -jar jarfile [args...]
           (to execute a jar file)

<snip>

Flat profile of 6.88 secs (4 total ticks): main

  Thread-local ticks:
 75.0%     3             Class loader
 25.0%     1             Unknown: thread_state


Global summary of 6.89 seconds:
100.0%     4             Received ticks
100.0%     4             Compilation
 75.0%     3             Class loader
 25.0%     1             Unknown code


Six seconds to do nothing is a problem. Especially when 1.5.0_08
takes 0.07 seconds to do the same.
Posted Date : 2006-09-22 17:28:48.0

The example in the previous entry ('.../bin/java -Xprof') does not always
run long enough for the flat profiler to be invoked. Here is a better
example program:

% cat MainSleepAndExit.java
public class MainSleepAndExit {
  public static void main(String[] args) {
    System.out.println("Hello world!");
    System.out.println("About to sleep for 5 seconds.");
    try {
        Thread.sleep(5000);
    } catch (InterruptedException ie) {
    }
    System.out.println("About to exit(0) from main.");
    System.exit(0);
  }
}

This program should run for ~6 seconds and instead runs for ~12 seconds
with the -Xprof option:

% $JAVA_HOME/bin/java -Xprof MainSleepAndExit
Hello world!
About to sleep for 5 seconds.
About to exit(0) from main.

Flat profile of 12.01 secs (11 total ticks): main

  Interpreted + native   Method
  9.1%     0  +     1    java.lang.Thread.sleep
  9.1%     0  +     1    java.io.FileInputStream.readBytes
  9.1%     1  +     0    sun.misc.URLClassPath.getLoader
 27.3%     1  +     2    Total interpreted

  Thread-local ticks:
 54.5%     6             Class loader
  9.1%     1             Unknown: no last frame
  9.1%     1             Unknown: thread_state


Global summary of 12.01 seconds:
100.0%    11             Received ticks
 63.6%     7             Compilation
 54.5%     6             Class loader
 18.2%     2             Unknown code
Posted Date : 2006-09-26 17:39:45.0

The next example program gives a similar result:

% cat MainSleepAndReturn.java
public class MainSleepAndReturn {
  public static void main(String[] args) {
    System.out.println("Hello world!");
    System.out.println("About to sleep for 5 seconds.");
    try {
        Thread.sleep(5000);
    } catch (InterruptedException ie) {
    }
    System.out.println("About to return from main.");
    return;
  }
}

This program should run for ~6 seconds and instead runs for ~12 seconds
with the -Xprof option:

% $JAVA_HOME/bin/java -Xprof MainSleepAndReturn
Hello world!
About to sleep for 5 seconds.
About to return from main.

Flat profile of 5.48 secs (26 total ticks): main

  Interpreted + native   Method
 96.2%     0  +    25    java.io.FileInputStream.readBytes
  3.8%     0  +     1    java.lang.Thread.sleep
100.0%     0  +    26    Total interpreted


Flat profile of 6.77 secs (1 total ticks): DestroyJavaVM

  Thread-local ticks:
100.0%     1             Unknown: thread_state


Global summary of 12.25 seconds:
100.0%    27             Received ticks
  3.7%     1             Unknown code

Because main() falls off the end, the extra time is cleanly
attributed to the DestroyJavaVM thread.
Posted Date : 2006-09-26 17:39:46.0

One more example that is very similar to MainSleepAndReturn:

% cat ChildThreadSleepAndReturn.java
public class ChildThreadSleepAndReturn extends Thread {
  public ChildThreadSleepAndReturn(String name) {
    super(name);
  }

  public void run() {
    System.err.println(getName() + ": thread is running.");
    System.err.println(getName() + ": thread is" +
        (isDaemon() ? " " : " NOT") + " a daemon thread.");
    System.err.println(getName() + ": thread is about to sleep for 5 secs.");
    try {
        Thread.sleep(5000);  // wait for 5 seconds
    } catch (InterruptedException ie) {
    }
    System.err.println(getName() + ": thread is about to return.");
  }

  public static void main(String[] args) {
    System.err.println("main: thread is running.");

    ChildThreadSleepAndReturn t1 = new ChildThreadSleepAndReturn("ChildThread");    t1.start();

    System.err.println("main: thread is about to return.");
  }
}

This program should run for ~6 seconds and instead runs for ~13 seconds
with the -Xprof option:

% $JAVA_HOME/bin/java -Xprof ChildThreadSleepAndReturn
main: thread is running.
main: thread is about to return.
ChildThread: thread is running.
ChildThread: thread is NOT a daemon thread.
ChildThread: thread is about to sleep for 5 secs.
ChildThread: thread is about to return.

Flat profile of 6.78 secs (1 total ticks): ChildThread

  Interpreted + native   Method
100.0%     0  +     1    java.lang.Thread.sleep
100.0%     0  +     1    Total interpreted


Flat profile of 13.56 secs (2 total ticks): DestroyJavaVM

  Thread-local ticks:
100.0%     2             Unknown: thread_state


Global summary of 13.57 seconds:
100.0%     2             Received ticks
100.0%     2             Unknown code

Again main() falls off the end, and this time DestroyJavaVM gets
attributed ~13 seconds of time. In this test program, the
DestroyJavaVM has waited through two wait_for_ext_suspend_completion()
timeouts.
Posted Date : 2006-09-26 17:39:46.0

This problem was originally reported by Sean Coffey running the following
command on Mustang-B99:

    java -Xprof -jar SwingSet2.jar
Posted Date : 2006-09-26 19:41:25.0

The fix for 6440070 also added two new product flags:

  /* 50 retries * (5 * current_retry_count) millis = ~6.375 seconds */      \
  /* typically, at most a few retries are needed */                         \
  product(intx, SuspendRetryCount, 50,                                      \
          "Maximum retry count for an external suspend request")            \
                                                                            \
  product(intx, SuspendRetryDelay, 5,                                       \
          "Milliseconds to delay per retry (* current_retry_count)")        \


To work around an instance of this bug, reduce the number of retries.
For example, -XX:SuspendRetryCount=25 will reduce the delay to about
1 second.

The following bug is a likely suspect:

    6440070 2/2 NotifyFramePop throws unexpected error:
            JVMTI_ERROR_THREAD_NOT_SUSPENDED
Posted Date : 2006-09-22 17:23:36.0

The fix for 6440070 exposed a problem in the fix for the following bug:

    6321448 3/3 self-suspension with JVM-internal monitors and mutexes may
                not be needed

Changing Monitor::wait() to no longer be a suspend-equivalent condition is
the right thing to do in most uses of Monitor::wait(). However, there are
some places in the VM where the Monitor::wait() call can stall for a very
long time which results in wait_for_ext_suspend_completion() timeouts.
Because of the suspend-wait-retry scaling changes made in 6440070, these
timeouts can take ~6 seconds per occurrence.
Posted Date : 2006-09-26 19:41:25.0