В сети есть очень загруженный сервис, где ЦП процесса JVM часто работает более чем на 100%, и процесс устранения неполадок описан ниже. Прочитав эту статью, вы получите следующие знания.
- Идеи по устранению неполадок, связанных с высокой загрузкой ЦП в программах Java
- log4j ложная асинхронность, которая может вызвать большое количество исключений в онлайн-сервисах
- Оптимизация асинхронной отправки Kafka
- Принцип и интерпретация On-CPU Flame Graph
- Использование деревьев префиксов Trie для оптимизации сопоставления путей Spring
начать пытаться
Высокая загрузка ЦП JVM. Первая реакция — найти поток с максимальной загрузкой ЦП и посмотреть, что этот поток выполняет. Используйте команду top, чтобы просмотреть использование ЦП всеми потоками в процессе. Команда выглядит следующим образом.
top -Hp you_pid
Результат выглядит следующим образом:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
48 root 20 0 30.367g 2.636g 12940 S 12.7 2.9 36:15.18 java
2365 root 20 0 30.367g 2.636g 12940 R 1.3 2.9 2:33.64 java
2380 root 20 0 30.367g 2.636g 12940 S 1.3 2.9 2:33.10 java
2381 root 20 0 30.367g 2.636g 12940 S 1.3 2.9 2:33.41 java
10079 root 20 0 30.367g 2.636g 12940 S 1.3 2.9 0:30.73 java
10 root 20 0 30.367g 2.636g 12940 S 1.0 2.9 4:08.54 java
11 root 20 0 30.367g 2.636g 12940 S 1.0 2.9 4:08.55 java
92 root 20 0 30.367g 2.636g 12940 S 1.0 2.9 2:53.71 java
681 root 20 0 30.367g 2.636g 12940 S 1.0 2.9 2:52.56 java
683 root 20 0 30.367g 2.636g 12940 S 1.0 2.9 2:56.81 java
690 root 20 0 30.367g 2.636g 12940 S 1.0 2.9 3:34.24 java
Вы можете видеть, что PID потока, который занимает больше всего ЦП, равен 48 (0x30), используйте jstack для вывода стека текущего потока, а затем grep 0x30, как показано ниже.
jstack 1 | grep -A 10 "0x30 "
Вывод следующий.
"kafka-producer-network-thread | producer-1" #35 daemon prio=5 os_prio=0 tid=0x00007f9ac4fc7000 nid=0x30 runnable [0x00007f9ac9b88000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x0000000094ef70c8> (a sun.nio.ch.Util$3)
- locked <0x0000000094ef70e0> (a java.util.Collections$UnmodifiableSet)
- locked <0x000000009642bbb8> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at org.apache.kafka.common.network.Selector.select(Selector.java:686)
Вы можете видеть, что это поток отправки kafka. Наша печать журнала заключается в использовании плагина log4j2 kafka для записи файлов журнала в kafka, а объем записи журнала очень велик. Далее давайте оптимизируем использование ЦП этим потоком отправки kafka.
Оптимизация KafkaAppender под Log4j2
KafkaAppender инкапсулирует KafkaProducer.После тестирования эти параметры тесно связаны с частотой отправки KafkaProducer.batch.size,linger.ms. Далее, давайте взглянем на реальную роль нескольких параметров здесь.
linger.ms
KafkaProducer отправит сообщение, когда пакетный буфер будет заполнен или наступит время linger.ms. linger.ms используется для указания того, как долго отправитель ожидает заполнения пула пакетных буферов, что эквивалентно алгоритму Nagle протокола TCP.
По умолчанию это значение равно 0. Пока есть данные, поток Sender будет отправлять их без ожидания.Даже если в пакетном буфере есть только один фрагмент данных, он будет отправлен немедленно. Таким образом, задержка отправки сообщения будет очень низкой, но пропускная способность будет очень низкой.
Установка значения больше 0 позволяет отправителю подождать некоторое время, если буфер не заполнен, и отправить данные с накопленным временем linger.ms. Это уменьшает количество запросов и позволяет избежать частой отправки слишком большого количества небольших пакетов без немедленной отправки данных. Это увеличивает задержку сообщения (латентность), но улучшает пропускную способность (пропускную способность).
batch.size
Когда KafkaProducer отправляет несколько сообщений, они отправляются в тот же раздел, что и пакет.
batch.size используется для указания размера области кэш-памяти для пакетной отправки.Обратите внимание, что это не количество штук.Значение по умолчанию – 16384 (16 КБ).
Когда пакетный буфер заполнен, все сообщения в буфере будут отправлены. Это не означает, что KafkaProducer будет ждать заполнения пакета перед отправкой, иначе при наличии только одного сообщения оно не будет отправлено.linger.msиbatch.sizeповлияет на поведение отправки KafkaProducer.
Установка слишком маленького значения batch.size снизит пропускную способность, а слишком большое приведет к трате памяти.
Ни одно из этих двух значений не настроено в нашей онлайн-конфигурации.Он будет работать в соответствии с конфигурацией linger.ms=0 и batch.size 16 КБ.Поскольку журнал создается очень часто, поток отправителя почти не простаивает и имеет обрабатываются отправленные данные.
Потенциальные ямки асинхронного приложения log4j2
Перед настройкой параметров отправителя Kafka есть риск: нужно заранее избегать потенциальных ям асинхронного аппендера log4j2, иначе это вызовет большое количество тайм-аутов онлайн-бизнес-интерфейса.
В принципе, асинхронный Appender log4j2 использует локальную очередь ArrayBlockingQueue для хранения сообщений, отправленных прикладным уровнем. Размер этой очереди по умолчанию составляет 128 в версии 2.7 log4j2. В более поздних версиях это значение было скорректировано до 1024. . Если KafkaAppender обрабатывается медленно, очередь быстро заполняется, как показано на следующем рисунке.
После заполнения это включает в себя ожидание блокировки или отбрасывание журнала, добавленного позже.Более жалко то, что конфигурация log4j2 по умолчанию — DefaultAsyncQueueFullPolicy, которая является стратегией синхронной блокировки и ожидания текущего потока. Мы можем выбрать отбрасывание этого значения, чтобы гарантировать, что независимо от того, медленно или медленно записывается базовый журнал, это не может повлиять на бизнес-интерфейс верхнего уровня. log4j предоставляет элементы конфигурации, задайте для системного свойства log4j2.AsyncQueueFullPolicy значение Discard.
Это еще не конец.После установки политики полной очереди на Discard, log4j по умолчанию будет отбрасывать только журналы уровня INFO и ниже. Если система создает большое количество журналов уровня ПРЕДУПРЕЖДЕНИЕ и ОШИБКА, даже если выбрана политика Отменить, восходящий поток будет заблокирован.Вам необходимо установить для log4j2.DiscardThreshold значение ОШИБКА или FATAL.
После изменения параметров KafkaProducer и log4j использование ЦП потоком отправки Kafka снижается до менее 5 %, а общая загрузка ЦП остается относительно высокой, поэтому продолжайте исследования.
всемогущее пламя
Сначала я хотел использовать perf, dtrace, systemtap и другие инструменты для создания флейм-графов, но, к сожалению, у меня не было привилегированных прав в контейнере Docker, я пробовал все вышеперечисленные команды и не смог запустить все вышеперечисленные команды. К счастью, Arthas предоставил команды для генерации пламенных графов profiler, его принцип заключается в использовании async-profiler для выборки приложений и генерации пламенных графов.
После использования arthas Attach в процессе JVM используйте запуск профилировщика, чтобы начать выборку, и выполните остановку профилировщика после запуска в течение определенного периода времени, чтобы сгенерировать пламенный график svg, как показано на следующем рисунке.
Графики пламени имеют несколько характеристик:
- Каждое поле представляет функцию в стеке;
- Ось Y представляет глубину стека вызовов функций, а функция нижнего уровня является родительским вызовом функции верхнего уровня. Чем глубже стек вызовов, тем выше пламя;
- Ось X представляет не время, а количество выборок.Чем шире ширина функции по оси X, тем больше раз она выбирается в выборке и тем больше время выполнения.
Из приведенного выше рисунка видно, что выполнение функций kafka и Spring занимает больше всего ЦП, и вышеприведенное содержание проблемы kafka может быть оптимизировано.Далее давайте посмотрим на стек вызовов, связанный с функцией Spring.
Стоимость расчета номера строки log4j
Увеличив масштаб SVG, вы можете увидеть, что вершина всегда плоская и высокая.Функция Log4jLogEvent.calcLocation, где log4j генерирует расчет количества строк печати журнала, как показано на следующем рисунке.
Принцип вычисления номера строки фактически достигается путем получения текущего стека вызовов.Эта производительность вычисления очень плохая, и насколько она медленная?В Интернете есть много тестовых примеров, которые можно протестировать.
Мы отключили вывод номера строки log4j, использование ЦП стало немного меньше, а вызов с плоским верхом исчез.
Используйте дерево префиксов Trie для оптимизации проблем с производительностью в самом Spring.
Продолжайте анализировать вызовы функций с высокой занятостью. По историческим причинам мы не рассматривали возможность заранее помещать URL-адреса, не требующие аутентификации, в один и тот же путь префикса в дизайне URL-адресов, что привело к более чем 100 конфигурациям перехватчика с сопоставлением исключений, как показано ниже.
<mvc:interceptors>
<mvc:interceptor>
<mvc:mapping path="/**"/>
<mvc:exclude-mapping path="/login"/>
<mvc:exclude-mapping path="/*/login"/>
<mvc:exclude-mapping path="/*/activity/teacher"/>
<mvc:exclude-mapping path="/masaike/dynamic/**"/>
...下面还有一百多个这样的 exclude...
<mvc:exclude-mapping path="/masaike/aaaa/**"/>
<mvc:exclude-mapping path="/masaike/**/hello"/>
<bean class="com.masaike.AuthenticationHandlerInterceptor"/>
</mvc:interceptor>
</mvc:interceptors>
Логика Spring MVC, обрабатывающая этот абзац, находится вorg.springframework.web.servlet.handler.MappedInterceptor
- Для интерфейса, который требует аутентификации, он будет проходить через весь список excludePatterns.
- Для интерфейса, не требующего аутентификации, цикл for прерывается посередине. В худшем случае вам также необходимо просмотреть весь список excludePatterns.
Это слишком неэффективно. Мы можем полностью оптимизировать эту логику и использовать дерево дерева для достижения сопоставления путей. Отличие от обычного дерева дерева состоит в том, что дерево дерева здесь должно поддерживать подстановочные знаки в середине.*и**формат.
Предположим, у нас есть следующие пути:
"/api/*/login"
, "/wildcard/**"
, "/wildcard/**/hello"
, "/v2/hello/"
, "/v2/user/info/"
, "/v2/user/feed/"
, "/v2/user/feed2/"
Результирующее дерево дерева показано ниже.
.
└──api
└──*
└──login
└──v2
└──hello
└──user
└──feed
└──feed2
└──info
└──wildcard
└──**
Реализация очень проста, каждый узел имеет список дочерних элементов, представленных картой, поэтому поиск выполняется очень быстро.
/**
* @author Arthur.Zhang (zhangya@imlizhi.com)
* 用于匹配 /a/b/c, *, ** 这种格式的前缀匹配
* 参考了 ZooKeeper 和 lucene 的 trie 实现
*/
public class PathTrie {
private Node root = new Node(emptyList(), null);
public PathTrie() {
}
public void insert(String path, String obj) {
List<String> parts = getPathSegments(path);
insert(parts, obj);
}
public void insert(List<String> parts, String o) {
if (parts.isEmpty()) {
root.obj = o;
return;
}
root.insert(parts, o);
}
private static List<String> getPathSegments(String path) {
return Splitter.on('/').splitToList(path).stream().filter(it -> !it.isEmpty()).collect(Collectors.toList());
}
public boolean existsPath(String path) {
return root.exists(getPathSegments(path), 0);
}
public void dump() {
if (root != null) root.dump();
}
private static class Node {
String name;
Map<String, Node> children;
String obj; // 标识是否是叶子节点
Node(List<String> path, String obj) {
if (path.isEmpty()) {
this.obj = obj;
return;
}
name = path.get(0);
}
private synchronized void insert(List<String> parts, String o) {
String part = parts.get(0);
Node matchedChild;
// 如果是 **，后面的路径节点不用再插入了
if ("**".equals(name)) {
return;
}
if (children == null) children = new ConcurrentHashMap<>();
matchedChild = children.get(part);
if (matchedChild == null) {
matchedChild = new Node(parts, o);
children.put(part, matchedChild);
}
// 移除已处理的
parts.remove(0);
if (parts.isEmpty()) { // 如果已经到底，将最后一个 child 的 obj 赋值
matchedChild.obj = o;
} else {
matchedChild.insert(parts, o); //还没有到底，继续递归插入
}
}
/**
* @param pathSegments 路径分割以后的 word 列表，比如 /a/b/c -> 'a' , 'b' , 'c'
* @param level 当前路径遍历的 level 深度，比如 /a/b/c -> 0='a' 1='b' 2='c'
*/
public boolean exists(List<String> pathSegments, int level) {
// 如果已经把传入的 path 遍历完了
if (pathSegments.size() < level + 1) {
// 如果当前 trie 树不是叶子节点
if (obj == null) {
// 获取叶子节点是否包含 **，如果包含的话，则匹配到
Node n = children.get("**");
if (n != null) {
return true;
}
}
return obj != null;
}
if (children == null) {
return false;
}
String pathSegment = pathSegments.get(level);
// 1、首先找绝对匹配的
Node n = children.get(pathSegment);
// 2、如果不存在，则找是否包含 * 的
if (n == null) {
n = children.get("*");
}
// 3、如果还不存在，则找是否包含 ** 的
if (n == null) {
n = children.get("**");
if (n != null) {
return true;
}
}
// 4、如果这些都没有找到，则返回 false
if (n == null) {
return false;
}
// 5、如果找到了一个 node，则继续递归查找
return n.exists(pathSegments, level + 1);
}
@Override
public String toString() {
return "Node{" +
"name='" + name + '\'' +
", children=" + children +
'}';
}
/**
* 使用类似 tree 命令的输出格式打印这棵前缀数
* .
* └──api
* └──*
* └──login
* └──v2
* └──hello
* └──user
* └──feed
* └──feed2
* └──info
* └──wildcard
* └──**
*/
public void dump() {
dump(0);
}
public void dump(int level) {
if (level == 0) {
System.out.println(".");
} else {
StringBuilder sb = new StringBuilder();
for (int i = 0; i < level - 1; i++) {
sb.append("\t");
}
sb.append("└──").append(name);
System.out.println(sb.toString());
}
if (children != null && !children.isEmpty()) {
for (Map.Entry<String, Node> item : children.entrySet()) {
item.getValue().dump(level + 1);
}
}
}
}
}
После внедрения Trie среднее потребление процессора снижается примерно на 5%.
резюме
После общей оптимизации загрузка процессора в пиковый период снизилась примерно со 100% до 35%, и эффект очевиден.
Оптимизация производительности — это полноценный проект, и более половины проблем решены, если вы сможете их найти. Кроме того, недостаточно понять основополагающие принципы: только поняв базовые принципы, мы можем по-настоящему нацелиться и обнаружить суть проблемы.
Если у вас есть какие-либо вопросы, вы можете отсканировать QR-код ниже и подписаться на мою официальную учетную запись, чтобы связаться со мной.