Heap_lock голодание в сборщике мусора
Потоки сборщика мусора, похоже, голодали, ожидая Heap_lock. Вот трассировка стека потока GC
+ 5480 _pthread_start (in libsystem_pthread.dylib) + 168 [0x7fff9255191a]
+ 5480 _pthread_body (in libsystem_pthread.dylib) + 131 [0x7fff9255199d]
+ 5480 java_start(Thread*) (in libjvm.dylib) + 246 [0x110e82cd6]
+ 5480 YieldingFlexibleGangWorker::loop() (in libjvm.dylib) + 419 [0x110fbf8fb]
+ 5480 Monitor::wait(bool, long, bool) (in libjvm.dylib) + 375 [0x110e5c859]
+ 5480 Monitor::IWait(Thread*, long) (in libjvm.dylib) + 168 [0x110e5c5f0]
+ 5480 ParkCommon(ParkEvent*, long) (in libjvm.dylib) + 42 [0x110e5bd1a]
+ 5480 os::PlatformEvent::park() (in libjvm.dylib) + 192 [0x110e7ea72]
+ 5480 _pthread_cond_wait (in libsystem_pthread.dylib) + 767 [0x7fff92552728]
+ 5480 __psynch_cvwait (in libsystem_kernel.dylib) + 10 [0x7fff98080db6]
Мое приложение Java порождает около 300 потоков. Они также голодают. Вот пример трассировки стека:
+ 5480 java_lang_String::create_from_str(char const*, Thread*) (in libjvm.dylib) + 59 [0x110cf1ab9]
+ 5480 java_lang_String::basic_create(int, Thread*) (in libjvm.dylib) + 38 [0x110cef8a0]
+ 5480 InstanceKlass::allocate_instance(Thread*) (in libjvm.dylib) + 31 [0x110cbd93f]
+ 5480 CollectedHeap::obj_allocate(KlassHandle, int, Thread*) (in libjvm.dylib) + 38 [0x110cbff8a]
+ 5480 CollectedHeap::common_mem_allocate_noinit(KlassHandle, unsigned long, Thread*) (in libjvm.dylib) + 140 [0x110ab2484]
+ 5480 GenCollectorPolicy::mem_allocate_work(unsigned long, bool, bool*) (in libjvm.dylib) + 475 [0x110b9f313]
+ 5480 Monitor::lock(Thread*) (in libjvm.dylib) + 132 [0x110e5c4e6]
+ 5480 Monitor::ILock(Thread*) (in libjvm.dylib) + 310 [0x110e5c3dc]
+ 5480 ParkCommon(ParkEvent*, long) (in libjvm.dylib) + 42 [0x110e5bd1a]
+ 5480 os::PlatformEvent::park() (in libjvm.dylib) + 192 [0x110e7ea72]
+ 5480 _pthread_cond_wait (in libsystem_pthread.dylib) + 767 [0x7fff92552728]
+ 5480 __psynch_cvwait (in libsystem_kernel.dylib) + 10 [0x7fff98080db6]
Голод начинается после нескольких часов работы моего приложения.
Я попробовал три сборщика: UseG1GC, UseParallelGC и UseConcMarkSweepGC с настройками по умолчанию и все еще получаю голод (не пробовал последовательный GC).
Я использую Java 1.8.0_92 (сборка 1.8.0_92-b14, Java HotSpot(TM) 64-разрядная серверная виртуальная машина, сборка 25.92-b14, смешанный режим) в OSX 10.11.5.
Достаточно места в куче Xmx6G; Я не вижу полной GC. Я увеличил стек для потоков GC XX:VMThreadStackSize до 10 МБ, но получил такое же голодание. Я также использовал более старую Java, то же голодание. Я не вижу ни одного фатального журнала ошибок ( http://www.oracle.com/technetwork/java/javase/felog-138657.html).
Пожалуйста, предложите, как отладить это голодание.
ОБНОВЛЕНИЕ 19 июня 2016 года:
Я сгруппировал висячие потоки по трассе стека, которую вы можете увидеть
Повесьте в GangWorker::loop()
5347 Thread_669608
+ 5347 thread_start (in libsystem_pthread.dylib) + 13 [0x7fff930c3351]
+ 5347 _pthread_start (in libsystem_pthread.dylib) + 168 [0x7fff930c591a]
+ 5347 _pthread_body (in libsystem_pthread.dylib) + 131 [0x7fff930c599d]
+ 5347 java_start(Thread*) (in libjvm.dylib) + 246 [0x112485bbe]
+ 5347 GangWorker::loop() (in libjvm.dylib) + 179 [0x1125c194f]
+ 5347 Monitor::wait(bool, long, bool) (in libjvm.dylib) + 375 [0x11245f639]
+ 5347 Monitor::IWait(Thread*, long) (in libjvm.dylib) + 168 [0x11245f3d0]
+ 5347 ParkCommon(ParkEvent*, long) (in libjvm.dylib) + 42 [0x11245eafa]
+ 5347 os::PlatformEvent::park() (in libjvm.dylib) + 192 [0x11248195a]
+ 5347 _pthread_cond_wait (in libsystem_pthread.dylib) + 767 [0x7fff930c6728]
+ 5347 __psynch_cvwait (in libsystem_kernel.dylib) + 10 [0x7fff8dbbcdb6]
Зависать в ConcurrentG1RefineThread::wait_for_completed_buffers()
5347 Thread_669627
+ 5347 thread_start (in libsystem_pthread.dylib) + 13 [0x7fff930c3351]
+ 5347 _pthread_start (in libsystem_pthread.dylib) + 168 [0x7fff930c591a]
+ 5347 _pthread_body (in libsystem_pthread.dylib) + 131 [0x7fff930c599d]
+ 5347 java_start(Thread*) (in libjvm.dylib) + 246 [0x112485bbe]
+ 5347 ConcurrentG1RefineThread::run() (in libjvm.dylib) + 90 [0x1121c054e]
+ 5347 ConcurrentG1RefineThread::wait_for_completed_buffers() (in libjvm.dylib) + 65 [0x1121c08e5]
+ 5347 Monitor::wait(bool, long, bool) (in libjvm.dylib) + 375 [0x11245f639]
+ 5347 Monitor::IWait(Thread*, long) (in libjvm.dylib) + 168 [0x11245f3d0]
+ 5347 ParkCommon(ParkEvent*, long) (in libjvm.dylib) + 42 [0x11245eafa]
+ 5347 os::PlatformEvent::park() (in libjvm.dylib) + 192 [0x11248195a]
+ 5347 _pthread_cond_wait (in libsystem_pthread.dylib) + 767 [0x7fff930c6728]
+ 5347 __psynch_cvwait (in libsystem_kernel.dylib) + 10 [0x7fff8dbbcdb6]
Зависание потоков компилятора
5347 Thread_669680: Java: C2 CompilerThread0
+ 5347 thread_start (in libsystem_pthread.dylib) + 13 [0x7fff930c3351]
+ 5347 _pthread_start (in libsystem_pthread.dylib) + 168 [0x7fff930c591a]
+ 5347 _pthread_body (in libsystem_pthread.dylib) + 131 [0x7fff930c599d]
+ 5347 java_start(Thread*) (in libjvm.dylib) + 246 [0x112485bbe]
+ 5347 JavaThread::run() (in libjvm.dylib) + 450 [0x112566344]
+ 5347 JavaThread::thread_main_inner() (in libjvm.dylib) + 155 [0x112564c57]
+ 5347 CompileBroker::compiler_thread_loop() (in libjvm.dylib) + 376 [0x1121b89ce]
+ 5347 CompileQueue::get() (in libjvm.dylib) + 122 [0x1121b87ac]
+ 5347 Monitor::wait(bool, long, bool) (in libjvm.dylib) + 222 [0x11245f5a0]
+ 5347 Monitor::IWait(Thread*, long) (in libjvm.dylib) + 168 [0x11245f3d0]
+ 5347 os::PlatformEvent::park(long) (in libjvm.dylib) + 404 [0x112482844]
+ 5347 _pthread_cond_wait (in libsystem_pthread.dylib) + 767 [0x7fff930c6728]
+ 5347 __psynch_cvwait (in libsystem_kernel.dylib) + 10 [0x7fff8dbbcdb6]
Кроме того, оставшиеся потоки имеют эти следы стека (одна строка на поток)
_OSSpinLockLockSlow ! syscall_thread_switch _OSSpinLockLockSlow _pthread_lookup_thread pthread_kill os::SuspendedThreadTask::internal_do_task() os::SuspendedThreadTask::run() ThreadSampleClosure::sample_thread(JavaThread*, 5347 Thread_669693
__accept BsdAttachListener::dequeue() AttachListener::dequeue() attach_listener_thread_entry(JavaThread*, JavaThread::thread_main_inner() JavaThread::run() java_start(Thread*) _pthread_body 5347 Thread_669711: Java: Attach Listener
__psynch_cvwait _pthread_cond_wait Parker::park(bool, Unsafe_Park ??? ??? 5347 Thread_669715: Java: RMI Scheduler(0)
__psynch_cvwait _pthread_cond_wait Parker::park(bool, Unsafe_Park ??? ??? ??? ??? 5347 Thread_669777: Java: log4j2.jmx.notif1
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ObjectMonitor::wait(long, ObjectSynchronizer::wait(Handle, JVM_MonitorWait ??? ??? 5347 Thread_669603
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ObjectMonitor::wait(long, ObjectSynchronizer::wait(Handle, JVM_MonitorWait ??? ??? 5347 Thread_669657: Java: Reference Handler
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ObjectMonitor::wait(long, ObjectSynchronizer::wait(Handle, JVM_MonitorWait ??? ??? 5347 Thread_669658: Java: Finalizer
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::ILock(Thread*) Monitor::lock(Thread*) G1CollectedHeap::attempt_allocation_slow(unsigned G1CollectedHeap::attempt_allocation(unsigned 5347 Thread_669669: Java: JFR request timer
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::ILock(Thread*) Monitor::lock(Thread*) G1CollectedHeap::attempt_allocation_slow(unsigned G1CollectedHeap::attempt_allocation(unsigned 5347 Thread_669712: Java: RMI TCP Accept-0
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::ILock(Thread*) Monitor::lock(Thread*) G1CollectedHeap::attempt_allocation_slow(unsigned G1CollectedHeap::attempt_allocation(unsigned 5347 Thread_669720: Java: JMX server connection timeout 29
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::ILock(Thread*) Monitor::lock(Thread*) G1CollectedHeap::attempt_allocation_slow(unsigned G1CollectedHeap::attempt_allocation(unsigned 5347 Thread_683755: Java: RMI TCP Connection(65)-192.168.1.167
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::ILock(Thread*) Monitor::lock(Thread*) G1CollectedHeap::attempt_allocation_slow(unsigned G1CollectedHeap::attempt_allocation(unsigned 5347 Thread_813902: Java: RMI TCP Connection(634)-192.168.1.167
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::ILock(Thread*) Monitor::lock(Thread*) SafepointSynchronize::begin() VMThread::loop() 5347 Thread_669656
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::ILock(Thread*) Monitor::lock_without_safepoint_check() SafepointSynchronize::block(JavaThread*) ThreadStateTransition::trans_and_fence(JavaThreadState, 5347 Thread_669676: Java: VM JFR Buffer Thread
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::IWait(Thread*, Monitor::wait(bool, ConcurrentMarkThread::sleepBeforeNextCycle() ConcurrentMarkThread::run() 5347 Thread_669645
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::IWait(Thread*, Monitor::wait(bool, ServiceThread::service_thread_entry(JavaThread*, JavaThread::thread_main_inner() 5347 Thread_669692: Java: Service Thread
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::IWait(Thread*, Monitor::wait(bool, SurrogateLockerThread::loop() JavaThread::thread_main_inner() 5347 Thread_669667: Java: Surrogate Locker Thread (Concurrent GC)
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::IWait(Thread*, Monitor::wait(bool, SuspendibleThreadSet::join() ConcurrentG1RefineThread::sample_young_list_rs_lengths() 5347 Thread_669626
__semwait_signal pthread_join ContinueInNewThread0 ContinueInNewThread JVMInit JLI_Launch main apple_main 5347 Thread_669600
__sigsuspend SR_handler(int, _sigtramp vframeStreamCommon::fill_from_frame() _pthread_lookup_thread pthread_kill closefd ??? 5347 Thread_671069: Java: DelayClose
kevent_qos _dispatch_mgr_invoke _dispatch_mgr_thread 5347 Thread_669601 DispatchQueue_2: com.apple.libdispatch-manager (serial)
mach_msg_trap mach_msg __CFRunLoopServiceMachPort __CFRunLoopRun CFRunLoopRunSpecific CreateExecutionEnvironment JLI_Launch main 5347 Thread_669599 DispatchQueue_1: com.apple.main-thread (serial)
semaphore_wait_trap check_pending_signals(bool) signal_thread_entry(JavaThread*, JavaThread::thread_main_inner() JavaThread::run() java_start(Thread*) _pthread_body _pthread_start 5347 Thread_669668: Java: Signal Dispatcher
__psynch_cvwait _pthread_cond_wait os::PlatformEvent::park() ParkCommon(ParkEvent*, Monitor::ILock(Thread*) Monitor::lock(Thread*) G1CollectedHeap::attempt_allocation_slow(unsigned 5347 Thread_815183: Java: RMI TCP Connection(635)-192.168.1.167
Я пропустил свои 300 потоков, потому что Java не находится в безопасной точке (jstack не работает), поэтому голодание не может быть из-за моих (пользовательских) потоков. Истощение должно быть вызвано потоками виртуальных машин (все из которых я перечислил выше со следами стека).
ОБНОВЛЕНИЕ 24 июня 2016 года:
Я сделал jstack -F, и мои потоки заблокированы, некоторые из них в операциях с памятью, как этот
Thread 200451: (state = BLOCKED)
- java.util.Arrays.copyOf(char[], int) @bci=1, line=3332 (Compiled frame)
- java.lang.AbstractStringBuilder.expandCapacity(int) @bci=43, line=137 (Compiled frame)
- java.lang.AbstractStringBuilder.ensureCapacityInternal(int) @bci=12, line=121 (Compiled frame)
- java.lang.AbstractStringBuilder.append(java.lang.String) @bci=21, line=421 (Compiled frame)
- java.lang.StringBuilder.append(java.lang.String) @bci=2, line=136 (Compiled frame)
но jstack не показывает потоки сборщика мусора. Чтобы получить это, я запускаю пример команды для того же процесса, и так же, как прежде, чем вы можете увидеть голодные потоки GC:
+ 5229 ??? (in <unknown binary>) [0x11064ae07]
+ 5229 OptoRuntime::new_array_nozero_C(Klass*, int, JavaThread*) (in libjvm.dylib) + 54 [0x10f8da854]
+ 5229 TypeArrayKlass::allocate_common(int, bool, Thread*) (in libjvm.dylib) + 138 [0x10f975406]
+ 5229 CollectedHeap::common_mem_allocate_noinit(KlassHandle, unsigned long, Thread*) (in libjvm.dylib) + 105 [0x10f4b2bbb]
+ 5229 CollectedHeap::allocate_from_tlab_slow(KlassHandle, Thread*, unsigned long) (in libjvm.dylib) + 283 [0x10f59e2af]
+ 5229 G1CollectedHeap::allocate_new_tlab(unsigned long) (in libjvm.dylib) + 28 [0x10f65590e]
+ 5229 G1CollectedHeap::attempt_allocation(unsigned long, unsigned int*, unsigned int*) (in libjvm.dylib) + 182 [0x10f65e42a]
+ 5229 G1CollectedHeap::attempt_allocation_slow(unsigned long, unsigned char, unsigned int*, unsigned int*) (in libjvm.dylib) + 339 [0x10f6576ab]
+ 5229 Monitor::lock(Thread*) (in libjvm.dylib) + 132 [0x10f85f2c6]
+ 5229 Monitor::ILock(Thread*) (in libjvm.dylib) + 310 [0x10f85f1bc]
+ 5229 ParkCommon(ParkEvent*, long) (in libjvm.dylib) + 42 [0x10f85eafa]
+ 5229 os::PlatformEvent::park() (in libjvm.dylib) + 192 [0x10f88195a]
+ 5229 _pthread_cond_wait (in libsystem_pthread.dylib) + 767 [0x7fff930c6728]
+ 5229 __psynch_cvwait (in libsystem_kernel.dylib) + 10 [0x7fff8dbbcdb6]
Голод исчез, когда я запустил свое приложение всего с 30 потоками (вместо 300).
Нам нужно выяснить, какую блокировку ожидает __psynch_cvwait сборщика мусора, но jstack этого не говорит. Вероятно, проверка кода - лучший выбор.