Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-6474293

performance regression in -Xprof

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: P3
    • Resolution: Fixed
    • Affects Version/s: 6
    • Fix Version/s: hs10
    • Component/s: hotspot
    • Labels:
      None
    • Subcomponent:
    • Resolved In Build:
      b03
    • CPU:
      generic
    • OS:
      generic

      Backports

        Description

        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

          Attachments

            Issue Links

              Activity

                People

                Assignee:
                dcubed Daniel Daugherty
                Reporter:
                dcubed Daniel Daugherty
                Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                  Dates

                  Created:
                  Updated:
                  Resolved:
                  Imported:
                  Indexed: