jvm stuck in SafepointSynchronize::begin()

[yang liu]

One of tomcat program hung and failed to response http request. After inspect the output of "jstack -F" and "pstack", I found the jvm stuck in SafepointSynchronize::begin() method. Why could this happen?

More details following.

1. top -H -p output, thread 25184 cpu 100%

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND

25184 root      20   0 14.8g 5.0g  62m R 100.3 32.8  17:50.67 java           <--------------

25170 root      20   0 14.8g 5.0g  62m S  0.0 32.8   0:00.01 java

25172 root      20   0 14.8g 5.0g  62m S  0.0 32.8   0:01.09 java

25173 root      20   0 14.8g 5.0g  62m S  0.0 32.8   0:02.61 java

25174 root      20   0 14.8g 5.0g  62m S  0.0 32.8   0:02.61 java

25175 root      20   0 14.8g 5.0g  62m S  0.0 32.8   0:02.59 java

25176 root      20   0 14.8g 5.0g  62m S  0.0 32.8   0:02.66 java

25177 root      20   0 14.8g 5.0g  62m S  0.0 32.8   0:02.62 java

25178 root      20   0 14.8g 5.0g  62m S  0.0 32.8   0:02.63 java

2. pstack output, thread 25184 cpu 100%

Thread 797 (Thread 0x7fe47d506700 (LWP 25184)):

#0  0x00007fe4af098d2b in SafepointSynchronize::begin() () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so <--------------

#1  0x00007fe4af191fef in VMThread::loop() () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#2  0x00007fe4af192470 in VMThread::run() () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#3  0x00007fe4af00b988 in java_start(Thread*) () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#4  0x00000037b52079d1 in start_thread () from /lib64/libpthread.so.0

#5  0x00000037b4ae88fd in clone () from /lib64/libc.so.6

3. jstack -F result

......

Thread 26488: (state = NEW)

Thread 2 (Thread 0x7fe359282700 (LWP 26488)):

#0  0x00000037b4af805e in __lll_lock_wait_private () from /lib64/libc.so.6

#1  0x00000037b4a7cc82 in _L_lock_3495 () from /lib64/libc.so.6

#2  0x00000037b4a77903 in arena_get2 () from /lib64/libc.so.6

#3  0x00000037b4a7a794 in malloc () from /lib64/libc.so.6

#4  0x00000037b4611190 in tls_get_addr_tail () from /lib64/ld-linux-x86-64.so.2

#5  0x00000037b4611660 in __tls_get_addr () from /lib64/ld-linux-x86-64.so.2

#6  0x00007fe4adabd762 in Profiler::Handle(int, siginfo*, void*) () from /usr/local/lightweight-java-profiler-master/build-64/liblagent.so

.......

Thread 26362: (state = IN_VM)

Thread 63 (Thread 0x7fe366e5d700 (LWP 26362)):

#0  0x00000037b520b5bc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0

#1  0x00007fe4af005243 in os::PlatformEvent::park() () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#2  0x00007fe4aefcc328 in Monitor::ILock(Thread*) () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#3  0x00007fe4aefcc55f in Monitor::lock_without_safepoint_check() () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#4  0x00007fe4af098127 in SafepointSynchronize::block(JavaThread*) () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#5  0x00007fe4aedead0b in JavaCallWrapper::JavaCallWrapper(methodHandle, Handle, JavaValue*, Thread*) () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#6  0x00007fe4aedeb94a in JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*) () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#7  0x00007fe4aedea5c8 in JavaCalls::call(JavaValue*, methodHandle, JavaCallArguments*, Thread*) () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#8  0x00007fe4aedea897 in JavaCalls::call_virtual(JavaValue*, KlassHandle, Symbol*, Symbol*, JavaCallArguments*, Thread*) () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#9  0x00007fe4aedea966 in JavaCalls::call_virtual(JavaValue*, Handle, KlassHandle, Symbol*, Symbol*, Handle, Thread*) () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#10 0x00007fe4af10e249 in SystemDictionary::load_instance_class(Symbol*, Handle, Thread*) () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

[Alex Bagehot]

Nitsan reported and fixed a 1/10 occurrence hang here: https://github.com/jvm-profiling-tools/honest-profiler/issues/75

Assuming You're using the lightweight java profiler which doesn't have that fix.

It is allocating memory in a signal handler see #3 and #9 below.

1 Point in time snapshot of thread state doesn't help much understand cpu usage - you need to take several of them or preferably get some perf output (which gives you a large number of unbiased cpu samples to work with).

However, the high/100% cpu of 1 thread associated with the hang happens because the thread initiating the safepoint (here LWP 25184) will spinpause/yield until all the threads have come to safepoint (which can't happen because of the profiler bug) or a safepoint timeout occurs.

thanks,

Alex

pstack.txt :

Thread 2 (Thread 0x7fe359282700 (LWP 26488)):

#0  0x00000037b4af805e in __lll_lock_wait_private () from /lib64/libc.so.6

#1  0x00000037b4a7cc82 in _L_lock_3495 () from /lib64/libc.so.6

#2  0x00000037b4a77903 in arena_get2 () from /lib64/libc.so.6

#3  0x00000037b4a7a794 in malloc () from /lib64/libc.so.6

#4  0x00000037b4611190 in tls_get_addr_tail () from /lib64/ld-linux-x86-64.so.2

#5  0x00000037b4611660 in __tls_get_addr () from /lib64/ld-linux-x86-64.so.2

#6  0x00007fe4adabd762 in Profiler::Handle(int, siginfo*, void*) () from /usr/local/lightweight-java-profiler-master/build-64/liblagent.so

#7  <signal handler called>

#8  0x00000037b4a77916 in arena_get2 () from /lib64/libc.so.6

#9  0x00000037b4a7a794 in malloc () from /lib64/libc.so.6

#10 0x00000037b5208b3f in pthread_getattr_np () from /lib64/libpthread.so.0

#11 0x00007fe4af00f724 in current_stack_region(unsigned char**, unsigned long*) () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#12 0x00007fe4af00f815 in os::current_stack_base() () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#13 0x00007fe4af13e614 in Thread::record_stack_base_and_size() () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#14 0x00007fe4af144dd4 in JavaThread::run() () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#15 0x00007fe4af00b988 in java_start(Thread*) () from /usr/java/jdk1.7.0_65/jre/lib/amd64/server/libjvm.so

#16 0x00000037b52079d1 in start_thread () from /lib64/libpthread.so.0

#17 0x00000037b4ae88fd in clone () from /lib64/libc.so.6

--
You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsub...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[yang liu]

Thank's for the reply! 😄

[Nitsan Wakart]

Thanks Alex!

For future reference to all here:

AFAIK lightweight-java-profiler has never progressed much beyond the proof of concept stage and is not actively maintained. It was forked and developed into honest-profiler, which offers more features, is actively developed and is more stable. On a different foundation and offering further interesting capabilities we also have async-profiler.

If you are using LWP, or thinking about using it, or know someone who uses it, switch to either HP or AP.

To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-symp...@googlegroups.com.