|
一、問(wèn)題描述 前陣子我們因?yàn)锽機(jī)房故障，將所有的流量切到了A機(jī)房，在經(jīng)歷了推送+自然高峰之后，A機(jī)房所有服務(wù)器都出現(xiàn)java線程數(shù)接近1000的情況（1000是設(shè)置的max值），在晚上7點(diǎn)多觀察，java線程數(shù)略有下降，但還是有900+的樣子，而此時(shí)，單臺(tái)服務(wù)器的TPS維持在400/s，并不是一個(gè)特別大的量。然后將A機(jī)房一臺(tái)機(jī)器下線，繼續(xù)觀察，到了晚上9點(diǎn)多，那臺(tái)下線的機(jī)器，jetty進(jìn)程的java線程數(shù)還是7、800的樣子。同時(shí)，同一機(jī)房的另外一臺(tái)還在線的機(jī)器在重啟jetty之后，在同樣tps400+的情況，線程數(shù)一直保持在只有300多。這就很奇怪了，下線的機(jī)器都沒(méi)有請(qǐng)求了，java線程數(shù)怎么還是這么多？會(huì)不會(huì)是多線程競(jìng)爭(zhēng)資源，導(dǎo)致阻塞？開(kāi)始研究這個(gè)問(wèn)題。 二、保存現(xiàn)場(chǎng)保存哪些現(xiàn)場(chǎng)我先查看并記錄了當(dāng)時(shí)的jetty進(jìn)程的線程數(shù)、db連接數(shù)、cpu負(fù)載、內(nèi)存使用情況、tps、nginx連接數(shù)、jetty錯(cuò)誤日志、GC情況、tcp連接狀態(tài)等，都是正常。
然后我用jstack命令導(dǎo)出當(dāng)前jvm的所有線程快照，用jmap命令將當(dāng)前java堆轉(zhuǎn)儲(chǔ)快照導(dǎo)出，結(jié)果發(fā)現(xiàn)，除了java線程數(shù)之外，其他指標(biāo)也都是正常。
這里先說(shuō)下jstack和jmap使用的常用參數(shù)舉例和注意事項(xiàng)：
找到j(luò)etty進(jìn)程pid對(duì)于這兩個(gè)命令，首先都需要找出jetty進(jìn)程對(duì)應(yīng)的pid，當(dāng)然可以使用jps命令來(lái)查找對(duì)應(yīng)的pid。
但是，我當(dāng)前l(fā)inux用戶是自己的用戶名用戶，而公司外網(wǎng)服務(wù)器我并沒(méi)有jetty的權(quán)限，也就是說(shuō)jps命令只有jetty用戶可以查看。
在網(wǎng)上找了下資料，這里我采用的是這種方式，用ps aux|grep jetty.xml找到了jetty進(jìn)程對(duì)應(yīng)的pid。
jstack保存線程快照我使用jstack完整命令是：“sudo -u jetty /data/java/bin/jstack -l pid >> ~/jstack.txt”。-l 參數(shù)是將鎖的信息也打印出來(lái)。
這里，有個(gè)比較隱蔽的坑，我們的jetty進(jìn)程是jetty用戶的。如果在linux上是root用戶或者其他用戶直接執(zhí)行jstack -l pid，會(huì)出現(xiàn)報(bào)錯(cuò)。所以，需要在命令前加上sudo -u jetty，用jetty賬戶來(lái)執(zhí)行這個(gè)命令。
而jetty賬戶又不一定將/data/java/bin加入環(huán)境變量，所以需要執(zhí)行jstack的完整路徑。
執(zhí)行完畢的結(jié)果存放在home目錄下的jstack.txt文件中。（這里是找運(yùn)維同事協(xié)助完成的）
jmap保存堆轉(zhuǎn)儲(chǔ)快照同樣，jmap命令也需要注意命令執(zhí)行的用戶。我使用的完整命令是：“sudo -u jetty /data/java/bin/jmap -dump:format=b,file=~/jmap.hprof pid”。
導(dǎo)出來(lái)的hprof文件非常大，保存了當(dāng)時(shí)堆中對(duì)象的快照。hprof不能直接閱讀，需要用專門的工具來(lái)分析。最常用的是mat和jhat。mat是圖形界面的工具，有windows版的，比較方便。但是mat有個(gè)死穴，當(dāng)分析的hprof文件過(guò)大時(shí)，會(huì)出現(xiàn)內(nèi)存溢出的錯(cuò)誤而導(dǎo)致無(wú)法得到結(jié)果。我曾經(jīng)嘗試解決這個(gè)問(wèn)題，但是一直沒(méi)有找到有效的方法。所以這里我用的是jhat。
jhat分析堆轉(zhuǎn)儲(chǔ)快照jhat是java自帶的命令行工具，比較簡(jiǎn)樸。但是對(duì)于特別大的文件，好像是唯一的選擇。將hprof文件壓縮，下載到開(kāi)發(fā)環(huán)境的虛擬機(jī)上，就可以開(kāi)始用jhat分析了。
我使用的完整命令是：“jhat -J-d64 -J-mx9g -port 5000 jmap.hprof”。來(lái)解釋一下參數(shù)。-J-d64：因?yàn)閖etty進(jìn)程是在64位的系統(tǒng)上運(yùn)行，所以需要指定64位。-J-mx9g：表示jhat進(jìn)程最多可以分配9G的堆內(nèi)存，這就是為什么jhat可以分析超大文件的原因了，因?yàn)榭梢灾付ǘ褍?nèi)存大小。-port 5000：jhat分析完畢之后，會(huì)啟動(dòng)一個(gè)web服務(wù)，可以通過(guò)指定端口來(lái)訪問(wèn)，這就是指定的端口。
參數(shù)就介紹完了，但是這樣的命令會(huì)有一個(gè)問(wèn)題。上面的命令執(zhí)行完，jhat進(jìn)程是在前臺(tái)的。換句話說(shuō)，如果你ctrl+c（或者xshell連接超時(shí)）結(jié)束了這個(gè)前臺(tái)進(jìn)程，那么jhat提供的web服務(wù)就結(jié)束了，你剛才分析了那么久的文件得重新再來(lái)。解決這個(gè)問(wèn)題，用到linux上的nohup和&組合。通過(guò)命令“nohup jhat -J-d64 -J-mx9g -port 5000 jmap.hprof &”，就可以將進(jìn)程放到后臺(tái)執(zhí)行。有興趣可以研究一下nohup，在這里不做贅述。
jhat分析需要一定時(shí)間?？梢杂胻op命令看，當(dāng)jhat進(jìn)程沒(méi)有瘋狂的吃cpu的時(shí)候，說(shuō)明分析已經(jīng)結(jié)束了。此時(shí)，可以通過(guò)ip:port來(lái)訪問(wèn)剛才分析出的結(jié)果了。
 三、定位問(wèn)題首先，來(lái)看剛才的jstack.txt。
 在近900個(gè)線程里面，有600+個(gè)線程都是wait在同一個(gè)對(duì)象<0x0000000734afba50>上，而且這600+個(gè)線程的調(diào)用棧都是一模一樣的。去查了一下，這個(gè)org.eclipse.jetty.util.thread.QueuedThreadPool的作用，就是jetty的worker線程池。每當(dāng)一個(gè)請(qǐng)求來(lái)臨的時(shí)候，jetty就從這個(gè)QueuedThreadPool中新建一個(gè)線程或者取一個(gè)空閑線程來(lái)處理這個(gè)請(qǐng)求。
看到調(diào)用棧里面的“at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:526)”，感覺(jué)好像這些線程都在等待任務(wù)來(lái)處理。當(dāng)然，這是猜的。
為了驗(yàn)證這個(gè)猜想，找到剛才jhat已經(jīng)分析好的堆的快照結(jié)果。首先，我找到“class org.eclipse.jetty.util.thread.QueuedThreadPool”這個(gè)類，然后依次點(diǎn)擊，進(jìn)入到QueuedThreadPool的唯一的實(shí)例中。
   到這里，就可以看到QueuedThreadPool這個(gè)對(duì)象中所有成員變量了：  其中，有兩個(gè)AtomicInteger型變量在這里需要關(guān)心：_threadsStarted和_threadsIdle。
_threadsStarted表示QueuedThreadPool當(dāng)前擁有的線程數(shù)，而_threadsIdle表示QueuedThreadPool中空閑的線程數(shù)。
點(diǎn)擊進(jìn)去，就看到這兩個(gè)成員變量的值，value分別是707和613。
這表示，QueuedThreadPool當(dāng)前開(kāi)啟了707個(gè)用于處理用戶請(qǐng)求的線程，而其中有613個(gè)處于閑置狀態(tài)。
到這里，我們上面的猜想基本得到驗(yàn)證。那些大量的time_wait的線程，真的是處在等待請(qǐng)求到來(lái)的狀態(tài)。那么問(wèn)題是，既然是閑置的線程，為什么jetty沒(méi)有進(jìn)行回收，time_wait有這么長(zhǎng)時(shí)間嗎？
四、分析jetty源碼，確定原因要繼續(xù)確定為什么空閑線程沒(méi)有被回收原因，分析jetty源碼是一種思路。我只找到和線上jetty大版本一樣，小版本接近的jetty源碼。但是不妨礙理清這部分的邏輯。
繼續(xù)回到剛才的jstack的結(jié)果中：
 熟悉阻塞隊(duì)列的人都知道，棧中的“org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:342)”，就是從一個(gè)指定的阻塞隊(duì)列中去獲取任務(wù)。如果此時(shí)阻塞隊(duì)列中沒(méi)有任務(wù)可取，線程就會(huì)被阻塞住，直到隊(duì)列中有任務(wù)可取或者超時(shí)。如果超時(shí)，poll方法將返回null值。進(jìn)入到idleJobPoll()方法中，也很容易就發(fā)現(xiàn)，poll的超時(shí)時(shí)間也是用了剛才的_maxIdleTimeMs變量，也就是60s。所以才會(huì)發(fā)生600+個(gè)線程同時(shí)wait一個(gè)條件的情況。這些線程都在等待BlockingArrayQueue中任務(wù)來(lái)臨這個(gè)Condition。那么，是誰(shuí)讓線程調(diào)用poll的？為什么poll設(shè)置了超時(shí)時(shí)間，在超時(shí)之后，線程沒(méi)有結(jié)束呢？為什么這些空閑線程沒(méi)有被及時(shí)回收呢？
帶著這些問(wèn)題，我們來(lái)看QueuedThreadPool的源碼。我們直接找到調(diào)用了idelJobPoll()方法的這塊代碼，如下：
 這里有幾個(gè)變量和方法需要先說(shuō)明一下。_maxIdelTimeMs是QueuedThreadPool中的一個(gè)成員變量，表示超時(shí)的毫秒數(shù)，默認(rèn)值是60000（表示60秒），可以在剛才jhat分析的結(jié)果中查詢到這個(gè)值。_lastShrink也是QueuedThreadPool的一個(gè)成員變量，是線程安全的AtomicLong類型，表示上一次線程退出時(shí)的時(shí)間戳，被所有線程池中的線程共享。campareAndSet方法，就是著名的CAS（比較后賦值）。例如：_lastShrink.compareAndSet(last,now)的意思是，先將_lastShrink和last比較看是否相同，相同則將_lastShrink的值等于now并返回true，否則不進(jìn)行賦值并返回false。
當(dāng)一個(gè)空閑線程從idelJobPool()方法中超時(shí)后獲取到null值，會(huì)再次進(jìn)入while循環(huán)。此時(shí)的線程數(shù)size（700+）是要大于_minThreads（設(shè)置的為200），所以會(huì)進(jìn)入框中的if代碼塊。if代碼塊中主要經(jīng)歷了以下步驟：
1.將last賦值為上一個(gè)線程池中的線程退出時(shí)的時(shí)間戳，將當(dāng)前時(shí)間賦值給now。 2.然后“if (last==0 || (now-last)>_maxIdleTimeMs)”這一句判斷，now距離上一個(gè)線程退出是否超過(guò)了maxIdleTimeMs（60000，60秒）。 3.如果2步驟中條件成立，會(huì)對(duì)_lastShrink重新賦值為當(dāng)前時(shí)間，并將QueuedThreadPool中的線程計(jì)數(shù)減一。 campareAndSet保證了，每一次只會(huì)有一個(gè)線程能夠賦值成功。 賦值成功后，就會(huì)return，讓線程跳出while循環(huán)，這個(gè)線程就結(jié)束了。 對(duì)于賦值不成功的線程，會(huì)繼續(xù)執(zhí)行到idleJobPoll()，和步驟4相似。 4.如果2步驟中條件不成立，會(huì)重新回到idleJobPoll()，阻塞住線程，又會(huì)嘗試從阻塞隊(duì)列中獲取任務(wù)。 也就是說(shuō)，每當(dāng)一個(gè)空閑線程執(zhí)行到框中的代碼時(shí)，都要判斷現(xiàn)在距離上次有線程退出是否超過(guò)60s。如果沒(méi)有超過(guò)60s，這個(gè)線程會(huì)繼續(xù)回到idelJobPool方法中去等待任務(wù)。換句話說(shuō)，1分鐘之內(nèi)，QueuedThreadPool最多只能允許一個(gè)線程退出。那么，我們600+個(gè)空閑線程如果要全部退出，那就要600分鐘，也就是10個(gè)小時(shí)??！
難怪，會(huì)有那么多空閑線程在那里啊，雖然這些空閑線程可以被重復(fù)利用并不影響業(yè)務(wù)，但也是占用了線程資源。不知道這個(gè)算不算是個(gè)bug，但是真的很坑。由其影響通過(guò)java線程數(shù)去判斷業(yè)務(wù)的繁忙情況，容易受到誤導(dǎo)。
五、實(shí)驗(yàn)驗(yàn)證為了進(jìn)一步驗(yàn)證這個(gè)結(jié)論，我在開(kāi)發(fā)環(huán)境部署了一樣的業(yè)務(wù)，純凈且沒(méi)有其他人訪問(wèn)。用ab以1000并發(fā)量發(fā)起30000個(gè)請(qǐng)求，迅速將java線程數(shù)提升至1000（最大值）。然后用watch命令，每5分鐘觀察一次java線程數(shù)，下面是部分結(jié)果：  可以看到，每5分鐘，線程數(shù)都下降了5。確實(shí)是1分鐘退出一個(gè)線程??！
六、結(jié)論這整個(gè)過(guò)程最重要的結(jié)論就是，當(dāng)發(fā)現(xiàn)java線程數(shù)非常高的時(shí)候，不必太擔(dān)心。有可能只是jetty沒(méi)有及時(shí)回收空閑線程而已。更重要的是，要掌握分析的工具和方法，查找出現(xiàn)象背后的原因。
|
|
|
來(lái)自： liang1234_ > 《應(yīng)用服務(wù)器》
