Блог

Главная - Вопросы по программированию - Как интерпретировать дамп потока Java?

Как интерпретировать дамп потока Java?

#java #thread-dump

#java #дамп потока

Вопрос:

У меня здесь есть веб-приложение Java, работающее на Tomcat6 с Ubuntu (server edition). Через 1-3 дня приложение становится очень медленным, поэтому я создал threaddump после нового перезапуска tomcat и еще один, когда приложение начинает замедляться:

Threaddump после нового перезапуска:

Threaddump через 3 дня (приложение работает медленно):

Из опубликованных мной дампов я вижу, что существует множество потоков, которые, похоже, по какой-то причине не завершаются. К сожалению, я не могу сказать, какие из них (имена классов?) и почему. Использование top на консоли показало, что значение «VIRT» увеличилось с ~ 800 (после нового перезапуска) до более 4000 (через 3 дня).

Как я могу лучше интерпретировать эти дампы? Я уже пытался загрузить их в TDA, но это не сработало (TDA, похоже, не распознает их как дампы).

Может быть, кто-то уже видит в дампах, что происходит?

Комментарии:

1. дамп потока может содержать недостаточно информации для отслеживания проблем с отзывчивостью.

2. @MRalwasser Каким будет ваше предложение?

3. Я смотрю на это. Я думаю, что он, вероятно, содержит достаточно информации, но есть тысячи потоков, поэтому потребуется некоторое копание.

4. @valmar Я бы профилировал приложение, пока оно страдает от «медленного реагирования»

5. @MRalwasser Как бы вы это сделали?

Ответ №1:

В текстовом файле jstack я вижу множество потоков, зависающих в BCI (интерпретатор байтового кода), вероятно, интерпретирующих ваш код. Похоже, он не указывает, где в вашем коде он интерпретируется.

В нем говорится, что у вас есть условие взаимоблокировки.

В файле .out я искал то, что выглядит как код приложения. Я вижу, что он висит на

  • EventProcessingThreadImpl.run:479 (2 потока)

  • GC.java: 100 (1 поток) в GC, ожидающий, пока что-то будет выпущено, чтобы GC мог продолжить.

  • Многие потоки, припаркованные в небезопасном состоянии, ожидающие синхронизатора, пытающиеся прочитать очередь заданий в ThreadPoolExecutor.java:907

  • Я также вижу то, что выглядит как множество шаблонных потоков, ожидающих выполнения работы, запускаемых потоков, ожидающих почты и т. Д.

Это как-нибудь поможет?

Добавлено:

Хорошо, я искал ваш код и нашел его в трех потоках, показанных здесь, и под каждым я дал предварительное объяснение.

(Также обратите внимание на эту ссылку об использовании jstack для поиска взаимоблокировок.)

 ----------------- 20607 -----------------
__pthread_cond_wait   0xcc
_ZN13ObjectMonitor4waitElbP6Thread   0x60a
_ZN18ObjectSynchronizer4waitE6HandlelP6Thread   0x53
JVM_MonitorWait   0x1e7
<Unknown compiled code>
* java.lang.Object.wait() bci:2 line:485 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessingThreadImpl.doSuspend0(java.lang.Object) bci:143 line:219 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessingThreadImpl.doSuspend(java.lang.Object) bci:7 line:185 (Interpreted frame)
* org.zkoss.zk.ui.impl.UiEngineImpl.wait(java.lang.Object) bci:198 line:1471 (Interpreted frame)
* org.zkoss.zk.ui.Executions.wait(java.lang.Object) bci:4 line:702 (Interpreted frame)
* org.zkoss.zul.Window.enterModal() bci:22 line:619 (Interpreted frame)
* org.zkoss.zul.Window.doModal() bci:67 line:551 (Interpreted frame)
* org.zkoss.zul.Messagebox.show(java.lang.String, java.lang.String, int, java.lang.String, int,     org.zkoss.zk.ui.event.EventListener) bci:343 line:274 (Interpreted frame)
* org.zkoss.zul.Messagebox.show(java.lang.String, java.lang.String, int, java.lang.String) bci:6 line:128 (Interpreted frame)
* com.smampi.web.view.client.ClientController$5.onEvent(org.zkoss.zk.ui.event.Event) bci:8 line:417 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessor.process0(org.zkoss.zk.ui.ext.Scope) bci:384 line:192 (Compiled frame)
????????

Поток 20607 находится в com.smampi.web.view.client.ClientController $ 5.onEvent строка 128 (я предполагаю).
Он отображает окно модального сообщения и ожидает ответа на него.

 ----------------- 20878 -----------------
__pthread_cond_wait   0xcc
_ZN13ObjectMonitor4waitElbP6Thread   0x60a
_ZN18ObjectSynchronizer4waitE6HandlelP6Thread   0x53
JVM_MonitorWait   0x1e7
<Unknown compiled code>
* java.lang.Object.wait() bci:2 line:485 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessingThreadImpl.doSuspend0(java.lang.Object) bci:143 line:219 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessingThreadImpl.doSuspend(java.lang.Object) bci:7 line:185 (Interpreted frame)
* org.zkoss.zk.ui.impl.UiEngineImpl.wait(java.lang.Object) bci:198 line:1471 (Interpreted frame)
* org.zkoss.zk.ui.Executions.wait(java.lang.Object) bci:4 line:702 (Interpreted frame)
* org.zkoss.zul.Window.enterModal() bci:22 line:619 (Interpreted frame)
* org.zkoss.zul.Window.doModal() bci:67 line:551 (Interpreted frame)
* org.zkoss.zul.Messagebox.show(java.lang.String, java.lang.String, int, java.lang.String, int, org.zkoss.zk.ui.event.EventListener) bci:343 line:274 (Interpreted frame)
* org.zkoss.zul.Messagebox.show(java.lang.String, java.lang.String, int, java.lang.String) bci:6 line:128 (Interpreted frame)
* com.smampi.web.view.client.ClientController$5.onEvent(org.zkoss.zk.ui.event.Event) bci:8 line:417 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessor.process0(org.zkoss.zk.ui.ext.Scope) bci:384 line:192 (Compiled frame)
????????

Поток 20878 также отображает окно сообщения, но в строке 417 (я предполагаю)

 ----------------- 22792 -----------------
__pthread_cond_wait   0xcc
_ZN7Monitor5ILockEP6Thread   0xb9
_ZN7Monitor4lockEP6Thread   0xf2
_ZN7Monitor4lockEv   0x28
_ZN18GenCollectorPolicy17mem_allocate_workEmbPb   0xca
_ZN16GenCollectedHeap12mem_allocateEmbbPb   0x38
_ZN13CollectedHeap26common_mem_allocate_noinitEmbP6Thread   0x9a
_ZN13instanceKlass17allocate_instanceEP6Thread   0x7d
_ZN18InterpreterRuntime4_newEP10JavaThreadP19constantPoolOopDesci   0xda
* com.sun.mail.util.SocketFetcher.startTLS(java.net.Socket, java.lang.String, java.util.Properties, java.lang.String) bci:378 line:413 (Interpreted frame)
* com.sun.mail.iap.Protocol.startTLS(java.lang.String) bci:23 line:377 (Interpreted frame)
* com.sun.mail.imap.protocol.IMAPProtocol.startTLS() bci:3 line:734 (Interpreted frame)
* com.sun.mail.imap.IMAPStore.login(com.sun.mail.imap.protocol.IMAPProtocol, java.lang.String, java.lang.String) bci:24 line:676 (Interpreted frame)
* com.sun.mail.imap.IMAPStore.protocolConnect(java.lang.String, int, java.lang.String, java.lang.String) bci:343 line:643 (Interpreted frame)
* javax.mail.Service.connect(java.lang.String, int, java.lang.String, java.lang.String) bci:380 line:295 (Interpreted frame)
* com.smampi.web.model.mail.server.MailServer.connect() bci:427 line:514 (Interpreted frame)
* com.smampi.web.model.mail.server.MailServer$1.closed(javax.mail.event.ConnectionEvent) bci:10 line:593 (Interpreted frame)
* javax.mail.event.ConnectionEvent.dispatch(java.lang.Object) bci:55 line:96 (Interpreted frame)

Поток 22792 пытается подключиться к почтовой службе из строки 514 com.smampi.web.model.mail.server.MailServer.connect, и он вызывается из com.smampi.web.model.mail.server.MailServer $ 1.закрыт в строке 593.
Для этого похоже, что он ожидает, пока другой поток прекратит сбор мусора, чтобы он мог выделить память для нового потока, чтобы он мог выполнить «startTLS» (для обновления простой текстовой ссылки до зашифрованной), чтобы он мог подключиться к почтовой службе.

Это проливает какой-либо свет?

Комментарии:

1. Мх, не совсем. Я понятия не имею, что EventProcessingThreadImpl.run может быть и откуда оно берется. Кроме того, я не знаю, какие объекты / потоки ожидает GC. Я знаю, что там много потоков, припаркованных в ожидании чего-то, но для чего? И какие это могут быть потоки? =/

2. @valmar: Я пытался выяснить, из всех вещей в этих трассировках стека, которые были в вашем коде, в отличие от системного кода Java или сторонних библиотек. Я посмотрю еще раз, если вы можете дать какой-то ключ к пониманию того, какой код на самом деле написан как часть вашего приложения, потому что, если есть что-то, что вы можете исправить, это то, где оно есть.

3. Мой код взят из пакетов com.smampi.* — Все остальное взято из других библиотек и самой Java.

4. Прежде всего, большое вам спасибо за ваши усилия, я действительно ценю это! Меня немного смущает, что модальное окно ожидает (чего?). Обычно, если модальное окно сообщения не может быть открыто, оно просто не должно выдавать исключение. Поток 22792 кажется более интересным, хотя я не понимаю, почему GC не завершает уничтожение объектов.. Откуда вы знаете, что поток в любом случае ожидает GC?

5. @valmar: Вы можете узнать, что вызывает модальное диалоговое окно, просмотрев строку кода, запрашивающую его. Это было бы интересно, потому что, возможно, это может привести к зависанию всего. Проблема с подключением заключается в том, что он ожидает завершения GC, который может ожидать, что что-то еще будет разблокировано одним из этих других потоков. (В файле действительно говорилось, что у вас тупиковая ситуация.)

Ответ №2:

Я вижу множество потоков, пытающихся установить контекст SSL:

Демон "JavaMail-EventQueue" prio = 10 tid = 0x00007f9f10416000 nid = 0x54c6 ожидает ввода монитора [0x00007f9e3e92d000]
 java.lang.Нитки.Состояние: ЗАБЛОКИРОВАНО (на мониторе объекта)
 в sun.security.provider.NativePRNG$randomIO.implNextBytes(NativePRNG.java:255)
 - ожидание блокировки (java.lang.Объект)
 в sun.security.provider.NativePRNG $randomIO.access $ 200(NativePRNG.java:108)
 в sun.security.provider.NativePRNG.engineNextBytes(NativePRNG.java:97)
в java.security.SecureRandom.nextBytes(SecureRandom.java:433)
 - заблокирован (java.security.SecureRandom)
 в java.security.SecureRandom.next(SecureRandom.java:455)
 в java.util.Random.nextInt(Random.java:189)
 в com.sun.net.ssl.internal.ssl.SSLContextImpl.engineerinit(SSLContextImpl.java:82)
в javax.net.ssl.SSLContext.init(SSLContext.java:248)
 в com.sun.mail.util.MailSSLSocketFactory.newAdapteeFactory(MailSSLSocketFactory.java:130)
 - заблокирован (com.sun.mail.util.MailSSLSocketFactory)
в com.sun.mail.util.MailSSLSocketFactory.(MailSSLSocketFactory.java:119)
 в com.sun.mail.util.MailSSLSocketFactory.(MailSSLSocketFactory.java:94)
 в com.sun.mail.util.SocketFetcher.startTLS(SocketFetcher.java: 413)
в com.sun.mail.iap.Protocol.startTLS(Protocol.java:377)
 - заблокирован (com.sun.mail.imap.protocol.IMAPProtocol)
 в com.sun.mail.imap.protocol.IMAPProtocol.startTLS(IMAPProtocol.java:734)
в com.sun.mail.imap.IMAPStore.login(IMAPStore.java: 676)
в com.sun.mail.imap.IMAPStore.protocolConnect(IMAPStore.java:643)
 - заблокирован (com.sun.mail.imap.IMAPStore)
 в javax.mail.Service.connect(Service.java:295)
 - заблокирован (com.sun.mail.imap.IMAPStore)
в com.smampi.web.model.mail.server.MailServer.connect(MailServer.java: 514)
 в com.smampi.web.model.mail.server.MailServer $ 1.закрыт (MailServer.java:593)
 в javax.mail.event.ConnectionEvent.dispatch(ConnectionEvent.java:96)
в javax.mail.EventQueue.run(EventQueue.java:134)
 в java.lang.Thread.run(Thread.java:662)

Я часто видел, как серверы становятся необъяснимо медленными во время настройки SSL (либо как сервер, либо как клиент), когда количество доступной энтропии для операционной системы становится очень низким (т. Е. ОС больше не может выдавать высококачественные случайные числа).

Попробуйте отобразить содержимое /proc/sys/kernel/random/entropy_avail с помощью 

 cat /proc/sys/kernel/random/entropy_avail

Это должно рассказать вам, сколько случайных данных ОС может предоставить на данный момент, обычно это должно быть не менее сотни. Если он постоянно равен 0 или очень близок, то у вас проблема и вам необходимо ввести другой источник энтропии.

Опять же, может быть и наоборот: на другом конце этого соединения могут возникнуть проблемы со сбором энтропии, и ответ может быть медленным.

Комментарии:

1. Я проверил /proc/sys/kernel/random/entropy_avail, и он дает мне значение 130. Интересно, будет ли этого достаточно? Мое приложение — это многопользовательское приложение, в котором каждый пользователь может настроить несколько учетных записей электронной почты. Каждая учетная запись подключается к своему собственному почтовому серверу через TLS или SSL (в отдельном потоке).

2. Хорошая догадка — но я вижу только три потока в собственной генерации случайных чисел — два из них в РАБОТОСПОСОБНОМ состоянии, что указывает на отсутствие ненужных ожиданий. Маловероятно, что это является основной причиной проблемы.

Ответ №3:

У вас много (тысячи?) Потоков в состоянии ОЖИДАНИЯ. Читайте здесь о различных состояниях потока: http://download.oracle.com/javase/1 ,5,0/docs/api/java/lang/Thread.State.html

Это проблема. Вам нужно будет выяснить, почему ваше приложение создает так много потоков, а не уничтожает их.

У вас также есть множество потоков, называемых «JavaMail-EventQueue». Узнайте, почему жизненный цикл рассылки не завершается. Добавив некоторые операторы ведения журнала к использованию JavaMail, вы, вероятно, обнаружите, что некоторые действия регулярно не выполняются.

Комментарии:

1. Да, я понял, что на этапе ожидания находится много потоков, и я также подозревал, что моя логика электронной почты имеет к этому какое-то отношение. К сожалению, приложение очень большое, и есть много классов, которые используют JavaMail, поэтому я действительно не знаю, как и с чего начать. Нет ли способа найти имя класса, который создает эти потоки (или имя класса самого потока)?

2. Нет, я не знаю способа узнать, что создает потоки. Если его нет в дампе потока, вы потеряны. Попробуйте перенести все использование JavaMail в общий класс… например, «JavaMailWrapper»… который просто регистрирует, а затем делегирует JavaMail. Вам придется проделать некоторую болезненную работу, подобную этой, чтобы решить проблему.

Ответ №4:

Я предполагаю, что вы случайно пытаетесь передать TLS (зашифрованный) службе, которая не ожидает зашифрованного трафика, поэтому у вас много потоков, ожидающих правильного ответа, который никогда не приходит.

Вы уверены, что используете правильный номер порта для этой службы?