Почему этот Java-процесс не может завершиться?

У меня проблема прерывания на сервере сборки, где процесс Java в сборке каким-то образом не завершается и, кажется, продолжает работать (используя 100% ЦП) навсегда (я видел, как он работал в течение 2+ дней в выходные дни, где обычно занимает около 10 минут). kill -9 pid кажется единственным способом остановить процесс.

Я попытался вызвать kill -QUIT pid в процессе, но он, похоже, не создает трассировку стека для STDOUT (может быть, она не отвечает на сигнал?). jstack без опции -F force, похоже, не может подключиться к запущенной JVM, но с параметром force он выводит результат, указанный ниже.

К сожалению, даже с этой трассировкой стека я не вижу никакого очевидного пути для дальнейшего изучения.

Насколько я могу судить, он показывает два потока "BLOCKED", которые запустили Object.wait(их стеки содержат только основной код Java, ничего из нашего), а третий - "IN_VM" без вывода стека.

Какие шаги следует предпринять для сбора дополнительной информации о причине проблемы (или еще лучше, как я могу ее решить)?

$ /opt/jdk1.6.0_29/bin/jstack -l -F 5546
Attaching to process ID 5546, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 20.4-b02
Deadlock Detection:

No deadlocks found.

Finding object size using Printezis bits and skipping over...
Thread 5555: (state = BLOCKED)

Locked ownable synchronizers:
    - None

Thread 5554: (state = BLOCKED)
 - java.lang.Object.wait(long) @bci=0 (Interpreted frame)
 - java.lang.ref.ReferenceQueue.remove(long) @bci=44, line=118 (Interpreted frame)
 - java.lang.ref.ReferenceQueue.remove() @bci=2, line=134 (Interpreted frame)
 - java.lang.ref.Finalizer$FinalizerThread.run() @bci=3, line=159 (Interpreted frame)

Locked ownable synchronizers:
    - None

Thread 5553: (state = BLOCKED)
 - java.lang.Object.wait(long) @bci=0 (Interpreted frame)
 - java.lang.Object.wait() @bci=2, line=485 (Interpreted frame)
 - java.lang.ref.Reference$ReferenceHandler.run() @bci=46, line=116 (Interpreted frame)

Locked ownable synchronizers:
    - None

Thread 5548: (state = IN_VM)

Locked ownable synchronizers:
    - None

(обновление Java версии 1.6.0 29, работающее на выпуске Scientific Linux версии 6.0)

Update:

Запуск strace -f -p 894 создает бесконечный поток...

[pid   900] sched_yield()               = 0
[pid   900] sched_yield()               = 0
...

а затем, когда Ctrl-Cd

Process 894 detached
...
Process 900 detached
...
Process 909 detached

jmap -histo 894 не соединение, а jmap -F -histo 894 возвращает...

Attaching to process ID 894, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 20.4-b02
Iterating over heap. This may take a while...
Finding object size using Printezis bits and skipping over...
Finding object size using Printezis bits and skipping over...
Object Histogram:

num       #instances    #bytes  Class description
--------------------------------------------------------------------------
1:      11356   1551744 * MethodKlass
2:      11356   1435944 * ConstMethodKlass
3:      914 973488  * ConstantPoolKlass
4:      6717    849032  char[]
5:      16987   820072  * SymbolKlass
6:      2305    686048  byte[]
7:      914 672792  * InstanceKlassKlass
8:      857 650312  * ConstantPoolCacheKlass
9:      5243    167776  java.lang.String
10:     1046    108784  java.lang.Class
11:     1400    87576   short[]
12:     1556    84040   * System ObjArray
13:     1037    64584   int[]
14:     103 60152   * ObjArrayKlassKlass
15:     622 54736   java.lang.reflect.Method
16:     1102    49760   java.lang.Object[]
17:     937 37480   java.util.TreeMap$Entry
18:     332 27960   java.util.HashMap$Entry[]
19:     579 27792   java.nio.HeapByteBuffer
20:     578 27744   java.nio.HeapCharBuffer
21:     1021    24504   java.lang.StringBuilder
22:     1158    24176   java.lang.Class[]
23:     721 23072   java.util.HashMap$Entry
24:     434 20832   java.util.TreeMap
25:     689 18936   java.lang.String[]
26:     238 17440   java.lang.reflect.Method[]
27:     29  16800   * MethodDataKlass
28:     204 14688   java.lang.reflect.Field
29:     330 13200   java.util.LinkedHashMap$Entry
30:     264 12672   java.util.HashMap
...
585:        1   16  java.util.LinkedHashSet
586:        1   16  sun.rmi.runtime.NewThreadAction$2
587:        1   16  java.util.Hashtable$EmptyIterator
588:        1   16  java.util.Collections$EmptySet
Total :     79700   8894800
Heap traversal took 1.288 seconds.

Ответы

Ответ 1

Вы всегда можете сделать strace -f -p pid, чтобы узнать, что делает процесс Java. По внешнему виду (вы не можете получить jstack без -F, а в потоке 5548 нет стека вызовов и это IN_VM), похоже, что поток 5548 слишком много делает для чего-то или, возможно, в некотором бесконечном цикле.

Ответ 2

это может быть вызвано нехваткой памяти. Я бы попробовал две вещи:

  • Включить автоматический сброс кучи на OutOfMemory, добавив параметры JVM

    -XX: + HeapDumpOnOutOfMemoryError XX: HeapDumpPath =/tmp

  • Попробуйте подключиться к JVM с помощью JConsole и посмотреть, есть ли какой-либо необычный шаблон

Ответ 3

Я бы заподозрил проблему памяти. Вы можете посмотреть процесс с помощью jstat и взять кучу кучи, используя jmap примерно в то время, когда вам нужно убить процесс. Посмотрите, указывает ли jstat непрерывный GC. Кроме того, вы можете проверить состояние системы в целом (открыть файловые дескрипторы, сеть и т.д.). Память была бы самой простой, поэтому я настоятельно рекомендую начать с нее.

Ответ 4

Сделайте снимок, пока процесс работает нормально через jstack -F (-F должен присутствовать, он создает другой снимок, чем просто jstack). Номера потоков не являются Thread.id, а системными. 5548, похоже, создается до Finalizer и RefCounter (они не являются источником проблемы), поэтому он должен быть либо потоком GC, либо некоторым компилятором.

100%, вероятно, означает некоторую ошибку в мониторе. Мониторы Java (hotspot) используют очень простой механизм блокировки спина, чтобы обеспечить право собственности.

И, конечно же, присоедините отладчик - GDB, чтобы проверить, где именно застрял процесс.

Ответ 5

Тема 5554 может указывать на то, что у вас много объектов с методами finalize и/или с некоторыми проблемами с методом finalize. Возможно, стоит посмотреть на это.

Я не был знаком с jstack, но похоже, что он выводит меньше информации о том, что сбрасывает поток, с которым я больше знаком. Может быть полезно попытаться получить дамп потока: kill -QUIT java_pid. Обратите внимание, что дамп отправляется в stdout, который может быть для консоли или для файла журнала в зависимости от вашей настройки.

Если вам сложно определить, куда направляется stdout, и, предположив, что он собирается в файл, вы можете использовать find по последнему времени модификации для идентификации файлов-кандидатов. Это предлагается в комментарии к этому сообщению в блоге:

вы можете запустить команду find [2] в корневом каталоге и узнать, что изменено за последние х секунд. Я обычно использовал находку, чтобы помочь мне доступ ко всем журналам, которые изменились за последние 10 минут, например: find /var/tomcat -mmin -3 -print (распечатывает все файлы, измененные в /var/tomcat за последние 3 минуты).

Обратите внимание, что если вы используете JVM с -Xrs, это означает, что обработчик сигнала SIGQUIT не будет установлен, и вы не сможете использовать это средство для запроса дампа потока.

Ответ 6

Я сталкиваюсь с подобной проблемой, мой JBOSS jvm получает бесконечный цикл, в конце концов он получает OutOfMemory, я не могу убить этот процесс, но Kill -9. Я подозреваю, что проблема с памятью в большинстве случаев.

Ответ 7

Вот некоторые инструменты, которые вы можете использовать для локализации части процессора, потребляющего процессор:

  • perf/oprofile, особенно opannotate - отлично подходит для просмотра того, что адский код потребляет циклы
  • strace, gstack/gdb (как упоминалось другими)
  • systemtap чрезвычайно мощна, но ограничена некоторыми способами, такими как инструменты ptrace (если ваша проблема не связана с syscall, она намного менее эффективна).