Bug ID: JDK-4636055 HPROF: JVM crashes during Shutdown when cpu=times with many threads, finalizatio


Name: tb29552			Date: 02/11/2002


/*
 * FULL PRODUCT VERSION : java version "1.4.0-rc" Java(TM) 2 Runtime
 * Environment, Standard Edition (build 1.4.0-rc-b91) Java HotSpot(TM) Client
 * VM (build 1.4.0-rc-b91, mixed mode)
 * 
 * 
 * FULL OPERATING SYSTEM VERSION :
 * 
 * glibc-2.2.4-19.3 Linux 2.4.9-6smp #1 SMP i686 Red Hat Linux release 7.2
 * (Enigma)
 * 
 * ADDITIONAL OPERATING SYSTEMS :
 * 
 * 
 * EXTRA RELEVANT SYSTEM CONFIGURATION : 2 CPUs
 * 
 * A DESCRIPTION OF THE PROBLEM : When starting Java with "java
 * -Xrunhprof:cpu=times ..." the program will execute normally, but the JVM
 * crashes before the CPU statistics are written to the file.
 * 
 * The effect is identical to that of bug 4489387, but in JDK 1.4 RC1, this bug
 * will only occur in a rarer setting. See the attached log and the bug
 * reproducing source code for details.
 * 
 * 
 * STEPS TO FOLLOW TO REPRODUCE THE PROBLEM : 1. Compile the attached sources.
 * 2. java -Xrunhprof:cpu=times CrashTest 3. Fiddle with the loop counts
 * until the bug manifests reliably.
 * 
 * EXPECTED VERSUS ACTUAL BEHAVIOR : I expected the CPU profiling data to be
 * written to a file. Actually, the JVM crashes. In rarer cases, it hangs.
 * 
 * 
 * ERROR MESSAGES/STACK TRACES THAT OCCUR : HPROF ERROR: thread local table NULL
 * in method exit 0x8073f44 HPROF ERROR: thread local table NULL in method
 * exit 0x8073f44 HPROF ERROR: thread local table NULL in method exit
 * 0x8075a5c HPROF ERROR : stack underflow in method exit HPROF ERROR : stack
 * underflow in method exit
 * 
 * Unexpected Signal : 11 occurred at PC=0x40339442
 * Function=get_thread_local_storage__5jvmpiP7JNIEnv_+0xF2
 * Library=/usr/java/j2sdk1.4.0/jre/lib/i386/client/libjvm.so
 * 
 * Current Java thread: at java.lang.Shutdown.halt(Native Method) at
 * java.lang.Shutdown.exit(Shutdown.java:211) - locked <0x48193dc8> (a
 * java.lang.Class) at java.lang.Runtime.exit(Runtime.java:90) at
 * java.lang.System.exit(System.java:713) at
 * CrashTest.main(CrashTest.java:31)
 * 
 * Dynamic libraries: 08048000-0804d000 r-xp 00000000 09:00 1589915
 * /usr/java/j2sdk1.4.0/bin/java 0804d000-0804e000 rw-p 00004000 09:00
 * 1589915    /usr/java/j2sdk1.4.0/bin/java 40000000-40016000 r-xp 00000000
 * 09:00 1474573    /lib/ld-2.2.4.so 40016000-40017000 rw-p 00015000 09:00
 * 1474573    /lib/ld-2.2.4.so 40018000-40021000 r-xp 00000000 09:00 1999515
 * /usr/java/j2sdk1.4.0/jre/lib/i386/native_threads/libhpi.so
 * 40021000-40022000 rw-p 00008000 09:00 1999515
 * /usr/java/j2sdk1.4.0/jre/lib/i386/native_threads/libhpi.so
 * 40022000-40023000 r--p 00000000 09:00 672074
 * /usr/lib/locale/en_US/LC_IDENTIFICATION 40023000-40024000 r--p 00000000
 * 09:00 262789 /usr/lib/locale/en_US/LC_MEASUREMENT 40024000-40025000 r--p
 * 00000000 09:00 1998861 /usr/lib/locale/en_US/LC_TELEPHONE
 * 40025000-40026000 r--p 00000000 09:00 1999242
 * /usr/lib/locale/en_US/LC_ADDRESS 40026000-40027000 r--p 00000000 09:00
 * 1999241    /usr/lib/locale/en_US/LC_NAME 40027000-40028000 r--p 00000000
 * 09:00 1720334    /usr/lib/locale/en_US/LC_PAPER 40028000-40029000 r--p
 * 00000000 09:00 2015260 /usr/lib/locale/en_US/LC_MESSAGES/SYS_LC_MESSAGES
 * 40029000-4002a000 r--p 00000000 09:00 262207
 * /usr/lib/locale/en_US/LC_MONETARY 4002a000-40037000 r-xp 00000000 09:00
 * 688145     /lib/i686/libpthread-0.9.so 40037000-4003f000 rw-p 0000c000
 * 09:00 688145     /lib/i686/libpthread-0.9.so 4003f000-40042000 r-xp
 * 00000000 09:00 1474590    /lib/libdl-2.2.4.so 40042000-40043000 rw-p
 * 00002000 09:00 1474590    /lib/libdl-2.2.4.so 40043000-40175000 r-xp
 * 00000000 09:00 688139     /lib/i686/libc-2.2.4.so 40175000-4017b000 rw-p
 * 00131000 09:00 688139     /lib/i686/libc-2.2.4.so 4017f000-40442000 r-xp
 * 00000000 09:00 803192 /usr/java/j2sdk1.4.0/jre/lib/i386/client/libjvm.so
 * 40442000-4058a000 rw-p 002c2000 09:00 803192
 * /usr/java/j2sdk1.4.0/jre/lib/i386/client/libjvm.so 4059e000-405b1000 r-xp
 * 00000000 09:00 1474595    /lib/libnsl-2.2.4.so 405b1000-405b2000 rw-p
 * 00012000 09:00 1474595    /lib/libnsl-2.2.4.so 405b4000-405e8000 r-xp
 * 00000000 09:00 328613 /usr/lib/libstdc++-2-libc6.1-1-2.9.0.so
 * 405e8000-405f4000 rw-p 00033000 09:00 328613
 * /usr/lib/libstdc++-2-libc6.1-1-2.9.0.so 405f6000-40618000 r-xp 00000000
 * 09:00 688143     /lib/i686/libm-2.2.4.so 40618000-40619000 rw-p 00021000
 * 09:00 688143     /lib/i686/libm-2.2.4.so 40619000-4062a000 r-xp 00000000
 * 09:00 1261810 /usr/java/j2sdk1.4.0/jre/lib/i386/libverify.so
 * 4062a000-4062c000 rw-p 00010000 09:00 1261810
 * /usr/java/j2sdk1.4.0/jre/lib/i386/libverify.so 4062c000-4064d000 r-xp
 * 00000000 09:00 1261798 /usr/java/j2sdk1.4.0/jre/lib/i386/libjava.so
 * 4064d000-4064f000 rw-p 00020000 09:00 1261798
 * /usr/java/j2sdk1.4.0/jre/lib/i386/libjava.so 40650000-40664000 r-xp
 * 00000000 09:00 1261811 /usr/java/j2sdk1.4.0/jre/lib/i386/libzip.so
 * 40664000-40667000 rw-p 00013000 09:00 1261811
 * /usr/java/j2sdk1.4.0/jre/lib/i386/libzip.so 40667000-41cde000 r--s
 * 00000000 09:00 737945 /usr/java/j2sdk1.4.0/jre/lib/rt.jar
 * 41d20000-41d37000 r--s 00000000 09:00 737946
 * /usr/java/j2sdk1.4.0/jre/lib/sunrsasign.jar 41d37000-41da5000 r--s
 * 00000000 09:00 737937 /usr/java/j2sdk1.4.0/jre/lib/jsse.jar
 * 41da5000-41db8000 r--s 00000000 09:00 737936
 * /usr/java/j2sdk1.4.0/jre/lib/jce.jar 41db8000-42039000 r--s 00000000 09:00
 * 737925 /usr/java/j2sdk1.4.0/jre/lib/charsets.jar 440e1000-440e7000 r--p
 * 00000000 09:00 671763 /usr/lib/locale/en_US/LC_COLLATE 440e7000-440e8000
 * r--p 00000000 09:00 672075     /usr/lib/locale/en_US/LC_TIME
 * 440e8000-440e9000 r--p 00000000 09:00 425999
 * /usr/lib/locale/en_US/LC_NUMERIC 440e9000-440eb000 r--s 00000000 09:00
 * 1245856 /usr/java/j2sdk1.4.0/jre/lib/ext/dnsns.jar 4c2f3000-4c31e000 r--p
 * 00000000 09:00 426003     /usr/lib/locale/en_US/LC_CTYPE 4c31e000-4c32c000
 * r--s 00000000 09:00 1245857 /usr/java/j2sdk1.4.0/jre/lib/ext/ldapsec.jar
 * 4c330000-4c33a000 r-xp 00000000 09:00 1474611
 * /lib/libnss_files-2.2.4.so 4c33a000-4c33b000 rw-p 00009000 09:00 1474611
 * /lib/libnss_files-2.2.4.so 4c33b000-4c34e000 r-xp 00000000 09:00 1261795
 * /usr/java/j2sdk1.4.0/jre/lib/i386/libhprof.so 4c34e000-4c34f000 rw-p
 * 00012000 09:00 1261795 /usr/java/j2sdk1.4.0/jre/lib/i386/libhprof.so
 * 4c57e000-4c621000 r--s 00000000 09:00 1245858
 * /usr/java/j2sdk1.4.0/jre/lib/ext/localedata.jar 4c621000-4c63e000 r--s
 * 00000000 09:00 1245859
 * /usr/java/j2sdk1.4.0/jre/lib/ext/sunjce_provider.jar
 * 
 * Local Time = Mon Jan 28 11:25:39 2002 Elapsed Time = 4 # # HotSpot Virtual
 * Machine Error : 11 # Error ID : 4F530E43505002D3 # Please report this
 * error at # http://java.sun.com/cgi-bin/bugreport.cgi # # Java VM: Java
 * HotSpot(TM) Client VM (1.4.0-rc-b91 mixed mode) #
 * 
 * 
 * This bug can be reproduced often.
 * 
 * ---------- BEGIN SOURCE ----------
 */
class DeliveryThread extends Thread {
    public synchronized void run() {
        try {
            while (true)
                wait();
        } catch(InterruptedException e) {
        }
    }
}

class Worker {
    private Thread  eventThread;

    public Worker () {
        for (int i = 0; i < 100; i++) {
            new Object();
        }
        this.eventThread = new DeliveryThread ();
        this.eventThread.start();
        for (int i = 0; i < 100; i++) {
            new Object();
        }
    }

    protected void finalize() {
        eventThread.interrupt();
    }

}

public class CrashTest {
    private static void usage() {
        System.err.println("Usage: java -Xrunhprof:cpu=times CrashTest " +
                           "<number of threads to create>");
        System.exit(1);
    }

    public static void main(String[] args) {
        if (args.length != 1) {
            usage();
        }
        try {
            int threadCount = Integer.parseInt(args[0]);
            System.out.println("Launching: " + threadCount + " Worker threads");
            for (int i = 0; i < threadCount; i++) {
                new Worker ();
            }
        } catch (NumberFormatException nex) {
            System.err.println(nex);
            usage();
        }
        System.out.println("Shutting down VM");
        System.exit(0);
    }
}

//---------- END SOURCE ----------

(Review ID: 138868) 
======================================================================

WORK AROUND Name: tb29552 Date: 02/11/2002 ###@###.### 2002-02-11 1) Remove the uses of finalize() or possibly: 2) Allow the workers to finish in an orderly manner, rather than calling System.exit() from main with no warning. ======================================================================
01-09-2004
PUBLIC COMMENTS .
01-09-2004
EVALUATION Problem does not show up with the new hprof (4873337) and will be closed as "will not fix" after integration of 4873337 in tiger (1.5). This appears to be some kind of problem with JVMPI ThreadLocalStorage not working, or maybe being used when it should not be used? The hprof agent doesn't search it's thread table when GetThreadLocalStorage returns NULL, it should fall back to searching it's table. ###@###.### 2003-11-09 ###@###.### 2004-01-29 I believe this problem was fixed via another bug: 4850081 4/4 Get/SetThreadLocalStorage need to work with AsyncGetCallTrace In particular, the following from 4850081's description matches this bug: > There are a couple of issues with using JVM/PI GetThreadLocalStorage() > and SetThreadLocalStorage() in a signal handler: : > - the methods do not check the return value from > JavaThread::thread_from_jni_environment() before using it. This means > that toward the end of a thread's life, a NULL pointer dereference > can crash the VM. I fixed 4850081 for Mantis Update 2 and Tiger. If Kelly concurs, I plan to close this bug as a duplicate of 4850081. ###@###.### 2004-01-29 (update 1) Kelly concurs so I'm closing this bug.
29-01-2004
SUGGESTED FIX If GetThreadLocalStorage returns NULL, search the thread table as a backup. ###@###.### 2003-11-09
09-11-2003

Duplicate :	JDK-4850081 - Get/SetThreadLocalStorage need to work with AsyncGetCallTrace
Relates :	JDK-5021882 - NEWHPROF: multiple Hprof failures with the CrashTest
Relates :	JDK-4325563 - HPROF: CPU sampling can continue during VM shutdown
Relates :	JDK-4489387 - -Xrunhprof crashed jvm or got program run to hang