Спецификации окружающей среды
- Сервер Java EE: Oracle Service Bus 11g
- ОС: AIX 6.1
- JDK: IBM JRE 1.6.0 @ 64-bit
- СУБД: Oracle 10g
- Тип платформы: Enterprise Service Bus
Инструменты для устранения неполадок
- Quest Software Foglight для Java (мониторинг и оповещение)
- Дамп потока Java VM (формат javacore IBM JRE)
Обзор проблемы
Значительное снижение производительности наблюдалось в нашей среде Oracle Service Bus Weblogic. Также были отправлены оповещения от агентов Foglight, указывающие на значительный рост использования потоков Weblogic.
Сбор и проверка фактов
Как обычно, исследование проблемы Java EE требует сбора технических и нетехнических фактов, чтобы мы могли либо получить другие факты и / или сделать вывод о первопричине. Перед применением корректирующих мер факты, приведенные ниже, были проверены, чтобы сделать вывод о первопричине:
- Какое влияние оказывает клиент? ВЫСОКИЙ
- Недавнее изменение затронутой платформы? Да, в журнале OSB изменен уровень ведения журнала для нескольких бизнес-сервисов до отчета о сбое
- Недавнее увеличение трафика на уязвимую платформу? нет
- С каких пор эта проблема наблюдается? Новая проблема наблюдается после изменений уровня регистрации
- Решил ли перезапуск сервера Weblogic проблему? да
Заключение № 1 : Изменения уровня ведения журнала, примененные ранее в некоторых бизнес-сервисах OSB, по-видимому, вызвали проблему с застрявшим потоком. Тем не менее, коренная причина остается неизвестной на данный момент.
Мониторинг потоков Weblogic: Foglight для Java
Foglight for Java (от Quest Software) — это отличный инструмент мониторинга, позволяющий вам полностью контролировать любую среду Java EE вместе с полными возможностями оповещения. Этот инструмент используется в нашей производственной среде для мониторинга данных промежуточного программного обеспечения (Weblogic), включая потоки, для каждого из управляемых серверов Oracle Service Bus. Ниже вы можете видеть последовательное увеличение потоков вместе с очередью ожидающих запросов.
Для справки, медленные потоки Weblogic идентифицируются как «Hogging Threads» и могут в конечном итоге быть переведены в состояние «STUCK», если они работают в течение нескольких минут (согласно настроенному вами порогу).
Теперь, каким должен быть ваш следующий курс действий? Перезапуск Weblogic? Определенно нет … Ваш первый «рефлекс» для такого рода проблем — захват дампа потока JVM. Такие данные очень важны для правильного анализа первопричин и понимания потенциального зависания. После сбора таких данных вы можете приступить к действиям по восстановлению сервера Weblogic, таким как перезапуск полного управляемого сервера (JVM).
Застрял Темы: Нить Дамп на помощь!
Следующим действием в этом сценарии сбоя было быстрое создание нескольких моментальных снимков дампов потока из JVM IBM перед попыткой восстановления уязвимых экземпляров Weblogic. Дамп потока был создан с помощью kill -3 <Java PID>, который сгенерировал несколько файлов javacore в корне домена Weblogic.
|
1
|
javacore.20120610.122028.15149052.0001.txt |
Как только производственная среда была запущена и запущена, команда быстро приступила к анализу файлов захваченных дампов потоков, как описано ниже.
Шаг # 1 анализа дампа потока — определить шаблон выполнения потока
Первым этапом анализа является быстрое прохождение всех потоков Weblogic и попытка определить общий проблемный шаблон, такой как потоки, ожидающие от удаленных внешних систем, потоки в состоянии взаимоблокировки, потоки, ожидающие от других потоков для выполнения своих задач и т. Д.
Анализ быстро выявил множество потоков, вовлеченных в ту же ситуацию блокировки, что и ниже. В этом примере мы видим поток Oracle Service Bus в заблокированном состоянии в классе Java TransactionManager (код ядра OSB).
|
01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
|
[ACTIVE] ExecuteThread: '292' for queue: 'weblogic.kernel.Default (self-tuning)'" J9VMThread:0x0000000139B76B00, j9thread_t:0x000000013971C9A0, java/lang/Thread:0x07000000F9D80630, state:B, prio=5 (native thread ID:0x2C700D1, native priority:0x5, native policy:UNKNOWN) Java callstack: at com/bea/wli/config/transaction/TransactionManager._beginTransaction(TransactionManager.java:547(Compiled Code)) at com/bea/wli/config/transaction/TransactionManager.beginTransaction(TransactionManager.java:409(Compiled Code)) at com/bea/wli/config/derivedcache/DerivedResourceManager.getDerivedValueInfo(DerivedResourceManager.java:339(Compiled Code)) at com/bea/wli/config/derivedcache/DerivedResourceManager.get(DerivedResourceManager.java:386(Compiled Code)) at com/bea/wli/sb/resources/cache/DefaultDerivedTypeDef.getDerivedValue(DefaultDerivedTypeDef.java:106(Compiled Code)) at com/bea/wli/sb/pipeline/RouterRuntimeCache.getRuntime(RouterRuntimeCache.java(Compiled Code)) at com/bea/wli/sb/pipeline/RouterManager.getRouterRuntime(RouterManager.java:640(Compiled Code)) at com/bea/wli/sb/pipeline/RouterContext.getInstance(RouterContext.java:172(Compiled Code)) at com/bea/wli/sb/pipeline/RouterManager.processMessage(RouterManager.java:579(Compiled Code)) at com/bea/wli/sb/transports/TransportManagerImpl.receiveMessage(TransportManagerImpl.java:375(Compiled Code)) at com/bea/wli/sb/transports/local/LocalMessageContext$1.run(LocalMessageContext.java:179(Compiled Code)) at weblogic/security/acl/internal/AuthenticatedSubject.doAs(AuthenticatedSubject.java:363(Compiled Code)) at weblogic/security/service/SecurityManager.runAs(SecurityManager.java:146(Compiled Code)) at weblogic/security/Security.runAs(Security.java:61(Compiled Code)) at com/bea/wli/sb/transports/local/LocalMessageContext.send(LocalMessageContext.java:144(Compiled Code)) at com/bea/wli/sb/transports/local/LocalTransportProvider.sendMessageAsync(LocalTransportProvider.java:322(Compiled Code)) at sun/reflect/GeneratedMethodAccessor980.invoke(Bytecode PC:58(Compiled Code)) at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code)) at java/lang/reflect/Method.invoke(Method.java:589(Compiled Code)) at com/bea/wli/sb/transports/Util$1.invoke(Util.java:83(Compiled Code)) at $Proxy111.sendMessageAsync(Bytecode PC:26(Compiled Code))…………………………… |
Анализ дампа потока, шаг № 2 — просмотр цепочки заблокированных потоков
Следующим шагом было рассмотрение цепочки затронутых и заблокированных потоков, включенных в наш идентифицированный шаблон. Как мы видели в части 4 анализа дампа потока, формат дампа потока IBM JVM содержит отдельный раздел, который обеспечивает полную разбивку всех цепочек заблокированных потоков, например, блокировок пула монитора объектов Java.
Быстрый анализ выявил следующего виновника потока, как показано ниже. Как вы можете видеть, поток 16 Weblogic является фактическим преступником с 300+ потоками, ожидающими блокировки на мониторе общего объекта TransactionManager @ 0x0700000001A51610 / 0x0700000001A51628.
|
01
02
03
04
05
06
07
08
09
10
|
2LKMONINUSE sys_mon_t:0x000000012CCE2688 infl_mon_t: 0x000000012CCE26C8:3LKMONOBJECT com/bea/wli/config/transaction/TransactionManager@0x0700000001A51610/0x0700000001A51628: Flat locked by "[ACTIVE] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000012CA3C800), entry count 13LKWAITERQ Waiting to enter:3LKWAITER "[STUCK] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000011C785C00)3LKWAITER "[STUCK] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000011CA93200)3LKWAITER "[STUCK] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000011B3F2B00)3LKWAITER "[STUCK] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000011619B300)3LKWAITER "[STUCK] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000012CBE8000)3LKWAITER "[STUCK] ExecuteThread: '21' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000012BE91200).................. |
Шаг № 3 — анализ дампа нити — более глубокий анализ виновника нити
Как только вы определите основной поток преступника, следующим шагом будет выполнение более глубокого анализа вычислительной задачи, которую этот поток выполняет в настоящее время. Просто вернитесь к исходным данным дампа потока и начните анализировать след стека преступника снизу вверх.
Как вы можете видеть ниже, трассировка стека потоков для нашего проблемного случая была довольно показательной. Это действительно показало, что поток № 16 в настоящее время пытается зафиксировать изменения, сделанные на уровне Weblogic / Oracle Service Bus. Проблема заключается в том, что операция фиксации зависает и занимает слишком много времени, в результате чего поток № 16 слишком долго сохраняет блокировку монитора общих объектов из TransactionManager и «истощает» другие потоки Oracle Service Bus Weblogic.
|
01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
|
"[ACTIVE] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)'"J9VMThread:0x000000012CA3C800, j9thread_t:0x000000012C9F0F40, java/lang/Thread:0x0700000026FCE120, state:P, prio=5(native thread ID:0x35B0097, native priority:0x5, native policy:UNKNOWN) Java callstack: at sun/misc/Unsafe.park(Native Method) at java/util/concurrent/locks/LockSupport.park(LockSupport.java:184(Compiled Code)) at java/util/concurrent/locks/AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:822) at java/util/concurrent/locks/AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:853(Compiled Code)) at java/util/concurrent/locks/AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1189(Compiled Code)) at java/util/concurrent/locks/ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:911(Compiled Code)) at com/bea/wli/config/derivedcache/DerivedCache$Purger.changesCommitted(DerivedCache.java:80) at com/bea/wli/config/impl/ResourceListenerNotifier.afterEnd(ResourceListenerNotifier.java:120) at com/bea/wli/config/transaction/TransactionListenerWrapper.afterEnd(TransactionListenerWrapper.java:90) at com/bea/wli/config/transaction/TransactionManager.notifyAfterEnd(TransactionManager.java:1154(Compiled Code)) at com/bea/wli/config/transaction/TransactionManager.commit(TransactionManager.java:1519(Compiled Code)) at com/bea/wli/config/transaction/TransactionManager._endTransaction(TransactionManager.java:842(Compiled Code)) at com/bea/wli/config/transaction/TransactionManager.endTransaction(TransactionManager.java:783(Compiled Code)) at com/bea/wli/config/deployment/server/ServerDeploymentReceiver$2.run(ServerDeploymentReceiver.java:275) at weblogic/security/acl/internal/AuthenticatedSubject.doAs(AuthenticatedSubject.java:321(Compiled Code)) at weblogic/security/service/SecurityManager.runAs(SecurityManager.java:120(Compiled Code)) at com/bea/wli/config/deployment/server/ServerDeploymentReceiver.commit(ServerDeploymentReceiver.java:260) at weblogic/deploy/service/internal/targetserver/DeploymentReceiverCallbackDeliverer.doCommitCallback(DeploymentReceiverCallbackDeliverer.java:195) at weblogic/deploy/service/internal/targetserver/DeploymentReceiverCallbackDeliverer.access$100(DeploymentReceiverCallbackDeliverer.java:13) at weblogic/deploy/service/internal/targetserver/DeploymentReceiverCallbackDeliverer$2.run(DeploymentReceiverCallbackDeliverer.java:68) at weblogic/work/SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:528(Compiled Code)) at weblogic/work/ExecuteThread.execute(ExecuteThread.java:203(Compiled Code)) at weblogic/work/ExecuteThread.run(ExecuteThread.java:171(Compiled Code)) |
Основная причина: соединение точек
На этом этапе сбор фактов и анализ дампа потоков позволил нам определить цепочку событий, как показано ниже:
- Изменение уровня ведения журнала, примененное администратором производственной Oracle Service Bus
- Потоку развертывания Weblogic № 16 не удалось правильно зафиксировать изменение
- Потоки среды выполнения Weblogic, выполняющие клиентские запросы, быстро начали стоять в очереди и ожидать блокировки на мониторе общего объекта (TransactionManager)
- В экземплярах Weblogic закончились потоки, генерирующие предупреждения и вынуждающие производственную службу поддержки завершить работу и перезапустить затронутые процессы JVM
Наша команда планирует в ближайшее время открыть Oracle SR, чтобы поделиться этим поведением развертывания OSB наряду с жесткой зависимостью между клиентскими запросами (потоками) и уровнем ведения журнала OSB. В то же время не будет предприниматься никаких попыток изменения уровня ведения журнала OSB за период периода обслуживания до дальнейшего уведомления.
Вывод
Я надеюсь, что эта статья помогла вам понять и оценить, насколько мощным может быть анализ дампа потоков, чтобы точно определить основную причину проблем с застрявшими потоками и важность для любой рабочей группы поддержки Java EE сбора таких важных данных, чтобы предотвратить повторные появления в будущем.
Пожалуйста, не стесняйтесь оставлять комментарии или вопросы.
Ссылка: Oracle Service Bus — пример использования застрявшего потока от нашего партнера JCG Пьера-Хьюга Шарбонно в блоге, посвященном шаблонам поддержки Java EE и руководству по Java .