線上有一個非常繁忙的服務的 JVM 進程 CPU 經(jīng)常跑到 100% 以上，下面寫了一下排查的過程。通過閱讀這篇文章你會了解到下面這些知識。
- Java 程序 CPU 占用高的排查思路
- 可能造成線上服務大量異常的 log4j 假異步
- Kafka 異步發(fā)送的優(yōu)化
- On-CPU 火焰圖的原理和解讀
- 使用 Trie 前綴樹來優(yōu)化 Spring 的路徑匹配
開始嘗試
JVM CPU 占用高，第一反應是找出 CPU 占用最高的線程，看這個線程在執(zhí)行什么，使用 top 命令可以查看進程中所有線程占用的 CPU 情況，命令如下所示。
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
復制代碼
可以看到占用 CPU 最高的線程 PID 為 48(0x30)，使用 jstack 輸出當前線程堆棧，然后 grep 一下 0x30，如下所示。
jstack 1 | grep -A 10 "0x30 "
復制代碼
輸出結(jié)果如下。
"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 的發(fā)送線程。我們的日志打印是使用 log4j2 的 kafka 插件將日志文件寫入到 kafka，日志寫入量非常大。接下來先來優(yōu)化這個 kafka 發(fā)送線程的 CPU 占用。
Log4j2 下 KafkaAppender 優(yōu)化
KafkaAppender 中封裝了 KafkaProducer，經(jīng)過測試與 KafkaProducer 發(fā)送頻率有很大關(guān)系的有這幾個參數(shù) batch.size、linger.ms。接下來看看這里幾個參數(shù)有什么實際的作用。
linger.ms
KafkaProducer 在 batch 緩沖區(qū)滿或者 linger.ms 時間到達時，會將消息發(fā)送出去。 linger.ms 用來指定發(fā)送端在 batch 緩沖池被填滿之前最多等待多長時間，相當于 TCP 協(xié)議的 Nagle 算法。
這個值默認為 0，只要有數(shù)據(jù) Sender 線程就會一直發(fā)，不會等待，就算 batch 緩沖區(qū)只有一條數(shù)據(jù)也會立即發(fā)送。這樣消息發(fā)送的延遲確實很低，但是吞吐量會變得很差。
設(shè)置一個大于 0 的值，可以讓發(fā)送端在緩沖區(qū)沒有滿的情況下等待一段時間，累積 linger.ms 時間的數(shù)據(jù)一起發(fā)送。這樣可以減少請求的數(shù)量，避免頻繁發(fā)送太多小包，不會立即發(fā)送數(shù)據(jù)。這樣增加了消息的時延（latency），但是提高了吞吐量（throughput）。
batch.size
KafkaProducer 在發(fā)送多條消息時，會把發(fā)往同一個 partition 的的消息當做一個 batch 批量發(fā)送。
batch.size 用于指定批量發(fā)送緩存內(nèi)存區(qū)域的大小，注意這里不是條數(shù)，默認值是 16384（16KB）
當 batch 緩沖區(qū)滿，緩沖區(qū)中所有的消息會被發(fā)送出去。這并不意味著 KafkaProducer 會等到 batch 滿才會發(fā)，不然只有一條消息時，消息就一直發(fā)不出去了。linger.ms 和 batch.size 都會影響 KafkaProducer 的發(fā)送行為。
batch.size 值設(shè)置太小會降低吞吐量，太大會浪費內(nèi)存。
我們線上的配置這兩個值都沒配置，會按 linger.ms=0，batch.size 為 16KB 的配置運行，因為日志產(chǎn)生得非常頻繁，Sender 線程幾乎不會閑下來，一直在處理發(fā)送數(shù)據(jù)包。
log4j2 的異步 Appender 潛在的坑
在做 Kafka 發(fā)送端的參數(shù)調(diào)整之前有一個風險點，log4j2 的異步 Appender 潛在的坑需要提前避免，否則會造成線上業(yè)務接口的大量超時。
log4j2 的異步 Appender 原理上是在本地利用了本地的一個 ArrayBlockingQueue 存儲應用層發(fā)過來的消息，這個 queue 的大小默認值在 2.7 版本的 log4j2 中是 128，在高版本中，這個值已經(jīng)被調(diào)為了 1024。如果 KafkaAppender 處理的比較慢，很快這個隊列就填滿，如下圖所示。
填滿以后就涉及到是 blocking 等待，還是丟棄后面加入的日志的問題，比較坑的是 log4j2 的默認配置是
DefaultAsyncQueueFullPolicy，這個策略是同步阻塞等待當前線程。我們可以選擇將這個值設(shè)置為丟棄，以保證不管底層的日志寫入慢不慢，都不能影響上層的業(yè)務接口，大不了就丟棄部分日志。log4j 提供了配置項，將系統(tǒng)屬性 log4j2.AsyncQueueFullPolicy 設(shè)置為 Discard 即可。
這還沒完，設(shè)置了隊列滿的策略為 Discard 后，log4j 默認只會舍棄 INFO 及以下級別的日志。如果系統(tǒng)大量產(chǎn)生 WARN、ERROR 級別的日志，就算策略是 Discard 還是會造成阻塞上游線程，需要將 log4j2.DiscardThreshold 設(shè)置為 ERROR 或者 FATAL。
修改了 KafkaProducer 和 log4j 的參數(shù)以后，kafka 發(fā)送線程的 CPU 占用降低到了 5% 以下，整體的 CPU 負載依舊是比較高的，接下來繼續(xù)排查。
萬能的火焰圖
一開始本來想用 perf、dtrace、systemtap 等工具來生成火焰圖，無奈在 Docker 容器中沒有 privileged 權(quán)限，我一一嘗試了都無法運行上面的所有命令，好在是 Arthas 提供了火焰圖生成的命令 profiler，它的原理是利用 async-profiler 對應用采樣，生成火焰圖。
使用 arthas Attach 上 JVM 進程以后，使用 profiler start 開始進行采樣，運行一段時間后執(zhí)行 profiler stop 就可以生成火焰圖 svg 了，部分如下圖所示。
火焰圖有幾個特征：
- 每個框代表棧里的一個函數(shù)；
- Y 軸表示函數(shù)調(diào)用棧的深度，下層函數(shù)是上層函數(shù)的負調(diào)用。調(diào)用棧越深，火焰越高；
- X 軸不是表示時間的流逝，而是表示抽樣數(shù)，一個函數(shù)在 X 軸的寬度越寬，表示它在采樣中被抽到的次數(shù)越多，執(zhí)行時間越長。
從上面的圖可以看到 kafka 和 Spring 函數(shù)執(zhí)行的 CPU 占用最多，kafka 的問題上面的內(nèi)容可以優(yōu)化，接下來我們來看 Spring 函數(shù)相關(guān)調(diào)用棧。
log4j 行號計算的代價
把 svg 放大，可以看到有一個頂一直都平很高，函數(shù)是
Log4jLogEvent.calcLocation，也就是 log4j 生成日志打印行數(shù)的計算的地方，如下圖所示。
計算行號的原理實際上是通過獲取當前調(diào)用堆棧來實現(xiàn)的，這個計算性能很差，具體有多慢，網(wǎng)上有很多 benchmark 的例子可以實測一下。
我們把 log4j 的行號輸出關(guān)掉，CPU 占用又小了一點點，這個平頂?shù)恼{(diào)用也不見了。
使用 Trie 前綴樹來優(yōu)化 Spring 本身的性能問題
繼續(xù)分析占用高函數(shù)調(diào)用。因為歷史的原因，我們在 url 設(shè)計上沒有能提前考慮將不需要走鑒權(quán)的 url 放在同一個前綴路徑下，導致 interceptor 的 exclude-mapping 配置有一百多個，如下所示。
<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
- 對于一個需要鑒權(quán)的接口，它會遍歷整個 excludePatterns 列表
- 對于一個的確不需要鑒權(quán)的接口，for 循環(huán)會在中間 break。最壞的情況下，也需要遍歷完所有的 excludePatterns 列表
這樣效率太低了，我們完全可以優(yōu)化這段邏輯，使用 trie 樹來實現(xiàn)路徑的匹配，與普通 trie 樹有區(qū)別的地方在于，這里的 trie 樹需要能支持中間帶通配符 * 和 ** 的格式。
假如我們有下面這些路徑：
"/api/*/login"
, "/wildcard/**"
, "/wildcard/**/hello"
, "/v2/hello/"
, "/v2/user/info/"
, "/v2/user/feed/"
, "/v2/user/feed2/"
復制代碼
生成的 trie 樹如下所示。
.
└──api
└──*
└──login
└──v2
└──hello
└──user
└──feed
└──feed2
└──info
└──wildcard
└──**
復制代碼
實現(xiàn)倒是非常簡單，每個 node 節(jié)點都有包含一個 map 表示的 child 列表，這樣在查找的時候就非?？?。
/**
* @author Arthur.Zhang (zhangya@imlizhi.com)
* 用于匹配 /a/b/c, *, ** 這種格式的前綴匹配
* 參考了 ZooKeeper 和 lucene 的 trie 實現(xiàn)
*/
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; // 標識是否是葉子節(jié)點
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;
// 如果是 **，后面的路徑節(jié)點不用再插入了
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()) { // 如果已經(jīng)到底，將最后一個 child 的 obj 賦值
matchedChild.obj = o;
} else {
matchedChild.insert(parts, o); //還沒有到底，繼續(xù)遞歸插入
}
}
/**
* @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) {
// 如果已經(jīng)把傳入的 path 遍歷完了
if (pathSegments.size() < level + 1) {
// 如果當前 trie 樹不是葉子節(jié)點
if (obj == null) {
// 獲取葉子節(jié)點是否包含 **，如果包含的話，則匹配到
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，則繼續(xù)遞歸查找
return n.exists(pathSegments, level + 1);
}
@Override
public String toString() {
return "Node{" +
"name='" + name + '\'' +
", children=" + children +
'}';
}
/**
* 使用類似 tree 命令的輸出格式打印這棵前綴數(shù)
* .
* └──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 的實現(xiàn)之后，平均的 CPU 占比消耗降低了 5% 左右。
小結(jié)
整體優(yōu)化以后，高峰期間的 CPU 占用從 100% 左右下降到了 35%，效果還是比較明顯的。
性能優(yōu)化是一個全棧的工程，能發(fā)現(xiàn)問題就已經(jīng)解決了一大半了。另外光會命令是不夠的，理解底層原理才能真正的有的放矢，發(fā)現(xiàn)問題的核心所在。
最后，小編還整理了一份面試寶典，有需要的私信小助理【666】
