oliver% /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.
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
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.
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.
This problem was originally reported by Sean Coffey running the following
command on Mustang-B99:

    java -Xprof -jar SwingSet2.jar