Предыстория: После завершения разработки и тестирования новой функции она готова к выпуску и запуску.При выпуске третьей машины мониторинг показывает, что ЦП одной из машин резко взлетел до 300%, а количество количество активных потоков Dubbo сразу взлетело до 1000+, поэтому выпуск пришлось остановить.Немедленно откатил машину с проблемой, и после отката пришел в норму;продолжил наблюдать за двумя другими выпущенными машинами. конец, ни один из них не был пощажен, и все они должны были быть отброшены.
Вот мой процесс устранения неполадок:
Анализ журнала мониторинга
Во-первых, проверьте журнал приложения в момент сбоя и обнаружите, что большое количество методов занимает много времени, среди которых метод filterMission особенно важен, занимая до 30+ секунд. Обратите внимание, что filterMission — это интерфейс с высоким QPS в текущем сервисе (в среднем 200 миллионов вызовов в день), поэтому вероятность сбоя также высока. Поэтому я еще раз рассмотрел реализацию filterMission: здесь нет сложной логики расчета, нет логики обработки большого объема данных и нет конфликтов блокировок, это требование не предполагает преобразование filterMission, и исключено, что filterMission вызывает сбои. .
Также из лога можно узнать, что время ожидания большого количества запросов истекло, что может свидетельствовать лишь о том, что система перегружена и не может определить суть проблемы.
Code Review
Я не смог найти причину в журнале приложений, поэтому мне пришлось сделать еще один обзор кода. Во-первых, проверьте, используется ли в системе логика синхронного кода, в основном для исключения возможности взаимоблокировки; проверьте код со сложной логикой работы; заодно сравните модифицированный на этот раз код с предыдущей версией, и найденные ничего, в чем проблема.
Анализ дампа потока
На данный момент я не могу пока проанализировать проблему из журнала, и я не могу найти проблему, глядя в код вслепую. Теперь я могу перевыпустить только одну машину. Когда возникает проблема, пусть операция и обслуживание выгружают стек потоков приложения и анализируют файл jstack. Прежде чем приступить к анализу файла дампа, давайте закрепим основу.
состояние потока
Описание каждого состояния на рисунке:
New: новое состояние, состояние, существовавшее при создании объекта потока;
Runnable: состояние готовности к выполнению, работоспособность, после вызова thread.start() поток переходит в состояние Runnable, и для запуска ему необходимо получить ЦП;
Running: выполняется, когда вызывается Thread.yield() или выполняется квант времени, ЦП будет перепланирован; Примечание: после вызова Thread.yield() поток освобождает ЦП, но перераспределение ЦП может позволить потоку чтобы восстановить временной отрезок.
Waiting: Потоки, вызывающие thread.join(), object.wait() и LockSupport.park(), войдут в это состояние, указывая на то, что поток ожидает пробуждения ресурса или условия; thread.join(), object.wait ( ) для пробуждения требует notify()/notifyAll() или прерывание объекта, а LockSupport.park() требует для пробуждения LockSupport.unpark() Эти методы переводят поток в состояние Runnable и участвуют в планировании ЦП.
thread.join(): функция должна дождаться завершения потока, и основной поток продолжит выполнение вниз только после завершения выполнения потока; из реализации join() мы можем видеть, что только когда thread.isAlive() возвращает true, будет возражать. он пробуждается в состоянии ожидания, thread.isAlive() будет оцениваться снова. ), если true, продолжайте вызывать object.wait(), чтобы войти в состояние ожидания, пока поток не завершится, а thread.isAlive() не вернет false.
object.wait(): Функция состоит в том, чтобы заставить поток войти в состояние ожидания. Только поток, удерживающий блокировку объекта, может вызвать ожидание () объекта. После того, как поток войдет в состояние ожидания, он снимет блокировку на объекте, который он удерживает, но по-прежнему будет удерживать блокировки на других объектах. Если другие потоки хотят вызвать notify(), notifyAll(), чтобы разбудить поток, им также необходимо удерживать блокировку объекта.
LockSupport.park(): приостановить текущий поток и не участвовать в планировании потока, пока не будет вызвана функция LockSupport.unpark() для повторного участия в планировании.
Timed_Waiting: Вызов Thread.sleep(long), LockSupport.parkNanos(long), thread.join(long) или obj.wait(long) приведет к переходу потока в это состояние. ожидающий;
Thread.sleep(): остановить выполнение текущего потока на указанное количество миллисекунд, и поток не будет освобождать ресурсы, такие как блокировки, которые он удерживает.
Blocked: относится к потоку, ожидающему получения блокировки. Когда поток входит в кодовый блок или метод, защищенный синхронизацией, если блокировка не получена, он переходит в это состояние; или если поток ожидает ввода-вывода, он также войдет в это состояние. Обратите внимание, что объект Lock в java не приводит к переходу потока в это состояние.
Dead: после того, как поток будет выполнен или возникнет неперехваченное исключение, он перейдет в мертвое состояние, указывая на то, что поток завершен.
Некоторые состояния на приведенном выше рисунке приведены только для удобства объяснения и на самом деле не существуют, например, работающий/спящий.Значения состояния потока, четко определенные в java, следующие:
НОВЫЙ, РАБОТАЕТ, ЗАБЛОКИРОВАН, ОЖИДАНИЕ, TIMED_WAITING, TERMINATED
Анализ журналов jstack
- Большое количество потоков dubbo находится в состоянии WAITING, см. лог:
"DubboServerHandler-172.24.16.78:33180-thread-1220" #1700 daemon prio=5 os_prio=0 tid=0x00007f3394988800 nid=0x4aae waiting on condition [0x00007f32d75c0000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000866090c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)Из лога видно, что поток "DubboServerHandler-172.24.16.78:33180-thread-1220" находится в состоянии WAITING. Основная причина в том, что поток выбирает задачи из очереди пула потоков для выполнения, но пул потоков и, наконец, вызывается LockSupport.park, чтобы заставить поток перейти в состояние ожидания и дождаться уведомления о том, что очередь не пуста.
Представьте, когда будет создан новый поток для обработки запроса? В сочетании с реализацией пула потоков jdk при поступлении нового запроса, если количество потоков в пуле не достигает corePoolSize, пул потоков напрямую создает новый поток для обработки запроса.
Согласно журналу jstack, существует 195 потоков dubbo, извлекающих задачи из ScheduledThreadPoolExecutor и находящихся в состоянии WAITING. Логически эти потоки dubbo отвечают только за обработку клиентских запросов, а не за планирование задач. Почему они получают задачи из потока задач планирования? Давайте временно закинем этот вопрос сюда, я не знаю ответа, надеюсь, кто-то может помочь.
- Другая часть потока находится в состоянии WAITING, см. лог:
"DubboServerHandler-172.24.16.78:33180-thread-1489" #1636 daemon prio=5 os_prio=0 tid=0x00007f33b0122800 nid=0x48ec waiting on condition [0x00007f32db600000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000089d717a8> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
at java.util.concurrent.SynchronousQueue.take(SynchronousQueue.java:924)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Эта часть dubbo-потока в основном приостанавливается (309 потоков) при получении задач из ThreadPoolExecutor для выполнения.После того, как эти потоки нормально обработают первый запрос, они вернутся в пул потоков для ожидания новых запросов. Поскольку newFixedThreadPool используется здесь в качестве пула обработки запросов dubbo, каждый новый запрос будет создавать новый поток для обработки по умолчанию, если только не будет достигнуто предельное значение пула. Только когда будет достигнуто максимальное количество потоков в пуле потоков, новые запросы будут добавлены в очередь задач, а те потоки, которые были заблокированы в getTask(), будут использованы повторно.
- Кроме того, большое количество dubbo-потоков находится в состоянии BLOCKED, см. лог:
"DubboServerHandler-172.24.16.78:33180-thread-236" #1727 daemon prio=5 os_prio=0 tid=0x00007f336403b000 nid=0x4b8b waiting for monitor entry [0x00007f32d58a4000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:149)
- waiting to lock <0x0000000085057998> (a org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:88)
at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:349)
at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1993)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1852)
at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:179)
at com.alibaba.dubbo.common.logger.slf4j.Slf4jLogger.info(Slf4jLogger.java:42)
at com.alibaba.dubbo.common.logger.support.FailsafeLogger.info(FailsafeLogger.java:93)
at com.dianwoba.universe.dubbo.filter.ResponseFilter$1.run(ResponseFilter.java:116)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)waiting for monitor entry : указывает, что текущий поток находится в очереди EntryList, ожидая получения блокировки монитора.
Примечание. Семантика синхронизации для синхронизированного в Java в основном основана на заголовке объекта Java и реализации монитора. Каждый монитор может принадлежать только одному потоку за раз, а другие могут только ждать, чтобы получить монитор. Монитор имеет две очереди: Набор ожидания и список записей. Когда поток имеет монитор и вызывает Object.wait(), он освобождает монитор и входит в очередь WaitSet для ожидания Когда другие потоки вызывают notify()/notifyAll() объекта, чтобы разбудить поток, они будут конкурировать за монитор снова. , состояние потока в это время WAITING, а состояние ожидания в WaitSet равно "in Object.wait()"; когда поток пытается войти в синхронизированный блок кода или метод, он войдет в очередь EntryList, если ему не удастся получить монитор. В это время состояние потока БЛОКИРОВАНО, а состояние ожидания в EntryList есть "ожидание записи монитора".
Согласно журналу jstack, 377 потоков dubbo ожидают блокировки ресурса "0x0000000085057998". Из стека видно, что эти потоки конкурируют за монитор RollingRandomAccessFileManager. Посмотрим, какой поток владеет монитором и посмотрим лог:
"DubboServerHandler-172.24.16.78:33180-thread-429" #553 daemon prio=5 os_prio=0 tid=0x00007f339c09f800 nid=0x4467 waiting for monitor entry [0x00007f331f53a000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:149)
- locked <0x0000000085057998> (a org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:88)
at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:381)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:376)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:349)
at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1993)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1852)
at org.apache.logging.slf4j.Log4jLogger.warn(Log4jLogger.java:239)
at com.alibaba.dubbo.common.logger.slf4j.Slf4jLogger.warn(Slf4jLogger.java:54)
at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:107)
at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:48)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:60)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:112)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:108)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170)
at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52)
at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)Когда я увидел стек потока, я был ошеломлен.Он заблокировал ресурс «0x0000000085057998», но он все еще находится в состоянии BLOCKED.Это пахнет тупиком? Но это не тупик, наиболее вероятная причина:
- Поток не получил ресурсов, необходимых для работы;
- JVM выполняет полный GC
Из этой части лога видно, что большинство потоков блокируются в процессе печати лога мониторинга, поэтому многие запросы истекают по таймауту. Основная причина заключается в том, что уровень загрузки ЦП высок, а поток, удерживающий процесс блокировки, очень медленный, в результате чего все больше и больше потоков блокируется в соревновании за блокировку, а общая производительность снижается.
На данный момент я так и не нашел причину проблемы.Я снова наблюдал за занятостью ресурсов и обнаружил, что при возникновении проблемы занятость памяти продолжает увеличиваться, и нет никаких следов снижения.Тогда я обнаружил операцию и обслуживание для создания дампа журнала сборщика мусора и обнаружил, что JVM выполняет полный сборщик мусора, и память в основном не изменяется после каждого сбора мусора, что указывает на то, что в программе произошла утечка памяти. Наконец, место, где произошла утечка памяти, — это интерфейс запроса на подкачку.Ограничение и смещение опущены в операторе SQL, что достаточно для первоначального намерения.
Эта Нима проверяла данные всей таблицы за один раз (3 миллиона), а также обрабатывала 3 миллиона записей в цикле.Было бы странно, если бы память не взорвалась. Именно по этой причине память долго не освобождается, и JVM не может высвободить память, выполнив fullGC, в результате fullGC продолжает выполняться, ЦП исчерпан, и запрос приложения не может быть обработанный.
Подводя итог, можно сказать, что виновником является утечка памяти, которая приводит к резкому скачку загрузки ЦП, увеличению количества активных потоков Dubbo, серьезной конкуренции блокировок и тайм-ауту обработки запросов. Согласно вышеприведенному анализу также выявляется еще одна необоснованная проблема: количество пулов потоков dubbo настроено слишком большим, а максимальное значение равно 1500, что означает, что в конечном пуле потоков будет 1500 потоков для обработки запросов пользователей. параллелизм высок, количество активных потоков увеличивается, ЦП часто выполняет переключение контекста, а пропускная способность системы не слишком высока. Это точка оптимизации.
В этой статье описывается процесс, с одной стороны, для записи ям, на которые наступили, и в то же время для улучшения собственного анализа неисправностей и возможностей обработки. Когда вам нужна проблема, вы не должны беспокоиться, научитесь анализировать проблему и находить проблему шаг за шагом. Особенно при столкновении с онлайн-проблемами из-за невозможности отладки ее необходимо отслеживать в приложении.При возникновении проблемы ее необходимо анализировать в сочетании с журналом.Проблема в бизнесе объединяется с бизнес-журналом, а проблема производительности сочетается с журналом дампа памяти и журналом дампа потока и т. д.
Приветствуется указание на ошибки в данной статье, просьба указывать источник оригинального текста при перепечаткеmy.oschina.net/7001/blog