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

Print additional information in thread dump (times, allocated bytes etc.)

XMLWordPrintable

    • svc
    • b20
    • generic
    • generic

        We at SAP have extended the thread dumps (obtained by jstack or jcmd) by several fields providing thread specific information. These extensions are quite popular with our support team. With some knowledge of the architecture of the application, they often allow for quick and simple diagnosis of a running system. Therefore we would like to contribute these enhancements.

        I took a few simple examples here, namely cpu time, elapsed time since thread creation, bytes allocated and classes defined by the thread. Provided it is known how the application should behave, a misbehaving thread can identified easily.

        There is no measurable overhead for this enhancement. However, it may be a problem that the format of the output is changed. Tools parsing the output may have to be changed.

        The added values are:

        - cpu=... : the time the thread spent executing on the CPU.

        - elapsed=... : the wall clock time passed since the thread was started.

        These two values allow you to detect threads that either spend too much time on the CPU or too less.
        The first ones might be a perfromance bottleneck. Threads that spend no time on the CPU might be
        blocked by something. This can especially be spotted by comparing subsequent thread dumps.

        - allocated=... : The number of bytes allocated by this thread.

        This might hint to a thread that tends to fill up the heap and cause too many garbage collections.

        - defined_classes=... : The number of classes defined by this thread

        This might hint to a thread that loads too many classes.

        The values 'allocated=' and 'defined_classes=' are only printed if the VM is started with -XX:+PrintExtendedThreadInfo.
        If the thread dumps are gathered by jcmd, '-e' must be added to the Thread.print command.

        Here is an example of the output generated:

        "main" #1 prio=5 os_prio=31 cpu=5884.26ms elapsed=42.41s allocated=155M defined_classes=1728 tid=0x00007fad8e801800 nid=0x2103 waiting on condition [0x0000000104f18000]
           java.lang.Thread.State: TIMED_WAITING (sleeping)
           JavaThread state: _thread_blocked
        Thread: 0x00007fad8e801800 [0x2103] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
           JavaThread state: _thread_blocked
        at java.lang.Thread.sleep(java.base/Native Method)
        at spec.jbb.JBButil.SecondsToSleep(JBButil.java:359)
        at spec.jbb.Company.displayResultTotals(Company.java:464)
        at spec.jbb.JBBmain.DoARun(JBBmain.java:223)
        at spec.jbb.JBBmain.runWarehouse(JBBmain.java:310)
        at spec.jbb.JBBmain.doIt(JBBmain.java:261)
        at spec.jbb.JBBmain.main(JBBmain.java:711)

        Printing the pthread_id was dropped from this RFE.

              ghaug Gunter Haug
              ghaug Gunter Haug
              Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

                Created:
                Updated:
                Resolved: