VisualVM
  1. VisualVM
  2. VISUALVM-511

estimated real CPU time gives impossible values

    Details

    • Type: Bug Bug
    • Status: Open
    • Priority: Major Major
    • Resolution: Unresolved
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: code
    • Labels:
      None
    • Environment:

      osx 10.6.8 on 2.66GHz Intel Core i7.
      java version "1.6.0_33"
      Java(TM) SE Runtime Environment (build 1.6.0_33-b03-424-10M3720)
      Java HotSpot(TM) 64-Bit Server VM (build 20.8-b03-424, mixed mode)

      Description

      Profile (with the Sampler in default settings) the attached program on a eg 4-core CPU. The program tries to run 8 threads in parallel, each thread busy-waiting for exactly 10 seconds.

      On a 4-core CPU this should result in an even distribution of the available 4*10s over the 8 processes.

      The ThreadMXBean output from the program confirms this, with each process getting around 4s of real CPU time.

      But the VisualVM gives a totally different picture, saying that all 8 processes got a 10seconds estimated real CPU time for a total of 80seconds. Obviously this is impossible with only 10 seconds runtime on a 4-core processor.

      The problem also shows on Win7-32bit.

      {{{
      import java.lang.management.ManagementFactory;
      import java.lang.management.ThreadMXBean;
      import java.util.Scanner;

      /**

      • simple test for profiler. Runs 8 threads all for 10 seconds
      • @author W.Pasman
      • */
        public class test2 {
        public static void main(String[] args) {
        System.out.println("press enter to start");
        Scanner sc = new Scanner(System.in);
        sc.nextLine();

      for (int n = 0; n < 8; n++) {
      Thread t = new Thread() {
      @Override
      public void run()

      { test2.sleep("child ", 10000); }

      };
      t.start();
      }
      test2.sleep("main", 10000);
      System.out.println("press enter to stop");
      sc.nextLine();

      }

      public static void sleep(String name, long t)

      { System.out.println(name + " is sleeping " + t); long start = System.currentTimeMillis(); while (System.currentTimeMillis() - start < t) ; ThreadMXBean bean = ManagementFactory.getThreadMXBean(); System.out.println("this thread ran " + bean.getThreadCpuTime(Thread.currentThread().getId()) / 1000000000. + "s."); }

      }
      }}}

      Attached is an image with the incorrect calltree CPU times.

        Activity

        Hide
        w.pasman added a comment -

        I checked the code (trunk version on svn)

        I see this in ThreadsCPU.java:

        {{{
        public ThreadsCPUInfo getThreadsCPUInfo() throws MBeanException, ReflectionException, IOException, InstanceNotFoundException {
        long[] ids = threadBean.getAllThreadIds();
        ThreadInfo[] tids = threadBean.getThreadInfo(ids);
        Object[] args = new Object[]

        {ids}

        ;
        String[] sigs = new String[]

        {"[J"}

        ; // NOI18N
        long[] tinfo = (long[])connection.invoke(THREAD_NAME, "getThreadCpuTime", args, sigs); // NOI18N
        long time = System.currentTimeMillis();

        return new ThreadsCPUInfo(time,tids,tinfo);
        }
        }}}

        Now I'm not used to the connection.invoke but it seems to me that getThreadCpuTime takes only 1 long, not an array of longs as what I understand from the code. See the ThreadMXBean interface definition.

        Show
        w.pasman added a comment - I checked the code (trunk version on svn) I see this in ThreadsCPU.java: {{{ public ThreadsCPUInfo getThreadsCPUInfo() throws MBeanException, ReflectionException, IOException, InstanceNotFoundException { long[] ids = threadBean.getAllThreadIds(); ThreadInfo[] tids = threadBean.getThreadInfo(ids); Object[] args = new Object[] {ids} ; String[] sigs = new String[] {"[J"} ; // NOI18N long[] tinfo = (long[])connection.invoke(THREAD_NAME, "getThreadCpuTime", args, sigs); // NOI18N long time = System.currentTimeMillis(); return new ThreadsCPUInfo(time,tids,tinfo); } }}} Now I'm not used to the connection.invoke but it seems to me that getThreadCpuTime takes only 1 long, not an array of longs as what I understand from the code. See the ThreadMXBean interface definition.

          People

          • Assignee:
            Unassigned
            Reporter:
            w.pasman
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated: