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

Stack trace sometimes shows 'locked' instead of 'waiting to lock'

    XMLWordPrintable

Details

    • Bug
    • Resolution: Fixed
    • P4
    • 9
    • 8
    • hotspot
    • b19
    • x86
    • windows_7

    Backports

      Description

        FULL PRODUCT VERSION :
        java version "1.8.0"
        Java(TM) SE Runtime Environment (build 1.8.0-b129)
        Java HotSpot(TM) Client VM (build 25.0-b69, mixed mode)

        ADDITIONAL OS VERSION INFORMATION :
        Microsoft Windows [Version 6.1.7601]

        EXTRA RELEVANT SYSTEM CONFIGURATION :
        Problem observed on linux-i586 and linux-x64 as well

        A DESCRIPTION OF THE PROBLEM :
        When stack trace information including a contended lock is obtained with Ctrl-Break, the stack trace often erroneously shows that multiple threads have locked the same object, leading to confusion and misunderstanding.

        STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
        1. Compile and run the attached program
        2. Obtain a stack trace multiple times (Ctrl-Break, jstack, ...)
        3. Observe the results

        EXPECTED VERSUS ACTUAL BEHAVIOR :
        EXPECTED -
        Threads Thread-0 and Thread-1 should never have identical lines '- locked <0xsomething> (a Test$1)' in their stack traces. One thread only should show as locking the object, while the other one should be 'waiting to lock' the same object, or just elsewhere in the code.
        ACTUAL -
        A thread that is shows 'waiting for monitor entry' in its stack trace header sometimes shows 'locked' on the object it is supposedly waiting to lock. See Thread-0 in the attached stack trace

        ERROR MESSAGES/STACK TRACES THAT OCCUR :
        2014-03-06 14:11:29
        Full thread dump Java HotSpot(TM) Client VM (25.0-b69 mixed mode):

        "DestroyJavaVM" #10 prio=5 os_prio=0 tid=0x0221c800 nid=0x9fac waiting on condition [0x00000000]
           java.lang.Thread.State: RUNNABLE

        "Thread-1" #9 prio=5 os_prio=0 tid=0x14d0b800 nid=0x1474 runnable [0x1554f000]
           java.lang.Thread.State: RUNNABLE
                at Test$1.run(Test.java:6)
                - locked <0x048725f8> (a Test$1)
                at java.lang.Thread.run(Thread.java:744)

        "Thread-0" #8 prio=5 os_prio=0 tid=0x14d09000 nid=0x2f4c waiting for monitor entry [0x1503f000]
           java.lang.Thread.State: BLOCKED (on object monitor)
                at Test$1.run(Test.java:6)
                - locked <0x048725f8> (a Test$1)
                at java.lang.Thread.run(Thread.java:744)

        "Service Thread" #7 daemon prio=9 os_prio=0 tid=0x14cb3400 nid=0x11f4 runnable [0x00000000]
           java.lang.Thread.State: RUNNABLE

        "C1 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x14cbd400 nid=0xa188 waiting on condition [0x00000000]
           java.lang.Thread.State: RUNNABLE

        "Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x14cbc400 nid=0xa160 runnable [0x00000000]
           java.lang.Thread.State: RUNNABLE

        "Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x14cb9400 nid=0xb780 waiting on condition [0x00000000]
           java.lang.Thread.State: RUNNABLE

        "Finalizer" #3 daemon prio=8 os_prio=1 tid=0x14c75800 nid=0x3104 in Object.wait() [0x14eef000]
           java.lang.Thread.State: WAITING (on object monitor)
                at java.lang.Object.wait(Native Method)
                - waiting on <0x048056d8> (a java.lang.ref.ReferenceQueue$Lock)
                at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
                - locked <0x048056d8> (a java.lang.ref.ReferenceQueue$Lock)
                at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:158)
                at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

        "Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x14c6f800 nid=0x2714 in Object.wait() [0x1508f000]
           java.lang.Thread.State: WAITING (on object monitor)
                at java.lang.Object.wait(Native Method)
                - waiting on <0x04805200> (a java.lang.ref.Reference$Lock)
                at java.lang.Object.wait(Object.java:502)
                at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
                - locked <0x04805200> (a java.lang.ref.Reference$Lock)

        "VM Thread" os_prio=2 tid=0x14c6b400 nid=0xa180 runnable

        "VM Periodic Task Thread" os_prio=2 tid=0x14cb5000 nid=0xbab4 waiting on condition

        JNI global references: 13

        Heap
         def new generation total 4928K, used 718K [0x04800000, 0x04d50000, 0x09d50000)
          eden space 4416K, 16% used [0x04800000, 0x048b39c8, 0x04c50000)
          from space 512K, 0% used [0x04c50000, 0x04c50000, 0x04cd0000)
          to space 512K, 0% used [0x04cd0000, 0x04cd0000, 0x04d50000)
         tenured generation total 10944K, used 0K [0x09d50000, 0x0a800000, 0x14800000)
           the space 10944K, 0% used [0x09d50000, 0x09d50000, 0x09d50200, 0x0a800000)
         Metaspace used 1553K, capacity 2242K, committed 2368K, reserved 4480K

        REPRODUCIBILITY :
        This bug can be reproduced often.

        ---------- BEGIN SOURCE ----------
        public class Test {
            public static void main(String[] args) {
                Runnable runnable = new Runnable() {
                    public void run() {
                        for (;;) {
                            synchronized (this) { }
                        }
                    }
                };
                new Thread(runnable).start();
                new Thread(runnable).start();
            }
        }
        ---------- END SOURCE ----------

        CUSTOMER SUBMITTED WORKAROUND :
        - Take multiple stack traces if possible
        - Understand that diagnostic information sometimes lies

        Attachments

          Issue Links

            Activity

              People

                dcubed Daniel Daugherty
                webbuggrp Webbug Group
                Votes:
                0 Vote for this issue
                Watchers:
                7 Start watching this issue

                Dates

                  Created:
                  Updated:
                  Resolved: