Производительность микросервиса Spring Boot падает на 90%! Найдите первопричину с помощью Артаса

открытый источник облачный носитель

头图.png

Автор | Ван Жусянь, инженер-исследователь, руководитель отдела образовательной инфраструктуры источник|Официальная учетная запись Alibaba Cloud Native

задний план

После получения отзыва о разработке от бизнес-отдела компании, после того как приложение было обновлено до внутренней структуры компании, стресс-тест производительности интерфейса среды UAT (предварительная версия) не соответствовал стандартам. Отчет о стресс-тесте перед обновлением:

1.png

После обновления отчета измерения давления:

2.png

При той же конфигурации машины (1C4G) пропускная способность упала с 53,9/с до 6,4/с при более высокой загрузке процессора.

А отзывы разработчиков из информации о каналах, запрошенной из системы полного контроля каналов SkyWalking, показывают, что большинство вызовов Feign занимают необычно много времени (390 мс), в то время как фактически вызываемые нижестоящие службы отвечают быстро (3 мс).

3.png

проблема позиционирования

Получив отзыв, я немедленно подал заявку на разрешение соответствующей машины и загрузил Arthas (версия 3.4.3) на соответствующую машину.

Позвольте бизнес-стороне провести испытание под давлением и приступить к поиску проблемы.

1. Запустите команду профилировщика анализа производительности процессора.

[arthas@17962]$ profiler start -d 30 -f /tmp/arthas/1.txt

Подождав 30 секунд, откройте 1.txt, проверьте результаты анализа производительности процессора, и начальная часть выглядит следующим образом:

--- 1630160766 ns (4.24%), 141 samples
  ......
  [14] org.springframework.boot.loader.LaunchedURLClassLoader.definePackageIfNecessary
  [15] org.springframework.boot.loader.LaunchedURLClassLoader.loadClass
  [16] java.lang.ClassLoader.loadClass
  [17] java.lang.Class.forName0
  [18] java.lang.Class.forName
  [19] org.springframework.util.ClassUtils.forName
  [20] org.springframework.http.converter.json.Jackson2ObjectMapperBuilder.registerWellKnownModulesIfAvailable
  [21] org.springframework.http.converter.json.Jackson2ObjectMapperBuilder.configure
  [22] org.springframework.http.converter.json.Jackson2ObjectMapperBuilder.build
  [23] org.springframework.web.servlet.config.annotation.WebMvcConfigurationSupport.addDefaultHttpMessageConverters
  [24] org.springframework.web.servlet.config.annotation.WebMvcConfigurationSupport.getMessageConverters
  [25] org.springframework.boot.autoconfigure.http.HttpMessageConverters$1.defaultMessageConverters
  [26] org.springframework.boot.autoconfigure.http.HttpMessageConverters.getDefaultConverters
  [27] org.springframework.boot.autoconfigure.http.HttpMessageConverters.<init>
  [28] org.springframework.boot.autoconfigure.http.HttpMessageConverters.<init>
  [29] org.springframework.boot.autoconfigure.http.HttpMessageConverters.<init>
  [30] com.zhangmen.xxx.DefaultFeignConfig.lambda$feignDecoder$0
  [31] com.zhangmen.xxx.DefaultFeignConfig$$Lambda$704.256909008.getObject
  [32] org.springframework.cloud.openfeign.support.SpringDecoder.decode
  [33] org.springframework.cloud.openfeign.support.ResponseEntityDecoder.decode
 ......

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

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

И обнаружил, что кадр стека, связанный с com.zhangmen, появляется вокруг кадра стека, связанного с Feign: com.zhangmen.xxx.DefaultFeignConfig$$Lambda704.256909008.getObjectиcom.zhangmen.xxx.DefaultFeignConfig.lambda704.256909008.getObject и com.zhangmen.xxx.DefaultFeignConfig.lambdaFeigndecoder $ 0.

Поиск com.zhangmen.xxx.DefaultFeignConfig в 1.txt обнаружил 340 совпадений, так что считайте это очень подозрительным подходом.

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

[arthas@17962]$ trace com.zhangmen.xxx.DefaultFeignConfig * '#cost>200' -n 3
`---[603.999323ms] com.zhangmen.xxx.DefaultFeignConfig:lambda$feignEncoder$1()
    `---[603.856565ms] org.springframework.boot.autoconfigure.http.HttpMessageConverters:<init>() #42

Выяснилось, что org.springframework.boot.autoconfigure.http.HttpMessageConverters:() отнимает много времени и продолжает отслеживать слой за слоем:

[arthas@17962]$ trace org.springframework.boot.autoconfigure.http.HttpMessageConverters <init> '#cost>200' -n 3
......
[arthas@17962]$ trace org.springframework.http.converter.json.Jackson2ObjectMapperBuilder registerWellKnownModulesIfAvailable '#cost>200' -n 3

4.png

Наконец обнаружил, что org.springframework.util.ClassUtils:forName() отнимает много времени и выдает исключение.

Используйте команду watch для просмотра определенных исключений:

[arthas@17962]$ watch org.springframework.util.ClassUtils forName -e "throwExp" -n

5.png

Решать проблему

Сообщите о выявленных проблемах соответствующему развитию бизнеса и предложите ввести зависимость jackson-datatype-joda.

После введения зависимости отчет стресс-теста:

6.png

Пропускная способность была увеличена с исходных 6,4/с до 69,3/с, что выше, чем 53,9/с до обновления платформы.

В настоящее время, согласно отзывам о развитии бизнеса, эта проблема вызвана пользовательским кодеком Feign (как показано на рисунке ниже) в коде, и этот кодек всегда существовал до обновления платформы.

7.png

Поэтому перед обновлением фреймворка выполните стресс-тест кода и используйте Arthas для выполнения следующих команд во время стресс-теста:

8.png

Нашел такое же исключение. Введите зависимость jackson-datatype-joda и снова выполните тест под давлением.Отчет о тесте под давлением выглядит следующим образом:

9.png

Подведем итоги предыдущего стресс-теста:

10.png

Возникает новый вопрос: почему новая и старая версии не вводят зависимости одновременно, и разница в пропускной способности почти в 8 раз, а новая и старая версии вводят зависимости одновременно, а разница в пропускной способности почти в 1 раз?

Для дальнейшего определения проблемы

В соответствии с новыми проблемами, обнаруженными на предыдущем шаге, следующим шагом будет выполнение стресс-тестов на версии, в которой не был обновлен фреймворк и введены зависимости, и версии, которая была обновлена ​​и введены зависимости. Команда Arthas используется для выборки данных анализа производительности процессора.Получить выборку 1 и выборку 2. И находим аналогичные стеки из выборки 1 и выборки 2 для сравнения:

11.png

При сравнении можно обнаружить, что первые 17 строк одинаковых стеков двух выборок отличаются. И проследите подозрительный кадр стека в примере 2:

[arthas@10561]$ trace org.apache.catalina.loader.WebappClassLoaderBase$CombinedEnumeration * '#cost>100' -n 3
`---[171.744137ms] org.apache.catalina.loader.WebappClassLoaderBase$CombinedEnumeration:hasMoreElements()
    `---[171.736943ms] org.apache.catalina.loader.WebappClassLoaderBase$CombinedEnumeration:inc() #2685
        `---[171.724546ms] org.apache.catalina.loader.WebappClassLoaderBase$CombinedEnumeration:inc()

Обнаружено, что после обновления фреймворка в загрузчике классов возникает ситуация, требующая много времени.

Однако трассировка этой части в образце 1 не занимает более 100 мс.

Далее используйте команду профилировщика, чтобы сгенерировать графики пламени двух версий в сценарии стресс-теста и найти похожие стеки для сравнения:

[arthas@10561]$ profiler start -d 30 -f /tmp/arthas/1.svg

12.png

Было обнаружено, что версия обновления фреймворка и введения зависимостей также добавила некоторые стеки, связанные с org/springframework/boot/loader/.

дальнейшее решение проблемы

Сообщайте о новых выводах для соответствующего развития бизнеса.

Они отметили, что в дополнение к обновлению фреймворка также были внесены коррективы в развертывание войны Spring Boot в jar. От использования автономного военного развертывания Tomcat до использования встроенного в Spring Boot развертывания Tomcat java -jar. Поэтому есть подозрение, что производительность загрузчика классов между двумя методами развертывания различается. Сопутствующее развитие бизнеса. На последнем этапе поиска проблемы, в соответствии с проблемой, которую я первоначально обнаружил, я искал feign com.fasterxml.jackson.datatype.joda.JodaModule в Google и нашел связанную статью.«LoadClass вызывает анализ Caton онлайн-сервиса».

Автор статьи столкнулся с проблемой, в принципе похожей на нашу.

Прочитав эту статью, я отладил часть исходного кода и, наконец, узнал, что основная причина проблемы заключается в следующем: SpringEncoder/SpringDecoder будет вызывать ObjectFactory.getObject()).getConverters() для получения HttpMessageConverters каждый раз, когда он кодирует/декодирует. И реализация ObjectFactory, настроенная в нашем пользовательском DefaultFeignConfig, заключается в создании нового объекта HttpMessageConverters каждый раз.

Конструктор HttpMessageConverters по умолчанию выполнит метод getDefaultConverters для получения коллекции HttpMessageConverter по умолчанию и инициализирует эти HttpMessageConverters по умолчанию. Среди них MappingJackson2HttpMessageConverter (их два, см. рисунок ниже) загрузит com.fasterxml.jackson.datatype.joda.JodaModule и com.fasterxml.jackson.datatype.joda$JodaModule (org.springframework. загрузить класс, он попытается снова загрузить внутренний класс) и сгенерировать исключение ClassNotFoundException, которое в конечном итоге будет проглочено.

А некоторые из HttpMessageConverter, SourceHttpMessageConverter и Jaxb2RootElementHttpMessageConverter по умолчанию, связанные с XML (их по два, см. рисунок ниже), будут выполнять TransformerFactory.newInstance() каждый раз при инициализации, а SPI будет использоваться для сканирования META-INF/под classpath во время выполнения. Каталог services получает конкретную реализацию, и конкретная реализация не получается после каждого сканирования. Наконец, указанный по умолчанию com.sun.org.apache.xalan.internal.xsltc.trax.TransformerFactoryImpl используется в качестве выполнение.

В конце концов, каждый вызов Feign (включая кодирование и декодирование) будет загружать com.fasterxml.jackson.datatype.joda.JodaModule и com.fasterxml.jackson.datatype.joda$JodaModule, которые не находятся в пути к классам, 4 раза (всего 8 раз). , И 8 раз использовать SPI для сканирования каталога META-INF/services под classpath для получения реализации, которую невозможно найти, и после war для jar, производительность загрузчика классов при частом поиске и загрузке ресурсов ухудшается, что в конечном итоге приводит к серьезному влиянию на производительность интерфейса.

Коллекция HttpMessageConverter по умолчанию:

13.png

Ниже приведены некоторые ключевые коды.

org/springframework/boot/autoconfigure/http/HttpMessageConverters.:

14.png

org/springframework/http/converter/json/Jackson2ObjectMapperBuilder.registerWellKnownModulesIfAvailable:

15.png

org/springframework/util.ClassUtils.forName:

16.png

org/springframework/http/converter/xml/SourceHttpMessageConverter:

17.png

javax/xml/transform/FactoryFinder.find:

18.png

В статье также приведены два решения этой проблемы:

первый метод, именно это я изначально предложил ввести зависимость jackson-datatype-joda, чтобы предотвратить повторную загрузку ClassLoader com.fasterxml.jackson.datatype.joda.JodaModule и com.fasterxml.jackson.datatype.joda, которые не находятся в пути к классам каждый раз, когда MappingJackson2HttpMessageConverter по умолчанию инициализируется $JodaModule.

Второй способ, не инициализирует HttpMessageConverter по умолчанию. Поскольку нам нужно использовать только пользовательский FastJsonHttpMessageConverter для выполнения кодирования и декодирования, мы можем полностью избежать выполнения метода getDefaultConverters и повторно инициализировать множество неиспользуемых по умолчанию HttpMessageConverters. Поэтому, когда создается новый объект HttpMessageConverters, вы можете установить для параметра addDefaultConverters значение false.

ObjectFactory<HttpMessageConverters> objectFactory = () -> new HttpMessageConverters(false, new HttpMessageConverter[] { (HttpMessageConverter)fastJsonHttpMessageConverter });

Фактически, мы также можем изменить реализацию ObjectFactory в DefaultFeignConfig, чтобы избежать создания нового объекта HttpMessageConverters каждый раз (повторная инициализация HttpMessageConverters) и добиться дальнейшей оптимизации. Поэтому рекомендуется изменить DefaultFeignConfig на следующий код для соответствующего развития бизнеса:

19.png

После того, как соответствующее развитие бизнеса улучшило DefaultFeignConfig в старой и новой версиях кода и развернуло его в среде FAT (тестовой), я использовал JMeter для имитации стресс-теста в среде FAT на моей собственной машине.

Результаты опрессовки после доработки старой версии:

20.png

Новая версия улучшенных результатов опрессовки:

21.png

Выяснилось, что производительность интерфейса двух версий в основном одинакова.

В среде UAT последний тестер снова выполнил стресс-тест кода после обновления фреймворка и улучшения DefaultFeignConfig.Результаты стресс-теста следующие:

22.png

Пропускная способность увеличилась с 6,4/с, которая изначально была нестандартной, до 160,4/с.

Так почему же настройка war на развертывание jar приводит к снижению производительности загрузчика классов, когда он часто находит и загружает ресурсы?

После некоторого понимания принципа исполняемого файла jar SpringBoot. Есть подозрение, что Spring Boot может начинаться с толстой банки, тем самым расширяя URL-протокол JarFile JDK и настраивая собственный ClassLoader и Hander протокола файла jar, а также реализуя метод загрузки jar в jar и jar в каталог.

Друзья, интересующиеся принципом исполняемого файла jar SpringBoot, могут обратиться к:"Исполняемый jar-пакет".

Основная причина снижения производительности загрузчика классов War2Jar

Чтобы проверить свою догадку, я создал простую демо-версию на своей машине.

В демо есть два сервиса, A и B. И A, и B зарегистрированы в реестре Eureka, и A звонит B через Feign.

Затем используйте Jmeter для тестирования различных сценариев в одной и той же конфигурации и используйте команду профилировщика Arthas для создания графиков пламени в различных сценариях во время стресс-теста.

Результаты испытаний под давлением следующие (-Xms512m -Xmx512m):

23.png

Сравнивая Таблицу 3 и Таблицу 4, мы видим, что после оптимизации кода введение зависимостей мало влияет на пропускную способность.

Из таблиц 3 и 4 видно, что после оптимизации кода пропускная способность трех методов развертывания в основном одинакова, если несуществующие ресурсы редко ищутся и загружаются.

Из таблицы 2 видно, что производительность военного развертывания Tomcat выше, когда SPI часто используется для получения реализаций, которых нет в пути к классам.

Из Таблицы 1 видно, что при частой загрузке несуществующих классов лучше запускать выполнение через JarLauncher после распаковки jar-пакета.

Сравните графики пламени аналогичных стеков ③ и ② в таблице 1:

24.png

Можно обнаружить разницу между ними при загрузке классов в org/springframework/boot/loader/LaunchedURLClassLoader.loadClass.

② Будет выполняться не только java/lang/ClassLoader.loadClass, но и org/springframework/boot/loader/LaunchedURLClassLoader.definePackageIfNecessary.

Просмотрите исходный код org/springframework/boot/loader/LaunchedURLClassLoader.loadClass:

25.png

Найдена условная ветвь.

Ознакомьтесь с исходным кодом org/springframework/boot/loader/Launcher.createArchive:

26.png

Было обнаружено, что значение этого условия связано с тем, является ли приложение исполняемым файлом jar или каталогом файлов.

Снова выполните стресс-тест на ② и отследите org/springframework/boot/loader/LaunchedURLClassLoader.definePackageIfNecessary:

`---[165.770773ms] org.springframework.boot.loader.LaunchedURLClassLoader:definePackageIfNecessary()
    +---[0.00347ms] org.springframework.boot.loader.LaunchedURLClassLoader:getPackage() #197
    `---[165.761244ms] org.springframework.boot.loader.LaunchedURLClassLoader:definePackage() #199

Поиск этого места действительно занимает много времени.

Прочитайте эту часть исходного кода, из комментариев вы можете узнать, что definePackageIfNecessary в основном пытается определить пакет, в котором находится класс, в соответствии с именем класса перед вызовом findClass, чтобы гарантировать, что манифест в файле jar, вложенный в jar-пакет может быть связан с package.

27.png

Отладка definePackageIfNecessary В этой части кода обнаружено, что когда definePackage будет проходить все пакеты jar в BOOT-INF/lib/ и BOOT-INF/classes/. Если указанный класс найден в этих ресурсах, продолжайте вызывать метод definePackage, в противном случае возвращайте значение null сразу после обхода.

28.png

29.png

Как упоминалось ранее, каждый вызов Feign загружает 4 раза com.fasterxml.jackson.datatype.joda.JodaModule и com.fasterxml.jackson.datatype.joda$JodaModule, которые не находятся в пути к классам (всего 8 раз). И мое простое демонстрационное приложение зависит от 117 банок (фактический проект уровня предприятия будет больше). Затем при каждом вызове Feign будет выполняться 8 * (117 + 1), всего 944 логики в цикле. Метод org.springframework.boot.loader.jar.Handler.openConnection в логике будет задействовать трудоемкие операции ввода-вывода в процессе выполнения, что в итоге серьезно скажется на производительности интерфейса. Из сгенерированного графика пламени вы также можете увидеть эту часть логики обработки.

30.png

На данный момент можно подтвердить, что адаптация войны к развертыванию jar привела к снижению производительности загрузчика классов, когда он часто выполняет поиск и загрузку ресурсов: Spring Boot добавляет некоторые настраиваемые функции, позволяющие запускать его с помощью толстого jar. логика, и эта часть настраиваемой логики обработки будет оказывать большее влияние на производительность программы, если она часто выполняется.

Что касается [Почему лучше начинать через JarLauncher после распаковки пакета jar, чем развертывание войны Tomcat при частой загрузке несуществующих классов? ] , [Когда SPI часто используется для получения реализаций, которые не могут быть найдены в пути к классам, военное развертывание Tomcat лучше, чем запуск пакета jar через JarLauncher после его распаковки? ], из-за нехватки места продолжение в этой статье не будет. Заинтересованные друзья могут следовать методам, представленным в этой статье, и комбинировать соответствующий исходный код для дальнейшего изучения.

Суммировать

При настройке кодека Feign, если вы используете SpringEncoder/SpringDecoder, вам следует избегать повторной инициализации HttpMessageConverters. Если вам не нужно использовать эти HttpMessageConverters по умолчанию, вы можете установить для первого параметра значение false при инициализации HttpMessageConverters, чтобы эти HttpMessageConverters по умолчанию не инициализировались.

Кроме того, имейте в виду, что разные методы развертывания имеют разную производительность, когда загрузчик классов часто находит и загружает ресурсы.

Когда мы пишем код, мы также должны избегать повторной инициализации, а также многократного поиска и загрузки несуществующих ресурсов.

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

пасхальные яйца

Если приложение использует агент SkyWalking, а затем использует Arthas, вы можете столкнуться с проблемой, что некоторые команды Arthas (трассировка, просмотр и другие команды, улучшающие классы) не работают должным образом.

решение:GitHub.com/Apache/Просто спросите…

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

Трассировка без * в имени метода:

31.png

Добавьте * к имени метода для трассировки:

32.png

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

Это связано с тем, что агент SkyWalking использует ByteBuddy для улучшения байт-кода. И каждый раз, когда ByteBuddy расширяет метод, он генерирует вспомогательный внутренний класс (HelloController) для этого метода.auxiliaryauxiliaryjiu2bTqU) и переименует исходный метод (test1) в текущем классе (HelloController) (test1).originaloriginallyu0XDob) и сгенерировать метод с тем же именем, что и исходный метод (test1), и метод с другим именем, но только для вспомогательных внутренних вызовов класса (test1)originaloriginallyu0XDobaccessoraccessor8Ф82ИмАФ).

Используйте коллег, разработанныхдекомпилятор JavaСоответствующий код можно увидеть визуально:

33.png

34.png

Кроме того, при использовании Arthas рекомендуется выбирать последнюю версию. Например, в версиях до 3.4.2 может возникнуть ошибка JVM Metaspace OOM, когда трассировка отслеживает большие методы. Подробнее см.:«Помните проблему Metaspace OOM, вызванную Артасом».

Если вы хотите создать платформу онлайн-диагностики корпоративного уровня на основе Arthas, вы можете обратиться кИсследование и практика Промышленно-коммерческого банка для создания онлайн диагностической платформы.

об авторе

Ван Руйсянь, энтузиаст с открытым исходным кодом, в настоящее время возглавляет инженера по исследованиям и разработкам в Департаменте инфраструктуры образования, в основном отвечая за исследования и разработку полнофункциональной системы мониторинга компании и платформы диагностики приложений.

Добро пожаловать на сайт start.aliyun.com, чтобы испытать на себе 57 практических экспериментов Артаса:start.aliyun.com/Handan city oh you-speaker…

35.gif

Предварительный просмотр эксперимента Артаса

Чтобы больше разработчиков могли начать использовать Arthas, диагностический артефакт Java, было запущено сообщество Arthas и JetBrains.Объявление о приеме статей на приз Артаса:**Говоря о том, что произошло между тобой и Артасом за эти годы. **Событие еще в самом разгаре,Нажмите, чтобы принять участие, Каждый может внести свой вклад, и вы можете выиграть призы, если примете участие!

Категории