Некоторые из способов раскрыть преступление, предложенные Холмсом, вдохновили меня на устранение неполадок. Сбои Java-приложений могут быть болезненными в тех случаях, когда наше приложение не оставляет достаточно следов, чтобы помочь нам разгадать тайну. В следующих нескольких параграфах я поделюсь своим опытом о том, как наша диагностика была проделана шаг за шагом.
Вам также может понравиться: Устранение неполадок приложений Java с Arthas
Я недавно присоединился к проекту, который работает уже несколько лет. Я расскажу некоторые факты о проекте, прежде чем углубляться в проблему.
- Эта система имела API, который принимает различные виды запросов от POS-устройств.
- Пока он обрабатывает запросы, он отправляет некоторые запросы сторонним системам.
- Он имел систему баз данных для хранения продукта и информации о заказе.
- В последнее время мы включили в систему еще несколько предприятий, поэтому мы получили больше трафика в систему.
- Несмотря на то, что система выделяет так много функциональных возможностей, она еще не была настроена на производительность.
1) Тайна случается, и она не оставляет никакой подсказки
В одно прекрасное утро наша система не смогла ответить ни на один из запросов API, и мы получили жалобы от клиентов. Затем нам пришлось перезапустить систему, чтобы восстановить систему в нормальное состояние. У нас не было много следов, чтобы понять, почему система перешла в такое странное состояние. Мы получили только несколько следов, которых было недостаточно для определения причины. Теперь у нас есть тайна в наших руках, но нет никаких доказательств, чтобы привести нас.
Мы смогли собрать следующую информацию во время инцидента.
- Медленный журнал запросов нашей базы данных MySQL .
У него было несколько медленных журналов запросов, которые были только там во время инцидента. Но мы были смущены, почему эти медленные запросы не присутствовали в другие времена. В дальнейшем наш инцидент не был временем пикового трафика. Мы были озадачены тем, почему наша система перестала работать в обычное время движения.
- Мы получили журналы использования ЦП , которые показали, что наше java-приложение занимало почти 100% ЦП более 20 минут.
Это показало, что наши темы были заняты во время выпуска. Но мы не могли определить, чем занята система.
- Журналы запросов приложений были просмотрены много раз, но не повезло.
Мы не смогли определить причину с помощью вышеуказанной ограниченной информации. Поэтому мы сосредоточились на поиске решения с помощью догадок. Мы думали увеличить память кучи.
2) Ловушка
В любом случае, мы планировали подождать, пока проблема не возникнет в следующий раз, чтобы собрать дополнительные доказательства. Поэтому мы планировали установить ловушку, чтобы захватить больше деталей. Jdk предлагает несколько инструментов, которые очень удобны для выявления подобных загадок.
1) Jstack — этот инструмент помогает нам принять threaddump. Threaddumps даст четкое представление о состоянии потока вместе со связанной трассировкой стека в данный момент времени.
Поскольку наше Java-приложение занимало почти 100% процессорного времени, нам было интересно узнать, что делали наши потоки в то время. Обычно целесообразно брать 3-4 таких дутпа с интервалом в 5 секунд. Важно, чтобы принять threaddump, когда система испытывает проблему.
2) Jmap — histo — это дает снимок памяти с гистограммой объекта, который дает число объектов, созданных в куче. Если в нашей системе есть утечки памяти, эта гистограмма может легко указать на виновника.
Так мы устроили ловушку для нашего неизвестного злодея.
3) Злодей снова посещает, поэтому инцидент повторяется
Снова возникла та же проблема, и на этот раз нам дали короткий срок для сбора следов. Поэтому они взяли одну threaddump и одну jmap-histo перед перезагрузкой системы. Мы подготовили сводку состояний потоков, используя вечнозеленые команды оболочки Linux. Сводка команд оболочки показала, что треть потоков приложений застряла при попытке поместить свои входящие команды в очередь запросов.
4) Время исследовать доказательства
Я покажу, как я обработал поток-дамп.
О. Сначала я искал наши местные ссылки на названия пакетов. Наш местный пакет начинается с «com.gotham»
Оболочка
xxxxxxxxxx
1
cat threaddumps.log | grep 'com.gotham'
Мальчик, в нашем коде застряло довольно много потоков. Наш код делает нашу систему занятой.
Б. Позже я хотел найти наиболее популярные строки кода, в которых застряли большинство потоков. Здесь удобна команда uniq.
Оболочка
xxxxxxxxxx
1
cat threaddumps.log | grep 'com.gotham' | sort | uniq -c
Это фрагмент вывода вышеприведенной команды. Первый столбец показывает количество появлений определенной строки, которая указана во втором столбце. Я всегда люблю команду «uniq», чтобы суммировать с подсчетами.
Оболочка
xxxxxxxxxx
1
2 at com.gotham.product.sync.services.ProductSyncService.syncProducts(ProductSyncService.java:375)
2
2 at com.gotham.services.resources.BusinessManagementApiResource$$FastClassBySpringCGLIB$$4c765361.invoke(<generated>)
4
3 at com.gotham.product.sync.services.ProductSyncService$$Lambda$280/204181735.run(Unknown Source)
6
3 at com.gotham.product.sync.services.ProductSyncService.lambda$syncCatalog$2(ProductSyncService.java:137)
8
3 at com.gotham.persistence.util.SessionWrapperUtil.wrapWithSession(SessionWrapperUtil.java:78)
10
4 at com.gotham.execution.engine.delegation.BusinessServiceDelegation.purchaseHistory(BusinessServiceDelegation.java:98)
12
4 at com.gotham.persistence.dao.impl.DefaultPurchaseHistoryDAO.find(DefaultPurchaseHistoryDAO.java:244)
14
4 at com.gotham.services.base.DefaultBusinessService.purchaseHistory(DefaultBusinessService.java:1043)
16
4 at com.gotham.services.resources.MerchantPurchaseManagementApiResource$$EnhancerBySpringCGLIB$$eaa39579.getPurchaseHistory(<generated>)
18
4 at com.gotham.services.resources.MerchantPurchaseManagementApiResource$$FastClassBySpringCGLIB$$332aefd8.invoke(<generated>)
20
4 at com.gotham.services.resources.MerchantPurchaseManagementApiResource.getPurchaseHistory(MerchantPurchaseManagementApiResource.java:84)
22
5 at com.gotham.services.aspect.PostPurchaseAction.performPaymentComplete(PostPurchaseAction.java:149)
24
86 at com.gotham.services.aspect.PostPurchaseAction.purchaseOrderCompleteAction(PostPurchaseAction.java:101)
26
86 at com.gotham.services.resources.KioskConsumerApiResource$$EnhancerBySpringCGLIB$$20806517.purchase(<generated>)
28
91 at com.gotham.messaging.handler.DefaultMessageEventProcessor.merchantMessage(DefaultMessageEventProcessor.java:196)
30
91 at com.gotham.services.aspect.PostPurchaseAction.sendMerchantMessage(PostPurchaseAction.java:162)
Мои команды оболочки говорят, что большинство потоков застряло в строке, показанной ниже.
Оболочка
xxxxxxxxxx
1
com.gotham.services.aspect.PostPurchaseAction.sendMerchantMessage(PostPurchaseAction.java:162)
Наконец-то нашел место для начала. Поэтому я проверил соответствующую кодовую базу, чтобы понять, что делает наш код в этой конкретной строке.
C. Когда я прочитаю полную трассировку стека, с которой связана строка выше. Я обнаружил, что 91 поток ждет, чтобы поместить свои запросы в очередь, которая, возможно, была заполнена в это конкретное время.
D. Я пошел в базу кода и выяснил причины переполнения очереди и выяснил, что мы используем очередь и пытаемся отправить некоторые уведомления в push-уведомления Apple. Несмотря на то, что это был асинхронный вызов, мы ожидали объекта Future, чтобы просто зарегистрировать состояние этой операции отправки уведомлений.
К сожалению, один поток-очередь-клиент застрял в ожидании ответа на неопределенный срок (это было видно в потоке потока). Возможно, он потерял ответ из-за потери пакета. К сожалению, у нас был только один поток очереди-потребителя. Ниже приведена трассировка стека потока-потребителя очереди из threaddump.
Оболочка
xxxxxxxxxx
1
at io.netty.util.concurrent.DefaultPromise.await(DefaultPromise.java:33)
2
at io.netty.util.concurrent.AbstractFuture.get(AbstractFuture.java:32)
3
at com.gotham.messaging.DefaultApnClient.lambda$sendMessage$0(DefaultApnClient.java:94)
Потери пакетов могут произойти в любое время в любой сети. Возможно, мы, к сожалению, попали в такую ситуацию.
Реконструкция места преступления.
Несмотря на то, что вышеперечисленные вещи были получены, мы должны воспроизвести тот же сценарий, чтобы доказать, что он намного сильнее. Таким образом, мы внедрили искусственное ожидание в потоке очереди, чтобы увидеть, происходит ли такая же ситуация. Затем загрузка ЦП начала увеличиваться, когда мы начали отправлять больше запросов в нашу систему. Итак, наш злодейский кодекс раскрыт, и теперь пришло время уничтожить злодея.
Мы удалили эту ненужную нить-ожидание и после этого жили счастливо :).
Конец близок ...
В этой ситуации мы не смогли разгадать тайну, проанализировав существующие следы. Таким образом, мы были готовы собрать больше информации в виде threaddump и jmap-histo. К счастью, threaddump было вполне достаточно, чтобы разгадать тайну.
Threaddump всегда является подходящим оружием для анализа Java-приложений, когда оно перестает отвечать на запросы. Команды оболочки действительно эффективны для анализа и понимания сути проблемы. Поэтому всегда полезно их изучать.
Дальнейшее чтение
Как решить проблемы с производительностью Java (часть 1)
Методический подход к устранению проблем облачных API-интерфейсов
Борьба с проблемами производительности Java в производственных системах