JAVA優化篇 如何從茫茫日志中找到運行緩慢的線程

引入

　　JAVA提供了一些分析DUMP的工具，比如jmap，visualvm 等

　　JAVA還有尋找線程狀態的工具，jstack等

　　數據庫也有檢查連接數，連接狀態的命令，status，processlist等

　　代碼中也可以添加一些時間的信息，對比信息發現可優化的地方

　　但這些都不是今天要記錄的內容，今天要做的是使用一個比較暴力的方式查找出高並發模式下運行緩慢的線程

正文

　　寫高並發的時候經常會遇到的問題：

　　　　單獨觀察每個分支線程或者主線程時，都執行地非常快，但是總體上運行的TPS卻並不高，沒有達到期望的值

　　　　更換環境，或者調大運行內存和CPU后，情況仍然不見好轉

　　這時候有個辦法是，找出每個線程的運行過程，尋找出耗時較大的代碼段，再對代碼進行分析

　　腳本我已經寫好了：

#!/bin/bash
 parseLog(){
    ##初始值
    upLine="blank"
    last_time_pre="blank"
    last_time_post="blank"
    cat "$1" | while read line
        do
          time_pre=`echo "$line" | awk '{print$1}'`
          time_post=`echo "$line" | awk '{print$2}'`
          if [[ `echo "$time_post" | grep ":"` != "" ]]
            then
            if [[ "$upLine" == "blank" ]]
            then
              upLine=${line}
              last_time_pre=`echo "$line" | awk '{print$1}'`
              last_time_post=`echo "$line" | awk '{print$2}'`
              total2="$last_time_pre"" $last_time_post"
              last_time_pre=`date +%s -d "$total2"` 
              last_time_pre=`expr "$last_time_pre" \* 1000`
              last_time_post=`echo ${last_time_post:9:3}`
            else
              total="$time_pre"" $time_post"
              time_pre=`date +%s -d "$total"`
              time_pre=`expr "$time_pre" \* 1000`
              time_post=`echo ${time_post:9:3}`
              time_end=`expr "$time_pre" + "$time_post"`
              time_begin=`expr "$last_time_pre" + "$last_time_post" + "$2"`
              last_time_pre=${time_pre}
              last_time_post=${time_post}
              if [[ "$time_end" -gt "$time_begin" ]]
                then
                    echo ${upLine} >> result.log
                    echo ${line} >> result.log
              fi
              upLine=${line}
            fi
          fi
        done
}


if [[ ! -n "$1" ]] || [[ ! -n "$2" ]] || [[ ! -n "$3" ]]
  then
    echo [log file] [interval millis] [key words]
    exit
fi


awk '{num[$4]++} 
      END{for(k in num)print k,"----",num[k]|"sort -k 3  -rn"}' "$1" |
      head -n 15 | awk '{str[$1]++} END{for (s in str)print s}'| grep "$3" > thread.log


##對上述輸出的每一個線程做分析處理，調用parseLog
cat thread.log | while read line
    do
      grep "\""${line}"\""  "$1" > temp.log
      parseLog temp.log $2
    done
exit

　　這個腳本有個基礎條件是，分析的日志必須得是按照一定規范輸出的日志，輸出字段中帶有時間和線程名

　　腳本傳參：

　　獲得可以分析的所有線程，按照數量排序，並只獲得前15個

　　接下來對每一個過濾出來的線程做分析處理

　　最后就是分析日志的方法了

　　主要思路是，用下一行的時間減去上一行的時間，如果超過給定的值，就將兩行都輸出到指定文件。

　　執行效果：

[utap@host145 logs]$ sh pick_thread.sh bb.log 1 timer
timerQ_3-service-#146]
[utap@host145 logs]$ cat result.log 
2019-11-05 00:02:00.371 [DEBUG] [TaskRule:405][printExpr] [timerQ_3-service-#146] [100000000004] - TaskRule printExpr i-j=2-0, expr[i].elementAt(j).m_min=0, m_max=9999
2019-11-05 00:02:00.373 [DEBUG] [TaskRule:405][printExpr] [timerQ_3-service-#146] [100000000004] - TaskRule printExpr i-j=3-0, expr[i].elementAt(j).m_min=0, m_max=9999^C

　　方便再次使用到吧,地址在 https://github.com/garfieldcgf/notes/tree/master/operations/bin