задний план

В последнее время мне не повезло, и меня почти каждый день беспокоили онлайн-вопросы. Буквально пару дней назад исправилПараллелизм HashSetПроблема, в субботу возникла еще одна проблема с производительностью.

Общее явление таково:

Ответ предоставленного нами OpenAPI бывает быстрым и медленным, десятки миллисекунд при быстром и всего несколько секунд при медленном.

попробуй решить

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

Нет другого выхода, кроме как стиснуть зубы.

Посреди этого у меня случилась случайность в сердце, и я попросил службу эксплуатации и техобслуживания проверить ее.NginxвнутриOpenAPIВремя отклика, хотите бросить горшок в сети. Результат действительно поразил лицо;NginxЖурналы здесь также показывают, что действительно есть проблема со временем отклика.

Чтобы ясно понять эту проблему, я кратко разберу процесс вызова.

Весь процесс представляет собой относительно распространенную многоуровневую архитектуру:

запросы клиентов наNginx.
Nginxзагруженный серверwebСлужить.
webобслуживание черезRPCбэкэнд вызоваServiceСлужить.

Дневник Дафа

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

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

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

инструментальный анализ

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

Тогда вам нуженagentинструмент тоже. Мы выбрали предыдущую версию с открытым исходным кодом Alibaba.Tprofileиспользовать.

Просто добавьте его в параметры запуска-javaagent:/xx/tprofiler.jarВы можете отслеживать трудоемкий метод, который вы хотите отслеживать, и вы можете выводить отчет, что очень удобно. Это не мешает коду и оказывает небольшое влияние на производительность.

использование инструмента

Ниже приведена краткая демонстрация того, как использовать этот инструмент.

Первый шаг, конечноcloneЗатем исходный код упаковывается, и я могу клонировать измененный исходный код.

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

Просто выполните следующий скрипт.

git clone https://github.com/crossoverJie/TProfiler

mvn assembly:assembly

Попав сюда, он будет в проектеTProfiler/pkg/TProfiler/lib/tprofiler-1.0.1.jarСоздайте пакет jar, который мы хотим использовать.

Далее вам нужно только настроить пакет JAR в параметры запуска, а также настроить путь к файлу конфигурации одновременно.

Я копирую официальное объяснение этого файла конфигурации.

#log file name
logFileName = tprofiler.log
methodFileName = tmethod.log
samplerFileName = tsampler.log

#basic configuration items
# 开始取样时间
startProfTime = 1:00:00

# 结束取样时间
endProfTime = 23:00:00

# 取样的时间长度
eachProfUseTime = 10

# 每次取样的时间间隔
eachProfIntervalTime = 1

samplerIntervalTime = 20

# 端口，主要不要冲突了
port = 50000
debugMode = false
needNanoTime = false

# 是否忽略 get set 方法
ignoreGetSetMethod = true

#file paths 日志路径
logFilePath = /data/work/logs/tprofile/${logFileName}
methodFilePath =/data/work/logs/tprofile/${methodFileName}
samplerFilePath =/data/work/logs/tprofile/${samplerFileName}

#include & excludes items
excludeClassLoader = org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader

# 需要监控的包
includePackageStartsWith = top.crossoverjie.cicada.example.action

# 不需要监控的包
excludePackageStartsWith = com.taobao.sketch;org.apache.velocity;com.alibaba;com.taobao.forest.domain.dataobject

Окончательные параметры запуска следующие:

-javaagent:/TProfiler/lib/tprofiler-1.0.1.jar
-Dprofile.properties=/TProfiler/profile.properties

Чтобы смоделировать и устранить проблему медленного отклика интерфейса, я используюcicadaпонялHTTPинтерфейс. Который вызывает два трудоемких метода:

Поэтому, когда я запускаю приложение,TprofileИнформация о методе, которую он собирает, будет записана в каталоге, который я настроил.

Я получаю доступ к интерфейсуhttp://127.0.0.1:5688/cicada-example/demoAction?name=test&id=10Через несколько раз он пишет подробный ответ для каждого метода.tprofile.log.

Слева направо каждый столбец представляет:

Идентификатор потока, глубина стека методов, номер метода, время (миллисекунды).

ноtmethod.logеще пусто;

В настоящее время нам нужно только выполнить эту команду, чтобы обновить последнюю информацию о выборке метода, чтобыtmethod.logв файле.

java -cp /TProfiler/tprofiler.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 50000 flushmethod

flushmethod success

На самом деле посетитьTprofileСлужба выставлена, он будет читать и анализироватьtprofile.logОдновременная записьtmethod.log.

Порт является портом в файле конфигурации.

открыть сноваtmethod.log:

Он записывает информацию о методе.

Первая строка цифр — это номер метода. Вы можете пройти по этому номеруtprofile.log(Подробности) каждый раз запрашивать трудоемкую ситуацию.
Число в конце строки — это номер последней строки в исходном коде этого метода.

На самом деле, большая часть анализа производительности представляет собой среднестатистический метод, занимающий много времени.

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

java -cp /TProfiler/tprofiler.jar com.taobao.profile.analysis.ProfilerLogAnalysis tprofiler.log tmethod.log topmethod.log topobject.log
print result success

Открытымtopmethod.logсреднее время всех методов.

4 — количество запросов.
205 это среднее время.
818 - это общее время.

соответствует реальной ситуации.

Подробный трудоемкий метод

Могут быть и другие требования, например, что, если я хочу запросить все детали метода?

Официально не предусмотрено, но тоже возможно, только немного хлопотно.

Например, я хочу просмотретьselectDB()Детали, отнимающие много времени:

Сначала вы должны знать количество этого метода, вtmethod.logможно увидеть в .

2 top/crossoverjie/cicada/example/action/DemoAction:selectDB:84

номер 2.

мы знали раньшеtprofile.logЗаписи являются деталями, поэтому вы можете просмотреть их с помощью следующих команд.

grep 2 tprofiler.log

Подробности каждого выполнения см. в третьем столбце метода номер 2.

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

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

Суммировать

Возвращаясь к предыдущему вопросу, мы получили следующие результаты онлайн-анализа этого инструмента.

Некоторые методы выполняются быстрее или медленнее, но все они зависят от базы данных. Из-за текущей нагрузки на базу данных мы собираемся разделить горячие и холодные данные, а также подбазу данных и подтаблицу.
Перед тем, как будет реализована первая операция, часть операции записи в базу данных изменена на асинхронную, чтобы сократить время отклика.
Рассмотрите возможность присоединитьсяpinpointТакойAPM工具.

похожий наTprofileИнструментов довольно много, просто найдите тот, который вам подходит.

не использовал что-то вродеpinpointТакие распределенные инструменты отслеживания должны были в значительной степени полагаться на этот инструмент раньше, поэтому в будущем могут быть сделаны некоторые настройки, такие как добавление некоторых визуальных интерфейсов и т. д., которые могут повысить эффективность расследования.

Ваши лайки и репост - лучшая поддержка для меня