快捷導(dǎo)航

記一次tomcat進(jìn)程cpu占用過(guò)高的問(wèn)題排查記錄

更新時(shí)間：2020年02月24日 15:09:02 作者：yiduyangyi

這篇文章主要介紹了記一次tomcat進(jìn)程cpu占用過(guò)高的問(wèn)題排查記錄，文中通過(guò)示例代碼介紹的非常詳細(xì)，對(duì)大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值，需要的朋友們下面隨著小編來(lái)一起學(xué)習(xí)學(xué)習(xí)吧

本文主要記錄一次tomcat進(jìn)程，因TCP連接過(guò)多導(dǎo)致CPU占用過(guò)高的問(wèn)題排查記錄。

問(wèn)題描述

linux系統(tǒng)下，一個(gè)tomcat web服務(wù)的cpu占用率非常高，top顯示結(jié)果超過(guò)200%。請(qǐng)求無(wú)法響應(yīng)。反復(fù)重啟依然同一個(gè)現(xiàn)象。

問(wèn)題排查

1、獲取進(jìn)程信息

通過(guò)jdk提供的jps命令可以快速查出jvm進(jìn)程，

jps pid

2、查看jstack信息

jstack pid

發(fā)現(xiàn)存在大量log4j線程block，處于waiting lock狀態(tài)

org.apache.log4j.Category.callAppenders(org.apache.log4j.spi.LoggingEvent) @bci=12, line=201 (Compiled frame)

搜索相關(guān)信息，發(fā)現(xiàn)log4j 1.x版本存在死鎖問(wèn)題。

發(fā)現(xiàn)問(wèn)題，于是調(diào)整log4j配置，僅打開(kāi)error級(jí)別日志，重啟tomcat。此時(shí)stack中block線程消失，但進(jìn)程cpu占用率依然高漲。

3、進(jìn)一步排查

分析每個(gè)線程的cpu占用量，此處需要引入一個(gè)大神貢獻(xiàn)的腳本，計(jì)算java進(jìn)程中，每個(gè)線程的cpu使用量。

#!/bin/bash

typeset top=${1:-10}
typeset pid=${2:-$(pgrep -u $USER java)}
typeset tmp_file=/tmp/java_${pid}_$$.trace

$JAVA_HOME/bin/jstack $pid > $tmp_file
ps H -eo user,pid,ppid,tid,time,%cpu --sort=%cpu --no-headers\
    | tail -$top\
    | awk -v "pid=$pid" '$2==pid{print $4"\t"$6}'\
    | while read line;
do
    typeset nid=$(echo "$line"|awk '{printf("0x%x",$1)}')
    typeset cpu=$(echo "$line"|awk '{print $2}')
    awk -v "cpu=$cpu" '/nid='"$nid"'/,/^$/{print $0"\t"(isF++?"":"cpu="cpu"%");}' $tmp_file
done

rm -f $tmp_file

腳本適用范圍

因?yàn)閜s中的%CPU數(shù)據(jù)統(tǒng)計(jì)來(lái)自于/proc/stat，這個(gè)份數(shù)據(jù)并非實(shí)時(shí)的，而是取決于OS對(duì)其更新的頻率，一般為1S。所以你看到的數(shù)據(jù)統(tǒng)計(jì)會(huì)和jstack出來(lái)的信息不一致也就是這個(gè)原因～但這份信息對(duì)持續(xù)LOAD由少數(shù)幾個(gè)線程導(dǎo)致的問(wèn)題排查還是非常給力的，因?yàn)檫@些固定少數(shù)幾個(gè)線程會(huì)持續(xù)消耗CPU的資源，即使存在時(shí)間差，反正也都是這幾個(gè)線程所導(dǎo)致。

除了這個(gè)腳本，簡(jiǎn)單點(diǎn)兒的方法則是，查出進(jìn)程id后，通過(guò)如下命令查看該進(jìn)程中每個(gè)線程的資源使用情況

top -H -p pid

從這里獲取pid（線程id），轉(zhuǎn)換為16進(jìn)制，然后去stack信息中查找對(duì)象的線程信息。

通過(guò)上述方法，查出tomcat進(jìn)程對(duì)應(yīng)的線程cpu占用率累積之和約80%，遠(yuǎn)小于top給出的200%+

說(shuō)明并不存在長(zhǎng)期占用cpu的線程，應(yīng)該是屬于有許多短暫性的cpu密集計(jì)算。進(jìn)而懷疑是不是jvm內(nèi)存不足，頻繁gc導(dǎo)致。

jstat -gc pid

發(fā)現(xiàn)jvm內(nèi)存使用并未出現(xiàn)異常，gc次數(shù)明顯暴漲

查完內(nèi)存，由于本身是一個(gè)網(wǎng)絡(luò)程序，進(jìn)一步排查網(wǎng)絡(luò)連接。

4、問(wèn)題定位

查詢(xún)tomcat對(duì)應(yīng)端口的tcp鏈接，發(fā)現(xiàn)存在大量EASTABLISH的鏈接，還有部分其它狀態(tài)的連接，總計(jì)400+。

netstat -anp | grep port

進(jìn)一步查看這些連接的來(lái)源，發(fā)現(xiàn)是該tomcat服務(wù)的應(yīng)用端，存在大量后臺(tái)線程，在頻繁輪詢(xún)?cè)摲?wù)，導(dǎo)致該服務(wù)tomcat 連接數(shù)被打滿(mǎn)，無(wú)法繼續(xù)接收請(qǐng)求。

netstat狀態(tài)說(shuō)明：

LISTEN：偵聽(tīng)來(lái)自遠(yuǎn)方的TCP端口的連接請(qǐng)求
SYN-SENT：再發(fā)送連接請(qǐng)求后等待匹配的連接請(qǐng)求（如果有大量這樣的狀態(tài)包，檢查是否中招了）
SYN-RECEIVED：再收到和發(fā)送一個(gè)連接請(qǐng)求后等待對(duì)方對(duì)連接請(qǐng)求的確認(rèn)（如有大量此狀態(tài)，估計(jì)被flood***了）
ESTABLISHED：代表一個(gè)打開(kāi)的連接
FIN-WAIT-1：等待遠(yuǎn)程TCP連接中斷請(qǐng)求，或先前的連接中斷請(qǐng)求的確認(rèn)
FIN-WAIT-2：從遠(yuǎn)程TCP等待連接中斷請(qǐng)求
CLOSE-WAIT：等待從本地用戶(hù)發(fā)來(lái)的連接中斷請(qǐng)求
CLOSING：等待遠(yuǎn)程TCP對(duì)連接中斷的確認(rèn)
LAST-ACK：等待原來(lái)的發(fā)向遠(yuǎn)程TCP的連接中斷請(qǐng)求的確認(rèn)（不是什么好東西，此項(xiàng)出現(xiàn)，檢查是否被***）
TIME-WAIT：等待足夠的時(shí)間以確保遠(yuǎn)程TCP接收到連接中斷請(qǐng)求的確認(rèn)
CLOSED：沒(méi)有任何連接狀態(tài)

5、根源分析

直接觸發(fā)原因是客戶(hù)端輪詢(xún)，請(qǐng)求異常，繼續(xù)輪序；客戶(hù)端不斷有新的后臺(tái)線程加入輪詢(xún)隊(duì)伍，最終導(dǎo)致服務(wù)端tomcat連接被打滿(mǎn)。

到此這篇關(guān)于記一次tomcat進(jìn)程cpu占用過(guò)高的問(wèn)題排查記錄的文章就介紹到這了,更多相關(guān)tomcat進(jìn)程cpu占用過(guò)高內(nèi)容請(qǐng)搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！

您可能感興趣的文章: