线上问题诊断指南
內容概要
- 診斷工具介紹
- 工具可用情況
- 偶現或已現問題診斷思路
硬件資源觀測
top
top可以看整個系統cpu、內存的使用情況，以及在各個進程上的情況，如下：
$ top top - 13:14:07 up 2 days, 6:38, 0 users, load average: 1.65, 0.59, 0.27 Tasks: 17 total, 3 running, 14 sleeping, 0 stopped, 0 zombie %Cpu(s): 25.0 us, 0.0 sy, 0.0 ni, 74.9 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st MiB Mem : 12693.4 total, 12052.8 free, 271.6 used, 368.9 buff/cache MiB Swap: 4096.0 total, 4096.0 free, 0.0 used. 12171.8 avail MemPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND3174 work 20 0 3860 104 0 R 100.0 0.0 1:40.75 stress3175 work 20 0 3860 104 0 R 100.0 0.0 1:40.76 stress1 root 20 0 900 492 428 S 0.0 0.0 0:00.11 init10 work 20 0 10044 5140 3424 S 0.0 0.0 0:00.12 bash3051 work 20 0 6393208 204364 20116 S 0.0 1.6 0:07.51 java3173 work 20 0 3860 980 896 S 0.0 0.0 0:00.00 stress3176 work 20 0 10888 3932 3348 R 0.0 0.0 0:00.02 top- 第一行是系統概要：當前時間，系統啟動時長，系統用戶數，系統負載1min/5min/15min
- 第二行是任務概要：總任務數，正在運行/睡眠/暫停/僵尸任務數
- 第三行cpu使用率：
????????us：非niced進程花費的cpu時間占比
????????sy：內核進程花費的cpu時間占比
????????ni：niced進程花費的cpu時間占比
????????id：內核空閑進程花費的cpu時間占比，一般來說CPU是無法空閑的，CPU空閑著，指的是在運行一個空閑程序的代碼。
????????wa：等待磁盤io完成花費的cpu時間占比
????????hi：處理硬件中斷花費的cpu時間占比
????????si：處理軟件中斷花費的cpu時間占比
????????st：被其它虛擬機偷取的cpu時間占比
- 第四行是內存使用率：
????????total：總內存大小(MB)
????????free：空閑內存大小(MB)
????????used：使用中的內存大小(MB)
????????buff/cache：用于文件緩存與系統緩存的內存大小(MB)
- 第五行是swap情況：
????????total：總swap文件大小
????????free：swap空閑大小
????????used：swap使用大小
????????avail Mem：可用內存大小，和swap無關，約等于上一行中free+buff/cache
下面的列表顯示的就是各進程情況了，除此之外，top還是個交互式命令，可直接在這個界面輸入指令使用其更多功能，如下：
| 指令 | 功能描述 |
| 1 | 查看1號cpu各核的cpu使用情況，類似mpstat |
| M | 進程按內存使用率倒序，同時按shift + m |
| P | 進程按cpu使用率倒序，同時按shift + p |
| H | 查看線程情況，同時按shift + h |
| c | 查看進程的完整命令行 |
| k | 殺死指定pid的進程 |
| h | 查看幫助 |
| q | 退出top |
注意，這里面的指令，很多都是開關式的，比如按1顯示cpu各核使用率，再按1就顯示整體cpu使用率了。
另外，如果你的電腦是8核的，top中進程的CPU%最高可以到800%，初次看到這種現象時，還很容易嚇一跳呢！
iostat
iostat命令可以很方便的查看磁盤當前的IO情況，如下：
$ iostat -xz 1 avg-cpu: %user %nice %system %iowait %steal %idle0.06 0.00 0.00 0.00 0.00 99.94Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 1.87 17854.96 3799.10 14930.26 42642.19 208548.03 26.82 7.10 0.37 1.04 0.20 0.28 522.73avg-cpu: %user %nice %system %iowait %steal %idle4.36 0.00 0.00 0.00 0.00 95.64Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 0.00 0.00 606.00 0.00 2616.00 8.63 0.04 0.06 0.00 0.06 0.06 3.40注意，和vmstat一樣，第一次的輸出結果是歷史以來的統計值，一般可以忽略不計，如下：
- %util ：磁盤使用率，Linux認為磁盤只能處理一個并發，但SSD或raid實際可以超過一個，所以100%也不一定代表滿載。
- avgqu-sz：磁盤任務隊列長度，大于磁盤的并發任務數則磁盤處于飽和狀態。
- svctm：平均服務時間，不包括在磁盤隊列中的等待時間。
- r_await,w_await：讀寫延遲時間(ms)，磁盤隊列等待時間+svctm，太大則磁盤飽和。
- r/s + w/s： 就是當前的IOPS。
- avgrq-sz：就是當前每秒平均吞吐量 單位是扇區（512b)。
iotop
iotop以進程的角度查看io情況，如下：
# -P表示只看進程整體的，不然iotop看的是每個線程的 # -o表示只看有io操作的進程，不然iotop會列出所有進程 $ sudo iotop -P -o Total DISK READ: 3.84 K/s | Total DISK WRITE: 138.97 M/s Current DISK READ: 3.84 K/s | Current DISK WRITE: 80.63 M/sPID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND737183 be/4 root 3.84 K/s 0.00 B/s 0.00 % 88.89 % [kworker/u256:1+flush-8:0]761496 be/4 work 0.00 B/s 138.96 M/s 0.00 % 79.09 % stress -d 1876 be/4 work 0.00 B/s 7.68 K/s 0.00 % 0.00 % java -Xms256m -Xmx1g -Xss1m -XX:MaxMetaspaceSize=1g ...可以看到整個磁盤的當前讀寫速率，以及各個進程占用的比例。
iftop
iftop可以用來查看整個網卡以及各個連接的當前網速，如下：
$ sudo iftop -B -nNP244KB 488KB 732KB 977KB 1.19MB └──────────────────────────────┴──────────────────────────────┴───────────────────────────────┴──────────────────────────────┴─────────────────────────────── 100.135.65.10:11111 => 100.135.95.10:29518 85.8KB 103KB 94.3KB<= 2.95KB 3.54KB 3.25KB 100.135.65.10:11111 => 100.135.95.9:35981 170KB 103KB 94.3KB<= 5.41KB 3.49KB 3.21KB 100.135.60.10:35172 => 100.135.24.54:3561 13.3KB 9.88KB 5.25KB<= 58.6KB 60.6KB 32.4KB 100.134.60.10:43240 => 100.134.24.55:3560 9.83KB 5.52KB 3.09KB<= 101KB 53.6KB 31.1KB 100.134.60.10:65932 => 100.154.24.55:3951 4.45KB 5.07KB 6.04KB<= 35.0KB 39.8KB 47.4KB 10.134.60.10:58990 => 10.134.24.5:80 22.0KB 19.2KB 22.5KB ───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────── TX: cum: 10.9MB peak: 1.75MB rates: 611KB 438KB 557KB RX: 6.49MB 453KB 360KB 296KB 332KB TOTAL: 17.4MB 2.19MB 972KB 735KB 889KB另外，在nicstat、iftop命令不可用的情況下，也可以使用ifconfig + awk來查看網速，單位B/s，如下：
$ while sleep 1;do ifconfig;done|awk -v RS= 'match($0,/^(\w+):.*RX.*bytes ([0-9]+).*TX.*bytes ([0-9]+)/,a){eth=a[1];if(s[eth][1])print a[1],a[2]-s[eth][2],a[3]-s[eth][3];for(k in a)s[eth][k]=a[k]}'eth0 294873 353037 lo 2229 2229 eth0 613730 666086 lo 17981 17981 eth0 317336 544921 lo 5544 5544 eth0 237694 516947 lo 2256 2256全能觀測工具
sar
sar是一個幾乎全能的觀測工具，它可以觀測CPU、內存、磁盤、網絡等等，不像上面的命令，只是側重某一方面，正因為它如此強大，掌握起來也要難得多，它的常見用法如下：
# cpu使用率 sar -u ALL 1 # 運行隊列與負載 sar -q 1 # 中斷次數 sar -I SUM 1 # 進程創建次數與線程上下文切換次數 sar -w 1 # 內存使用、臟頁與slab sar -r ALL 1 # 缺頁與內存頁掃描 sar -B 1 # 內存swap使用 sar -S 1 1 sar -W 1 # 磁盤IOPS sar -dp 1 # 文件描述符與打開終端數 sar -v 1 1 # 網卡層使用率 sar -n DEV 1 # tcp層收包發包情況 sar -n TCP,ETCP 1 # socket使用情況 sar -n SOCK 1這只是列出了sar的一部分用法，實際上sar可以觀測到非常多的內容，具體可以man sar查看。
dstat
bpytop
軟件資源觀測
線程
# 查看各java進程的線程數量$ ps -o pid,nlwp -C javaPID NLWP2121 21# 查看java各線程CPU、內存使用情況$ top -H -p `pgrep -n java`網絡連接
netstat是用來查看網絡連接信息的工具命令，具體來說，像在編程語言中可以通過創建socket來建立網絡連接，而netstat就是用來查看這些socket信息的，如下：
# 查看所有的socket，-n代表不解析ip為主機名，-a表示all所有，-t代表tcp$ netstat -nat# 顯示各狀態socket數量，TIME_WAIT與CLOSE_WAIT數量太多，一般都不是好事情$ netstat -nat | awk '/tcp/{print $6}'|sort|uniq -c21 ESTABLISHED3 TIME_WAIT3 CLOSE_WAIT2 LISTEN# 查看LISTEN狀態的socket，-l代表只顯示LISTEN狀態的$ netstat -nltActive Internet connections (only servers)Proto Recv-Q Send-Q Local Address Foreign Address Statetcp 0 0 0.0.0.0:8888 0.0.0.0:* LISTENtcp6 0 0 :::8888 :::* LISTEN# 查看進程867的socket數量，-p顯示出創建網絡連接的進程號$ netstat -natp|grep -w 867 -c2# 找到監聽在8888端口的進程$ netstat -nltp|grep -w 8888tcp 0 0 0.0.0.0:8888 0.0.0.0:* LISTEN 867/ncattcp6 0 0 :::8888 :::* LISTEN 867/ncatjvm觀測工具
jstack
jstack是JVM下的線程剖析工具，可以打印出當前時刻各線程的調用棧，這樣就可以了解到jvm中各線程都在干什么了，如下：
$ jstack 3051 2021-11-07 21:55:06 Full thread dump OpenJDK 64-Bit Server VM (11.0.12+7 mixed mode):Threads class SMR info: _java_thread_list=0x00007f3380001f00, length=10, elements={ 0x00007f33cc027800, 0x00007f33cc22f800, 0x00007f33cc233800, 0x00007f33cc24b800, 0x00007f33cc24d800, 0x00007f33cc24f800, 0x00007f33cc251800, 0x00007f33cc253800, 0x00007f33cc303000, 0x00007f3380001000 }"main" 1 prio=5 os_prio=0 cpu=2188.06ms elapsed=1240974.04s tid=0x00007f33cc027800 nid=0xbec runnable [0x00007f33d1b68000]java.lang.Thread.State: RUNNABLEat java.io.FileInputStream.readBytes(java.base@11.0.12/Native Method)at java.io.FileInputStream.read(java.base@11.0.12/FileInputStream.java:279)at java.io.BufferedInputStream.read1(java.base@11.0.12/BufferedInputStream.java:290)at java.io.BufferedInputStream.read(java.base@11.0.12/BufferedInputStream.java:351)- locked <0x00000007423a5ba8> (a java.io.BufferedInputStream)at sun.nio.cs.StreamDecoder.readBytes(java.base@11.0.12/StreamDecoder.java:284)at sun.nio.cs.StreamDecoder.implRead(java.base@11.0.12/StreamDecoder.java:326)at sun.nio.cs.StreamDecoder.read(java.base@11.0.12/StreamDecoder.java:178)- locked <0x0000000745ad1cf0> (a java.io.InputStreamReader)at java.io.InputStreamReader.read(java.base@11.0.12/InputStreamReader.java:181)at java.io.Reader.read(java.base@11.0.12/Reader.java:189)at java.util.Scanner.readInput(java.base@11.0.12/Scanner.java:882)at java.util.Scanner.findWithinHorizon(java.base@11.0.12/Scanner.java:1796)at java.util.Scanner.nextLine(java.base@11.0.12/Scanner.java:1649)at com.example.clientserver.ClientServerApplication.getDemo(ClientServerApplication.java:57)at com.example.clientserver.ClientServerApplication.run(ClientServerApplication.java:40)at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:804)at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:788)at org.springframework.boot.SpringApplication.run(SpringApplication.java:333)at org.springframework.boot.SpringApplication.run(SpringApplication.java:1309)at org.springframework.boot.SpringApplication.run(SpringApplication.java:1298)at com.example.clientserver.ClientServerApplication.main(ClientServerApplication.java:27)at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.12/Native Method)at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.12/NativeMethodAccessorImpl.java:62)at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.12/DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(java.base@11.0.12/Method.java:566)at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49)at org.springframework.boot.loader.Launcher.launch(Launcher.java:107)at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:88)"Reference Handler" 2 daemon prio=10 os_prio=0 cpu=2.76ms elapsed=1240973.97s tid=0x00007f33cc22f800 nid=0xbf3 waiting on condition [0x00007f33a820a000]java.lang.Thread.State: RUNNABLEat java.lang.ref.Reference.waitForReferencePendingList(java.base@11.0.12/Native Method)at java.lang.ref.Reference.processPendingReferences(java.base@11.0.12/Reference.java:241)at java.lang.ref.Reference$ReferenceHandler.run(java.base@11.0.12/Reference.java:213)實例：找占用CPU較高問題代碼
如果你發現你的java進程CPU占用一直都很高，可以用如下方法找到問題代碼：
1，找出占用cpu的線程號pid
# -H表示看線程，其中312是java進程的pid $ top -H -p 3122，轉換線程號為16進制
# 其中62是從top中獲取的高cpu的線程pid $ printf "%x" 314 13a3，獲取進程中所有線程棧，提取對應高cpu線程棧
$ jstack 312 | awk -v RS= '/0x13a/'通過這種方法，可以很容易找到類似大循環或死循環之類性能極差的代碼。
實例：棧統計
一般來說，jstack配合top只能定位類似死循環這種非常嚴重的性能問題，由于cpu速度太快了，對于性能稍差但又不非常差的代碼，單次jstack很難從線程棧中捕捉到問題代碼。
因為性能稍差的代碼可能只會比好代碼多耗1ms的cpu時間，但這1ms就比我們的手速快多了，當執行jstack時線程早已執行到非問題代碼了。
既然手動執行jstack不行，那就讓腳本來，快速執行jstack多次，雖然問題代碼對于人來說執行太快，但對于正常代碼來說，它還是慢一些的，因此當我快速捕捉多次線程棧時，問題代碼出現的次數肯定比正常代碼出現的次數要多。
# 每0.2s執行一次jstack，并將線程棧數據保存到jstacklog.log $ while sleep 0.2;do \ pid=$(pgrep -n java); \ [[ $pid ]] && jstack $pid; \ done > jstacklog.log$ wc -l jstacklog.log 291121 jstacklog.log抓了這么多線程棧，如何分析呢？我們可以使用linux中的文本命令來處理，按線程棧分組計數即可，如下：
$ cat jstacklog.log \ |sed -E -e 's/0x[0-9a-z]+/0x00/g' -e '/^"/ s/[0-9]+/n/g' \ |awk -v RS="" 'gsub(/\n/,"\\n",$0)||1' \ |sort|uniq -c|sort -nr \ |sed 's/$/\n/;s/\\n/\n/g' \ |less出現次數最多的線程棧，大概率就是性能不佳或阻塞住的代碼，上圖中com.example.demo.web.controller.TestController.select方法棧抓取到2053次，是因為我一直在壓測這一個接口，所以它被抓出來最多。
實例：火焰圖
可以發現，用文本命令分析線程棧并不直觀，好在性能優化大師Brendan Gregg發明了火焰圖，并開發了一套火焰圖生成工具。
工具下載地址：https://github.com/brendangregg/FlameGraph
將jstack抓取的一批線程棧，生成一個火焰圖，如下：
$ cat jstacklog.log \| ./FlameGraph/stackcollapse-jstack.pl --no-include-tname \| ./FlameGraph/flamegraph.pl --cp > jstacklog.svg如上，生成的火焰圖是svg文件，使用瀏覽器打開即可，在火焰圖中，顏色并沒有實際含義，它將相同的線程棧聚合在一起顯示，因此，圖中越寬的棧表示此棧在運行過程中，被抓取到的次數越多，也是我們需要重點優化的地方。
jmap
jmap是JVM下的內存剖析工具，用來分析或導出JVM堆數據，如下：
# 查看對象分布直方圖，其中3051是java進程的pid $ jmap -histo:live 3051 | head -n20num instances bytes class name (module) -------------------------------------------------------1: 19462 1184576 [B (java.base@11.0.12)2: 3955 469920 java.lang.Class (java.base@11.0.12)3: 18032 432768 java.lang.String (java.base@11.0.12)4: 11672 373504 java.util.concurrent.ConcurrentHashMap$Node (java.base@11.0.12)5: 3131 198592 [Ljava.lang.Object; (java.base@11.0.12)6: 5708 182656 java.util.HashMap$Node (java.base@11.0.12)7: 1606 155728 [I (java.base@11.0.12)8: 160 133376 [Ljava.util.concurrent.ConcurrentHashMap$Node; (java.base@11.0.12)9: 1041 106328 [Ljava.util.HashMap$Node; (java.base@11.0.12)10: 6216 99456 java.lang.Object (java.base@11.0.12)11: 1477 70896 sun.util.locale.LocaleObjectCache$CacheEntry (java.base@11.0.12)12: 1403 56120 java.util.LinkedHashMap$Entry (java.base@11.0.12)13: 1322 52880 java.lang.ref.SoftReference (java.base@11.0.12)14: 583 51304 java.lang.reflect.Method (java.base@11.0.12)15: 999 47952 java.lang.invoke.MemberName (java.base@11.0.12)16: 29 42624 [C (java.base@11.0.12)17: 743 41608 java.util.LinkedHashMap (java.base@11.0.12)18: 877 35080 java.lang.invoke.MethodType (java.base@11.0.12)也可以直接將整個堆內存轉儲為文件，如下：
$ jmap -dump:format=b,file=heap.hprof 3456 Heap dump file created$ ls *.hprof heap.hprof堆轉儲文件是二進制文件，沒法直接查看，一般是配合mat(Memory Analysis Tool)等堆可視化工具來進行分析，如下：
mat打開hprof文件后，會看下如下一個概要界面。
點擊Histogram可以按類維度查詢內存占用大小
點擊Dominator Tree可以看到各對象總大小(Retained Heap，包含引用的子對象)，以及所占內存比例，可以看到一個ArrayList對象占用99.31%，看來是個bug，找到創建ArrayList的代碼，修改即可。
可以看到，使用jmap+mat很容易分析內存泄露bug，但需要注意的是，jmap執行時會讓jvm暫停，對于高并發的服務，最好先將問題節點摘除流量后再操作。
另外，可以在jvm上添加參數-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=./dump/，使得在發生內存溢出時，自動生成堆轉儲文件到dump目錄。
mat下載地址：http://www.eclipse.org/mat/
arthas
arthas是java下的一款動態追蹤工具，可以觀測到java方法的調用參數、返回值等，除此之外，還提供了很多實用功能，如反編譯、線程剖析、堆內存轉儲、火焰圖等。
下載與使用
# 下載arthas $ wget https://arthas.aliyun.com/download/3.4.6?mirror=aliyun -O arthas-packaging-3.4.6-bin.zip# 解壓 $ unzip arthas-packaging-3.4.6-bin.zip -d arthas && cd arthas/# 進入arthas命令交互界面 $ java -jar arthas-boot.jar `pgrep -n java` [INFO] arthas-boot version: 3.4.6 [INFO] arthas home: /home/work/arthas [INFO] Try to attach process 3368243 [INFO] Attach process 3368243 success. [INFO] arthas-client connect 127.0.0.1 3658,---. ,------. ,--------.,--. ,--. ,---. ,---./ O \ | .--. ''--. .--'| '--' | / O \ ' .-' | .-. || '--'.' | | | .--. || .-. |`. `-. | | | || |\ \ | | | | | || | | |.-' | `--' `--'`--' '--' `--' `--' `--'`--' `--'`-----'wiki https://arthas.aliyun.com/doc tutorials https://arthas.aliyun.com/doc/arthas-tutorials.html version 3.4.6 pid 3368243 time 2021-11-13 13:35:49# help可查看arthas提供了哪些命令 [arthas@3368243]$ help # help watch可查看watch命令具體用法 [arthas@3368243]$ help watchwatch、trace與stack
在arthas中，使用watch、trace、stack命令可以觀測方法調用情況，如下：
# watch觀測執行的查詢SQL，-x 3指定對象展開層級 [arthas@3368243]$ watch org.apache.ibatis.executor.statement.PreparedStatementHandler parameterize '{target.boundSql.sql,target.boundSql.parameterObject}' -x 3 method=org.apache.ibatis.executor.statement.PreparedStatementHandler.parameterize location=AtExit ts=2021-11-13 14:50:34; [cost=0.071342ms] result=@ArrayList[@String[select id,log_info,create_time,update_time,add_time from app_log where id=?],@ParamMap[@String[id]:@Long[41115],@String[param1]:@Long[41115],], ]# watch觀測耗時超過200ms的SQL [arthas@3368243]$ watch com.mysql.jdbc.PreparedStatement execute '{target.toString()}' 'target.originalSql.contains("select") && #cost > 200' -x 2 Press Q or Ctrl+C to abort. Affect(class count: 3 , method count: 1) cost in 123 ms, listenerId: 25 method=com.mysql.jdbc.PreparedStatement.execute location=AtExit ts=2021-11-13 14:58:42; [cost=1001.558851ms] result=@ArrayList[@String[com.mysql.jdbc.PreparedStatement@6283cfe6: select count(*) from app_log], ]# trace追蹤方法耗時，層層追蹤，就可找到耗時根因，--skipJDKMethod false顯示jdk方法耗時，默認不顯示 [arthas@3368243]$ trace com.mysql.jdbc.PreparedStatement execute 'target.originalSql.contains("select") && #cost > 200' --skipJDKMethod false Press Q or Ctrl+C to abort. Affect(class count: 3 , method count: 1) cost in 191 ms, listenerId: 26 ---ts=2021-11-13 15:00:40;thread_name=http-nio-8080-exec-47;id=76;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@5a2d131d---[1001.465544ms] com.mysql.jdbc.PreparedStatement:execute()+---[0.022119ms] com.mysql.jdbc.PreparedStatement:checkClosed() #1274+---[0.016294ms] com.mysql.jdbc.MySQLConnection:getConnectionMutex() #57+---[0.017862ms] com.mysql.jdbc.PreparedStatement:checkReadOnlySafeStatement() #1278+---[0.008996ms] com.mysql.jdbc.PreparedStatement:createStreamingResultSet() #1294+---[0.010783ms] com.mysql.jdbc.PreparedStatement:clearWarnings() #1296+---[0.017843ms] com.mysql.jdbc.PreparedStatement:fillSendPacket() #1316+---[0.008543ms] com.mysql.jdbc.MySQLConnection:getCatalog() #1320+---[0.009293ms] java.lang.String:equals() #57+---[0.008824ms] com.mysql.jdbc.MySQLConnection:getCacheResultSetMetadata() #1328+---[0.009892ms] com.mysql.jdbc.MySQLConnection:useMaxRows() #1354+---[1001.055229ms] com.mysql.jdbc.PreparedStatement:executeInternal() #1379+---[0.02076ms] com.mysql.jdbc.ResultSetInternalMethods:reallyResult() #1388+---[0.011517ms] com.mysql.jdbc.MySQLConnection:getCacheResultSetMetadata() #57+---[0.00842ms] com.mysql.jdbc.ResultSetInternalMethods:getUpdateID() #1404---[0.008112ms] com.mysql.jdbc.ResultSetInternalMethods:reallyResult() #1409# stack追蹤方法調用棧，找到耗時SQL來源 [arthas@3368243]$ stack com.mysql.jdbc.PreparedStatement execute 'target.originalSql.contains("select") && #cost > 200' Press Q or Ctrl+C to abort. Affect(class count: 3 , method count: 1) cost in 138 ms, listenerId: 27 ts=2021-11-13 15:01:55;thread_name=http-nio-8080-exec-5;id=2d;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@5a2d131d@com.mysql.jdbc.PreparedStatement.execute()at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:493)at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:63)at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:63)at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:326)at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:136)at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:77)at sun.reflect.GeneratedMethodAccessor75.invoke(null:-1)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:498)at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)at com.sun.proxy.$Proxy113.selectOne(null:-1)at org.mybatis.spring.SqlSessionTemplate.selectOne(SqlSessionTemplate.java:166)at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:83)at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)at com.sun.proxy.$Proxy119.selectCost(null:-1)at com.demo.example.web.controller.TestController.select(TestController.java:57)可以看到watch、trace、stack命令中都可以指定條件表達式，只要滿足ognl表達式語法即可，ognl完整語法很復雜，如下是一些經常使用的：
ognl
通過ognl命令，可直接查看靜態變量的值，如下：
# 調用System.getProperty靜態函數，查看jvm默認字符編碼 [arthas@3368243]$ ognl '@System@getProperty("file.encoding")' @String[UTF-8]# 找到springboot類加載器 [arthas@3368243]$ classloader -t +-BootstrapClassLoader +-sun.misc.Launcher$ExtClassLoader@492691d7+-sun.misc.Launcher$AppClassLoader@764c12b6+-org.springframework.boot.loader.LaunchedURLClassLoader@4361bd48# 獲取springboot中所有的beanName，-c指定springboot的classloader的hash值 # 一般Spring項目，都會定義一個SpringUtil的，用于獲取bean容器ApplicationContext [arthas@3368243]$ ognl -c 4361bd48 '#context=@com.demo.example.web.SpringUtil@applicationContext, #context.beanFactory.beanDefinitionNames' @String[][@String[org.springframework.context.annotation.internalConfigurationAnnotationProcessor],@String[org.springframework.context.annotation.internalAutowiredAnnotationProcessor],@String[org.springframework.context.annotation.internalCommonAnnotationProcessor],@String[testController],@String[apiController],@String[loginService],... ]# 獲取springboot配置，如server.port是配置http服務端口的 [arthas@3368243]$ ognl -c 4361bd48 '#context=@com.demo.example.web.SpringUtil@applicationContext, #context.getEnvironment().getProperty("server.port")' @String[8080]# 查看server.port定義在哪個配置文件中 # 可以很容易看到，server.port定義在application-web.yml [arthas@3368243]$ ognl -c 4361bd48 '#context=@com.demo.example.web.SpringUtil@applicationContext, #context.environment.propertySources.propertySourceList.{? containsProperty("server.port")}' @ArrayList[@ConfigurationPropertySourcesPropertySource[ConfigurationPropertySourcesPropertySource {name='configurationProperties'}],@OriginTrackedMapPropertySource[OriginTrackedMapPropertySource {name='applicationConfig: [classpath:/application-web.yml]'}], ]# 調用springboot中bean的方法，獲取返回值 [arthas@3368243]$ ognl -c 4361bd48 '#context=@com.demo.example.web.SpringUtil@applicationContext, #context.getBean("demoMapper").queryOne(12)' -x 2 @ArrayList[@HashMap[@String[update_time]:@Timestamp[2021-11-09 18:38:13,000],@String[create_time]:@Timestamp[2021-04-17 15:52:55,000],@String[log_info]:@String[TbTRNsh2SixuFrkYLTeb25a6zklEZj0uWANKRMe],@String[id]:@Long[12],@String[add_time]:@Integer[61],], ]# 查看springboot自帶tomcat的線程池的情況 [arthas@3368243]$ ognl -c 4361bd48 '#context=@com.demo.example.web.SpringUtil@applicationContext, #context.webServer.tomcat.server.services[0].connectors[0].protocolHandler.endpoint.executor' @ThreadPoolExecutor[sm=@StringManager[org.apache.tomcat.util.res.StringManager@16886f49],submittedCount=@AtomicInteger[1],threadRenewalDelay=@Long[1000],workQueue=@TaskQueue[isEmpty=true;size=0],mainLock=@ReentrantLock[java.util.concurrent.locks.ReentrantLock@69e9cf90[Unlocked]],workers=@HashSet[isEmpty=false;size=10],largestPoolSize=@Integer[49],completedTaskCount=@Long[10176],threadFactory=@TaskThreadFactory[org.apache.tomcat.util.threads.TaskThreadFactory@63c03c4f],handler=@RejectHandler[org.apache.tomcat.util.threads.ThreadPoolExecutor$RejectHandler@3667e559],keepAliveTime=@Long[60000000000],allowCoreThreadTimeOut=@Boolean[false],corePoolSize=@Integer[10],maximumPoolSize=@Integer[8000], ]其它命令
arthas還提供了jvm大盤、線程剖析、堆轉儲、反編譯、火焰圖等功能，如下：
# 顯示耗cpu較多的前4個線程 [arthas@3368243]$ thread -n 4 "C2 CompilerThread0" [Internal] cpuUsage=8.13% deltaTime=16ms time=46159ms"C2 CompilerThread1" [Internal] cpuUsage=4.2% deltaTime=8ms time=47311ms"C1 CompilerThread2" [Internal] cpuUsage=3.06% deltaTime=6ms time=17402ms"http-nio-8080-exec-40" Id=111 cpuUsage=1.29% deltaTime=2ms time=624ms RUNNABLE (in native)at java.net.SocketInputStream.socketRead0(Native Method)...at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4113)at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2570)at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2731)at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2818)...at com.demo.example.web.controller.TestController.select(TestController.java:57)# 堆轉儲 [arthas@3368243]$ heapdump Dumping heap to /tmp/heapdump2021-11-13-15-117226383240040009563.hprof ... Heap dump file created# cpu火焰圖，容器環境下profiler start可能用不了，可用profiler start -e itimer替代 [arthas@3368243]$ profiler start Started [cpu] profiling [arthas@3368243]$ profiler stop OK profiler output file: /home/work/app/arthas-output/20211113-151208.svg# dashboard就類似Linux下的top一樣，可看jvm線程、堆內存的整體情況 [arthas@3368243]$ dashboard# jvm就類似Linux下的ps一樣，可以看jvm進程的一些基本信息，如：jvm參數、類加載、線程數、打開文件描述符數等 [arthas@3368243]$ jvm# 反編譯 [arthas@3368243]$ jad com.demo.example.web.controller.TestController可見，arthas已經不是一個單純的動態追蹤工具了，它把jvm下常用的診斷功能幾乎全囊括了。
相關項目地址：
https://arthas.aliyun.com/doc/index.html
https://github.com/jvm-profiling-tools/async-profiler
系統調用觀測
strace
strace是Linux中用來觀測系統調用的工具，學過操作系統原理都知道，操作系統向應用程序暴露了一批系統調用接口，應用程序只能通過這些系統調用接口來訪問操作系統，比如申請內存、文件或網絡io操作等。
用法如下：
# -T 打印系統調用花費的時間 # -tt 打印系統調用的時間點 # -s 輸出的最大長度，默認32，對于調用參數較長的場景，建議加大 # -f 是否追蹤fork出來子進程的系統調用，由于服務端服務普通使用線程池，建議加上 # -p 指定追蹤的進程pid # -o 指定追蹤日志輸出到哪個文件，不指定則直接輸出到終端 $ strace -T -tt -f -s 200 -p 87 -o strace.log實例：抓取實際發送的SQL
有些時候，我們會發現代碼中完全沒問題的SQL，卻查不到數據，這極有可能是由于項目中一些底層框架改寫了SQL，導致真實發送的SQL與代碼中的SQL不一樣。
遇到這種情況，先別急著扒底層框架代碼，那樣會比較花時間，畢竟程序員的時間很寶貴，不然要加更多班的，怎么快速確認是不是這個原因呢？
有兩種方法，第一種是使用wireshark抓包，第二種就是本篇介紹的strace了，由于程序必然要通過網絡io相關的系統調用，將SQL命令發送到數據庫，因此我們只需要用strace追蹤所有系統調用，然后grep出發送SQL的系統調用即可，如下：
$ strace -T -tt -f -s 200 -p 52 |& tee strace.log從圖中可以清晰看到，mysql的jdbc驅動是通過sendto系統調用來發送SQL，通過recvfrom來獲取返回結果，可以發現，由于SQL是字符串，strace自動幫我們識別出來了，而返回結果因為是二進制的，就不容易識別了，需要非常熟悉mysql協議才行。
另外，從上面其實也很容易看出SQL執行耗時，計算相同線程號的sendto與recvfrom之間的時間差即可。
內核觀測工具
perf
perf是Linux官方維護的性能分析工具，它可以觀測很多非常細非常硬核的指標，如IPC，cpu緩存命中率等，如下：
# ubuntu安裝perf，包名和內核版本相關，可以直接輸入perf命令會給出安裝提示 sudo apt install linux-tools-5.4.0-74-generic linux-cloud-tools-5.4.0-74-generic# cpu的上下文切換、cpu遷移、IPC、分支預測 sudo perf stat -a sleep 5 # cpu的IPC與緩存命中率 sudo perf stat -e cycles,instructions,cache-references,cache-misses,bus-cycles -a sleep 10 # cpu的1級數據緩存命中率 sudo perf stat -e L1-dcache-loads,L1-dcache-load-misses,L1-dcache-stores -a sleep 10 # 頁表緩存TLB命中率 sudo perf stat -e dTLB-loads,dTLB-load-misses,dTLB-prefetch-misses -a sleep 10 # cpu的最后一級緩存命中率 sudo perf stat -e LLC-loads,LLC-load-misses,LLC-stores,LLC-prefetches -a sleep 10# Count system calls by type for the specified PID, until Ctrl-C: sudo perf stat -e 'syscalls:sys_enter_*' -p PID -I1000 2>&1 | awk '$2 != 0' # Count system calls by type for the entire system, for 5 seconds: sudo perf stat -e 'syscalls:sys_enter_*' -a sleep 5 2>&1| awk '$1 != 0' # Count syscalls per-second system-wide: sudo perf stat -e raw_syscalls:sys_enter -I 1000 -aoncpu火焰圖
當然，它也可以用來抓取線程棧，并生成火焰圖，如下：
# 抓取60s的線程棧，其中1892是mysql的進程pid $ sudo perf record -F 99 -p 1892 -g sleep 60 [ perf record: Woken up 5 times to write data ] [ perf record: Captured and wrote 1.509 MB perf.data (6938 samples) ]# 生成火焰圖 $ sudo perf script \| ./FlameGraph/stackcollapse-perf.pl \| ./FlameGraph/flamegraph.pl > mysqld_flamegraph.svg如上所示，使用perf生成的mysql的火焰圖，perf抓取線程棧相比jstack的優點是，抓取精度比jstack更高，運行開銷比jstack更小，并且還可以抓到Linux內核調用棧！
注：perf抓取線程棧，是順著cpu上的棧寄存器找到當前線程的調用棧的，因此它只能抓到當前正在cpu上運行線程的線程棧，因此通過perf可以非常容易做oncpu分析，分析high cpu問題。offcpu火焰圖
線程在運行的過程中，要么在CPU上執行，要么被鎖或io操作阻塞，從而離開CPU進去睡眠狀態，待被解鎖或io操作完成，線程會被喚醒而變成運行態。
如下：
當線程在cpu上運行時，我們稱其為oncpu，當線程阻塞而離開cpu后，稱其為offcpu。
如果當線程在睡眠之前記錄一下當前時間，然后被喚醒時記錄當前線程棧與阻塞時間，再使用FlameGraph工具將線程棧繪制成一張火焰圖，這樣我們就得到了一張offcpu火焰圖，火焰圖寬的部分就是線程阻塞較多的點了，這就需要再介紹一下bcc工具了。
bcc
bcc是使用Linux ebpf機制實現的一套工具集，包含非常多的底層分析工具，如查看文件緩存命中率，tcp重傳情況，mysql慢查詢等等。
它還可以做offcpu分析，生成offcpu火焰圖，如下：
# ubuntu安裝bcc工具集 $ sudo apt install bpfcc-tools # 使用root身份進入bash $ sudo bash # 獲取jvm函數符號信息 $ ./FlameGraph/jmaps # 抓取offcpu線程棧30s，83101是mysqld的進程pid $ offcputime-bpfcc -df -p 83101 30 > offcpu_stack.out # 生成offcpu火焰圖 $ cat offcpu_stack.out \| sed 's/;::/:::/g' \| ./FlameGraph/flamegraph.pl --color=io --title="Off-CPU Time Flame Graph" --countname=us > offcpu_stack.svg如上圖，我繪制了一張mysql的offcpu火焰圖，可以發現大多數線程的offcpu都是由鎖引起的，另外，offcpu火焰圖與oncpu火焰圖稍有不同，oncpu火焰圖寬度代表線程棧出現次數，而offcpu火焰圖寬度代表線程棧阻塞時間。
bcc項目地址：https://github.com/iovisor/bcc
bpftrace
arthas只能追蹤java程序，對于原生程序(如MySQL)就無能為力了，好在Linux生態提供了大量的機制以及配套工具，可用于追蹤原生程序的調用，如perf、bpftrace、systemtap等，由于bpftrace使用難度較小，本篇主要介紹它的用法。
bpftrace是基于ebpf技術實現的動態追蹤工具，它對ebpf技術進行封裝，實現了一種腳本語言，就像上面介紹的arthas基于ognl一樣，它實現的腳本語言類似于awk，封裝了常見語句塊，并提供內置變量與內置函數，如下：
$ sudo bpftrace -e 'BEGIN { printf("Hello, World!\n"); } ' Attaching 1 probe... Hello, World!實例：在調用端追蹤慢SQL
前面我們用strace追蹤過mysql的jdbc驅動，它使用sendto與recvfrom系統調用來與mysql服務器通信，因此，我們在sendto調用時，計下時間點，然后在recvfrom結束時，計算時間之差，就可以得到相應SQL的耗時了，如下：
- 先找到sendto與recvfrom系統調用在bpftrace中的追蹤點，如下：
- 編寫追蹤腳本trace_slowsql_from_syscall.bt，腳本代碼如下：
其中，comm表示進程名稱，tid表示線程號，@query[tid]與@start[tid]類似map，以tid為key的話，這個變量就像一個線程本地變量了。
3. 調用上面的腳本，可以看到各SQL執行耗時，如下：
$ sudo BPFTRACE_STRLEN=80 bpftrace trace_slowsql_from_syscall.bt Attaching 3 probes... Tracing jdbc SQL slower than 0 ms by sendto/recvfrom syscall TIME(ms) PID MS QUERY 6398 3368243 125 select sleep(0.1) 16427 3368243 22 select id from app_log al order by id desc limit 1 16431 3368243 20 select id,log_info,create_time,update_time,add_time from app_log where id=11692 17492 3368243 21 select id,log_info,create_time,update_time,add_time from app_log where id=29214實例：在服務端追蹤慢SQL
從調用端來追蹤SQL耗時，會包含網絡往返時間，為了得到更精確的SQL耗時，我們可以寫一個追蹤服務端mysql的腳本，來觀測SQL耗時，如下：
- 確定mysqld服務進程的可執行文件與入口函數
- 使用uprobe追蹤dispatch_command的調用，如下：
追蹤腳本整體上與之前系統調用版本的類似，不過追蹤點不一樣而已。
實例：找出掃描大量行的SQL
眾所周知，SQL執行時需要掃描數據，并且掃描的數據越多，SQL性能就會越差。
但對于一些中間情況，SQL掃描行數不多也不少，如2w條。且這2w條數據都在緩存中的話，SQL執行時間不會很長，導致沒有記錄在慢查詢日志中，但如果這樣的SQL并發量大起來的話，會非常耗費CPU。
對于mysql的話，掃描行的函數是row_search_mvcc，如果你經常抓取mysql棧的話，很容易發現這個函數，如下：
mysql每掃一行調用一次row_search_mvcc，如果在追蹤腳本中追蹤此函數，記錄下調用次數，就可以觀測SQL的掃描行數了，如下：
#!/usr/bin/bpftrace BEGIN{printf("Tracing mysqld SQL scan row than %d. Ctrl-C to end.\n", $1);printf("%-10s %-6s %6s %10s %s\n", "TIME(ms)", "PID", "MS", "SCAN_NUM", "QUERY"); } uprobe:/usr/local/mysql/bin/mysqld:*dispatch_command*{$COM_QUERY = (uint8)3;if (arg2 == $COM_QUERY) {@query[tid] = str(*arg1);@start[tid] = nsecs;} } uprobe:/usr/local/mysql/bin/mysqld:*row_search_mvcc*{@scan_num[tid]++; } uretprobe:/usr/local/mysql/bin/mysqld:*dispatch_command* /@start[tid]/{$dur = (nsecs - @start[tid]) / 1000000;if (@scan_num[tid] > $1) {printf("%-10u %-6d %6d %10d %s\n", elapsed / 1000000, pid, $dur, @scan_num[tid], @query[tid]);}delete(@query[tid]);delete(@start[tid]);delete(@scan_num[tid]); }腳本運行效果如下：
$ sudo BPFTRACE_STRLEN=80 bpftrace trace_mysql_scan.bt 200 Attaching 4 probes... Tracing mysqld SQL scan row than 200. Ctrl-C to end. TIME(ms) PID MS SCAN_NUM QUERY 150614 1892 4 300 select * from app_log limit 300# 全表掃描，慢！ 17489 1892 424 43717 select count(*) from app_log # 大范圍索引掃描，慢！ 193013 1892 253 20000 select count(*) from app_log where id < 20000 # 深分頁，會查詢前20300條，取最后300條，慢！ 213395 1892 209 20300 select * from app_log limit 20000,300 # 索引效果不佳，雖然只會查到一條數據，但掃描數據量不會少，慢！ 430374 1892 186 15000 select * from app_log where id < 20000 and seq = 15000 limit 1如上所示，app_log是我建的一張測試表，共43716條數據，其中id字段是自增主鍵，seq值與id值一樣，但沒有索引。
可以看到上面的幾個場景，不管什么場景，只要掃描行數變大，耗時就會變長，但也都沒有超過500毫秒的，原因是這個表很小，數據可以全部緩存在內存中。
可見，像bpftrace這樣的動態追蹤工具是非常強大的，而且比arthas更加靈活，arthas只能追蹤單個函數，而bpftrace可以跨函數追蹤。
bpftrace使用手冊：https://github.com/iovisor/bpftrace/blob/master/docs/reference_guide.md
抓包工具
ngrep
ngrep也是一款抓包工具，它將包數據以文本形式直接顯示出來，對于簡單場景的抓包，不需要wireshark配合，如下：
抓HTTP請求
ngrep -W byline port 8080抓取查詢SQL
ngrep -W byline 'select' port 4578tcpdump
tcpdump是一個通用抓包工具，一般用它來抓網絡包數據，然后再使用wireshark分析，如下：
抓取3961端口網絡包
tcpdump tcp -i eth0 -s 0 -c 10000 and port 3764 -w ./target.capwireshark分析
將target.cap導入到wireshark分析。
查看某一具體sql的網絡包交互情況，如下：
a. 先Decode相應端口使用MySQL協議解析：
b. 如下，輸入mysql.query contains "5211117719406053"，查看SQL中包含單號5211117719406053的數據包：
抓包如何判斷是網絡慢還是后端處理慢？
為方便分析耗時，一般建議在wireshark上再添加如下兩列：
- tcpDelta = tcp.time_delta，表示在當前tcp連接中，當前包相對上一個包的時間差。
- ack_rtt = tcp.analysis.ack_rtt，表示tcp中的ack包，相對其數據包的時間差。
如下，找耗時最大的包：發現對于select t2.data as sapCustomerCode,t1.uniquecode as uniquecode from ...這條SQL，服務端回復ack很快，而在回復數據包時變慢，說明是慢在MySQL處理上，而非網絡里，因為如果網絡慢的話，ack應該也會變慢。
觀測工具總結
命令可用情況
由于應用系統一般部署在Neo容器環境中，權限這一塊是受限的，在Neo環境中上述各工具命令的可用情況如下：
| 命令 | 是否可用 | 描述 |
| vmstat、mpstat、free | 可用 | |
| top、pidstat、iostat | 可用 | |
| iotop | 不可用 | 權限問題，執行會報錯 |
| nicstat、iftop、sar、dstat | 可用 | |
| jstack、jmap、arthas | 可用 | |
| strace | 可用 | |
| ngrep、tcpdump | 可用 | |
| perf、bcc、bpftrace | 不可用 | 需要CAP_SYS_ADMIN權限，Neo沒有授權此權限給業務容器 |
思考：問題偶現或已經發生過了，怎么辦？
上面使用各種工具排查問題，都是建立在問題正在發生的場景下，如果問題偶然出現，或已經發生完了，由于問題現場已經消失，使用命令工具就不太好使了。
這種情況的問題排查，比較依賴于系統的建設，訂單組這邊為方便解決這種問題，分別在如下幾個方面做了一些工作：
完善監控系統
完善各維度的監控系統，如：機器監控、線程池、連接池、JVM監控、數據庫監控等。
機器監控
主要監控硬件資源，如CPU、內存等，監控數據由Neo提供，可以理解為top命令數據被采集下來了。
線程池監控
對于服務端程序來說，線程是最重要的軟件資源之一，線程不夠了，程序啥事都沒法干了，這也是導致接口偶爾慢的主要原因之一。
連接池監控
對于服務端程序來說，數據庫連接也是最重要的軟件資源之一，連接不夠了，會導致線程阻塞，這也是導致接口偶爾慢的主要原因之一。
JVM監控
jvm監控，主要監控堆內存使用情況，以及gc情況，由于gc的不確定性，gc也是導致接口偶爾慢的主要原因之一，而如果是oom這種問題，則會導致整個系統停擺。
數據庫監控
業務監控
根據系統所支撐的業務流程，建設一些業務維度的監控面板。
短信預警
完善日志系統
日志有哪些？
nginx日志
如果你的服務前面有nginx，一定不要錯過了nginx日志的檢查。
access日志
像tomcat、resin等web服務器，都提供有接口訪問日志功能，記錄了請求時間、耗時等，強烈建議打開。
springboot開啟方法，application.yml文件中添加如下配置：
server:servlet:context-path: "/"tomcat:accesslog:enabled: truedirectory: /home/work/logs/applogs/oc-searchfile-date-format: .yyyy-MM-ddpattern: '%h %l %u %t "%r" %s %b %Dms "%{Referer}i" "%{User-Agent}i" "%{X-Request-ID}i" "%{X-Forwarded-For}i"'resin開啟方法，resin.xml中添加如下配置：
gc日志
對于有gc的服務，gc日志一定要配置上，加入如下JVM參數即可開啟：
-XX:-OmitStackTraceInFastThrow -Xloggc:/home/work/logs/applogs/gc-%t.log -XX:+PrintClassHistogram -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintAdaptiveSizePolicy -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/work/logs/applogs/dmesg
內核日志，一般建議排查問題沒有思路時，常規性的看一下這個日志。
# 像丟包、警告、錯誤等情況，內核會記錄下來 dmesg | tail -n100 # 如果你的進程莫名其妙掛掉了，很有可能是內存不足，內核殺死了你的服務進程 dmesg | grep -i kill應用日志
這個就是我們應用里面的slf4j、log4j等輸出的日志了。
慢查詢日志
日志格式規范
時間、日志級別、機器、線程、日志記錄器名、trace_id、耗時、業務操作名、單號、異常堆棧等
注意以下場景：
1、打印異常時，將全部異常棧打印出來，而不要只打印message
// 不推薦，這樣打印異常，會導致異常棧丟失，難以定位問題 log.error(e.getMessage); // 推薦寫法 log.error(orderId + "xxx處理失敗", e);// 不推薦，原始異常丟失 try{... }catch(Exception e){throw new BizException("xxx處理失敗"); } // 推薦寫法 try{... }catch(Exception e){throw new BizException("xxx處理失敗", e); }2、nginx傳遞的X-REQUEST-ID，直接記錄到日志中，便于追蹤
String logId = request.getHeader("X-REQUEST-ID"); log.info("logId:{}, {}訂單處理，耗時{}ms", logId, orderId, cost);//最好通過日志的MDC機制，統一在日志框架中記錄 MDC.put("traceId", logId);?日志分析常見思路
查找異常值
查看日志是否有高耗時操作，或是否出現java異常。
關聯分析
時間關聯性：比如在某一時刻耗時請求增加，看看相同時間cpu、內存、gc的情況。
線程關聯性：比如某一處理耗時增加，看看相同線程前后的日志是否有些不一樣的case。
調用關聯性：最常見的就是對比調用方與服務方相同trace_id的耗時情況，如果沒有傳遞trace_id，也可思考數據本身的關聯性，比如單號+時間這種，很多時候也能唯一確定一次調用。
分布情況
分析日志在時間、位置(機器,線程,接口,方法,錯誤碼)、耗時上的分布。
掛腳本
arthas后臺任務
arthas可以通過添加&符號，使命令運行在后臺模式，因此只需要添加條件，一段時間檢查結果即可。
# 添加后臺任務，監測慢查詢SQL [arthas@3368243]$ watch com.mysql.jdbc.PreparedStatement execute '{target.toString()}' 'target.originalSql.contains("select") && #cost > 2000' -x 2 > slow_sql.log &# 與shell類似，可以通過jobs查看后臺任務 [arthas@3368243]$ jobs定時檢測腳本
通過在機器上啟動一些定時腳本，定時檢測問題是否發生，如發生，則使用相關診斷命令并保存命令結果，如下：
# 當系統健康檢查失敗2次時，自動jstack while sleep 1;do res=$(curl 'http://localhost:8080/_health' --connect-timeout 2 --max-time 2 -sS 2>&1)[[ $res =~ "ok" ]] && ((fail_num=0)) || ((fail_num++))if [[ $fail_num -ge 2 ]];thenpid=$(pgrep -n java)jstack $pid >> jstack.log 2>&1fi done編碼規范
oom是魔鬼，系統一旦出現oom，會導致整個系統停擺，系統可用性迅速下降到接近0，為此，定下了2個專門的規范，盡量避免oom產生。
總結
如果一個偶現問題，分析下來沒有思路了，考慮一下是否可以完善一下監控系統或添加更詳細的日志，不要排查不出來，也不做進一步的輔助排查問題的嘗試。
其它命令
vmstat
vmstat全名是虛擬內存統計信息命令，看起來好像是用來觀測內存的，實際上cpu、內存、io資源它都能觀測。
$ vmstat -w 1 procs -----------------------memory---------------------- ---swap-- -----io---- -system-- --------cpu--------r b swpd free buff cache si so bi bo in cs us sy id wa st4 0 0 12531512 102680 274940 0 0 0 3 0 3 0 0 100 0 02 0 0 12531512 102680 274940 0 0 0 0 106 55 25 0 75 0 02 0 0 12531512 102680 274940 0 0 0 0 105 58 25 0 75 0 02 0 0 12531512 102680 274940 0 0 0 0 105 56 25 0 75 0 01s顯示一次，第一行是系統啟動以來的統計信息，一般可忽略不看，從第二行開始看即可。
- r：cpu運行隊列長度，即有多少線程等待操作系統調度運行，這可看做是cpu的飽和度指標，長時間處于高值一般都有問題。
- b: 不可中斷阻塞的線程數量，一般就是阻塞于io訪問的線程數量。
- swpd: 內存交換到磁盤的內存大小，單位kB
- free：剩余內存大小，單位kB
- buff: 用于buff的內存大小，單位kB
- cache：用于文件頁面緩存的內存大小，單位kB
- si：磁盤換入到內存的當前速度，單位kB/s
- so：內存換出到磁盤的當前速度，單位kB/s
- bi：每秒讀取的磁盤塊數量，單位blocks/s
- bo：每秒寫入的磁盤塊數量，單位blocks/s
- in：每秒中斷數量
- cs：每秒線程上下文切換次數
- us：cpu用戶態使用率
- sy：cpu內核態使用率
- id：cpu空閑率
- wa：等待I/O，線程被阻塞等待磁盤I/O時的CPU空閑時間占總時間的比例
- st：steal偷取，CPU在虛擬化環境下在其他租戶上的開銷
mpstat
mpstat是用來查看cpu上各個核的cpu使用率的，如下：
$ mpstat -P ALL 1 Linux 4.19.128-microsoft-standard (DESKTOP-GC9LLHC) 10/24/21 _x86_64_ (8 CPU)12:39:37 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle 12:39:38 all 24.57 0.00 0.00 0.00 0.00 1.72 0.00 0.00 0.00 73.71 12:39:38 0 0.00 0.00 0.00 0.00 0.00 12.28 0.00 0.00 0.00 87.72 12:39:38 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00 12:39:38 2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00 12:39:38 3 100.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 12:39:38 4 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00 12:39:38 5 100.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 12:39:38 6 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00 12:39:38 7 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00如上，可見3、5號核的cpu使用率基本滿載，而其它核非常空閑，這一般是由于程序多線程設計上有問題，導致某部分線程非常忙，另一部分線程沒事干，而mpstat就是用來觀測是否有這種cpu核負載不均的問題的。
pidstat
pidstat基本和top功能是類似的，不過它是非交互式的命令，一般作為top的補充使用，如下：
# 默認查看活動進程的cpu使用情況，加-t可以查看線程的 $ pidstat 1 13:32:45 UID PID %usr %system %guest %wait %CPU CPU Command 13:32:46 1000 3051 0.00 1.00 0.00 0.00 1.00 1 java 13:32:46 1000 3241 100.00 0.00 0.00 0.00 100.00 7 stress 13:32:46 1000 3242 100.00 0.00 0.00 0.00 100.00 5 stressAverage: UID PID %usr %system %guest %wait %CPU CPU Command Average: 1000 3051 0.00 0.33 0.00 0.00 0.33 - java Average: 1000 3241 100.00 0.00 0.00 0.00 100.00 - stress Average: 1000 3242 100.00 0.00 0.00 0.00 100.00 - stress# -w可以看線程上下文切換情況 # cswch/s：自愿上下文切換，比如等待io或鎖 # nvcswch/s：非自愿上下文切換，比如分給自己時間片用完了，一般需要關注這個，因為現在的程序大多是io密集型的，用完時間片的機會很少 $ pidstat -w 1 13:37:57 UID PID cswch/s nvcswch/s Command 13:37:58 1000 3299 1.00 0.00 pidstat13:37:58 UID PID cswch/s nvcswch/s Command 13:37:59 0 8 1.00 0.00 init 13:37:59 1000 9 1.00 0.00 wsltermd 13:37:59 1000 3299 1.00 0.00 pidstat# -v可以看運行進程的線程數與文件描述符數量 $ pidstat -v 1 01:41:34 PM UID PID threads fd-nr Command 01:41:35 PM 1000 876 95 177 java# -r可以看運行進程的內存使用情況以及缺頁情況 # minflt/s：輕微缺頁，一般不用太關注 # majflt/s：嚴重缺頁，一般意味著發生了swrap，量較大時需要關注 $ pidstat -r 1 02:07:24 PM UID PID minflt/s majflt/s VSZ RSS %MEM Command 02:07:25 PM 999 2786 2.00 0.00 52792 3140 0.08 redis-server 02:07:25 PM 1000 601098 1.00 0.00 13976 6296 0.16 sshd# -d可以看某個進程的io使用情況 $ pidstat -d 1 14:12:06 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 14:12:07 1000 3051 0.00 80.00 0.00 0 java 14:12:07 1000 3404 0.00 0.00 0.00 79 stressfree
其實上面的vmstat、top已經可以看到內存使用情況了，free命令更純粹一點，如下：
# 查看內存使用情況，-m以MB為單位，-g可以使其以GB為單位 $ free -mtotal used free shared buff/cache available Mem: 3907 1117 778 3 2012 2503 Swap: 1897 708 1189要特別注意里面的free、buff/cache以及available，如下：
- free：系統空閑內存，一般來說，隨著使用時間越來越長，Linux中free會越來越小，原因是Linux會把訪問的文件數據盡可能地緩存在內存中，以便下次讀取時能快速返回
- buff/cache：就是文件緩存到內存中所占內存的大小
- available：系統真正的可用內存，約等于free+buff/cache，所以系統內存是否足夠，你應該看available的值。
df
df命令可以很容易的看到文件系統的空間使用情況，如下：
$ df -h Filesystem Size Used Avail Use% Mounted on udev 1.9G 0 1.9G 0% /dev tmpfs 391M 2.7M 389M 1% /run /dev/sda1 276G 150G 115G 57% / tmpfs 2.0G 0 2.0G 0% /dev/shm tmpfs 5.0M 4.0K 5.0M 1% /run/lock/dev/sda1的Use%這一列可以看到磁盤使用了57%了。
nicstat
nicstat可以查看整個網卡的使用情況，如下：
$ nicstat -z 1Time Int rKB/s wKB/s rPk/s wPk/s rAvs wAvs %Util Sat 22:35:22 ens33 38.09 7.13 32.03 6.77 1217.8 1078.4 0.03 0.00 22:35:22 lo 0.07 0.07 0.36 0.36 207.6 207.6 0.00 0.00Time Int rKB/s wKB/s rPk/s wPk/s rAvs wAvs %Util Sat 22:35:23 ens33 0.27 0.56 3.99 4.99 69.50 114.0 0.00 0.00Time Int rKB/s wKB/s rPk/s wPk/s rAvs wAvs %Util Sat 22:35:24 ens33 0.21 0.34 3.00 3.00 72.67 116.7 0.00 0.00Time Int rKB/s wKB/s rPk/s wPk/s rAvs wAvs %Util Sat 22:35:25 ens33 0.28 0.33 4.00 3.00 70.50 111.3 0.00 0.00Time Int rKB/s wKB/s rPk/s wPk/s rAvs wAvs %Util Sat 22:35:26 ens33 0.34 0.34 5.00 3.00 69.20 116.7 0.00 0.00Time Int rKB/s wKB/s rPk/s wPk/s rAvs wAvs %Util Sat 22:35:27 ens33 0.28 0.33 4.00 3.00 70.50 111.3 0.00 0.00其中%Util就是網卡帶寬的使用率了。
分享一個快速查找「占用CPU較高問題代碼」的shell腳本：https://raw.githubusercontent.com/xiaoxi666/scripts/main/show-busy-java-threads。線上機器直接wget下載執行（sh show-busy-java-threads）即可。默認會輸出占用CPU最高的5個線程，也可自行設置參數。思路也是讓機器快速執行多條命令，代替人工操作。
?
PS：腳本源于開源項目GitHub - Wekoi/awesome-scripts: useful scripts for Linux op，里面還有不少其他好用的腳本，有需要的同學可參考使用。
總結
- 上一篇： 联想主板9针开关接线图_针式打印机不开机
- 下一篇： 常微分方程的解法 (二): 欧拉（Eul