Как выглядит дамп потока, когда JVM провела время в GC

При профилировании Java-приложения я отмечаю интересный факт. Когда JVM находится в GC, спираль дампа потока смерти выглядит так:

"1304802943@qtp-393978767-9985" prio=10 tid=0x00007f3ed02dd000 nid=0x74e7 in Object.wait() [0x000000004febb000]
 java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:626)
    - locked <0x00000007aed40048> (a org.mortbay.thread.QueuedThreadPool$PoolThread)

"26774405@qtp-393978767-9984" prio=10 tid=0x00007f3ee4b37000 nid=0x74e6 in Object.wait() [0x0000000045d1a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:626)
    - locked <0x00000007aed83aa0> (a org.mortbay.thread.QueuedThreadPool$PoolThread)

"764808089@qtp-393978767-9983" prio=10 tid=0x00007f3ee4c50000 nid=0x74e5 in Object.wait() [0x000000004ad6a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:626)
    - locked <0x00000007aed5c448> (a org.mortbay.thread.QueuedThreadPool$PoolThread)

Итак, есть много потоков в состоянии TIMED_WAITING. Теоретически такая ситуация может быть легко обнаружена в нормально работающем приложении (у приложения просто нет входящих запросов в данный момент), но я не могу найти ни одного потока диспетчеризации запросов, делающего что-то полезное (номинальная частота обращений около 100 hps).

Это поведение имеет какое-то отношение к GC или это просто совпадение?


java garbage-collection thread-dump
person Denis Bazhenov    schedule 07.12.2011    source источник
comment
Вместо анализа дампов потоков добавьте: -XX:+PrintGCDetails -XX:+PrintGCTimeStamps для обнаружения долго выполняющегося GC.   -  person Tomasz Nurkiewicz    schedule 07.12.2011

Ответы (3)


arrow_upward
3
arrow_downward

Отвечая только на заголовок вопроса:

Как выглядит дамп потока, когда JVM проводит время в GC?

Ответ: у вас нет возможности получить такой дамп (обычным способом).

JVM обрабатывает запрос на создание дампа потока только после достижения точки безопасности. что просто не может произойти в GC.

Но есть читерский способ получить дамп потока активного GC с помощью недокументированной функции JVMTI AsyncGetCallTrace, которая упоминается в этом посте:

http://jeremymanson.blogspot.com/2010/07/why-many-profilers-have-serious.html

Это также указывает на то, что Oracle Solaris Studio может использоваться для получения таких смешанных дампов потоков Native/Java.

person Vadzim    schedule 29.12.2012

arrow_upward
1
arrow_downward

Попробуйте jmap -histo:live с течением времени, вы можете сравнить вывод, посмотреть, какие типы объектов растут.

Вам необходимо установить JDK для jmap. http://docs.oracle.com/javase/6/docs/technotes/tools/share/jmap.html

Предупреждение, jmap является интенсивным, он приостанавливает все потоки во время работы, что должно длиться всего несколько секунд. Процессы могут создавать дамп ядра, потому что это интенсивно, обычно это быстро и безопасно, но я видел, как он блокирует или убивает большие приложения, многогигабайтные кучи.

person KaizenSoze    schedule 30.12.2011

arrow_upward
0
arrow_downward

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

Если вы хотите посмотреть, на что ваш сервер тратит свое время, я бы попробовал профилировщик, такой как VisualVM, или коммерческий профилировщик, такой как YourKit.

Выполняя поиск вашего кода в Google, я нашел другую версию http://grepcode.com/file/repo1.maven.org/maven2/org.mortbay.jetty/jetty-util/7.0.0.pre5/org/mortbay/thread/QueuedThreadPool.java однако я подозреваю, что ваши потоки TIMED_WAIT в этом блоке в методе run()

                // We are idle
                // wait for a dispatched job
                synchronized (this)
                {
                    if (_job==null)
                        this.wait(getMaxIdleTimeMs());
                    job=_job;
                    _job=null;
                }
person Peter Lawrey    schedule 07.12.2011