分享 有一個 其中 res set ava jhat 前臺 沒有

作者：鹿丸不會多項式 出處：http://www.cnblogs.com/hechao123 轉載請先與我聯系。

一、問題描述

前陣子我們因為B機房故障，將所有的流量切到了A機房，在經歷了推送+自然高峰之後，A機房所有服務器都出現java線程數接近1000的情況（1000是設置的max值），在晚上7點多觀察，java線程數略有下降，但還是有900+的樣子，而此時，單臺服務器的TPS維持在400/s，並不是一個特別大的量。然後將A機房一臺機器下線，繼續觀察，到了晚上9點多，那臺下線的機器，jetty進程的java線程數還是7、800的樣子。同時，同一機房的另外一臺還在線的機器在重啟jetty之後，在同樣tps400+的情況，線程數一直保持在只有300多。這就很奇怪了，下線的機器都沒有請求了，java線程數怎麽還是這麽多？會不會是多線程競爭資源，導致阻塞？開始研究這個問題。

二、保存現場

保存哪些現場

我先查看並記錄了當時的jetty進程的線程數、db連接數、cpu負載、內存使用情況、tps、nginx連接數、jetty錯誤日誌、GC情況、tcp連接狀態等，都是正常。 然後我用jstack命令導出當前jvm的所有線程快照，用jmap命令將當前java堆轉儲快照導出，結果發現，除了java線程數之外，其他指標也都是正常。 這裏先說下jstack和jmap使用的常用參數舉例和註意事項：

找到jetty進程pid

對於這兩個命令，首先都需要找出jetty進程對應的pid，當然可以使用jps命令來查找對應的pid。 但是，我當前linux用戶是自己的用戶名用戶，而公司外網服務器我並沒有jetty的權限，也就是說jps命令只有jetty用戶可以查看。 在網上找了下資料，這裏我采用的是這種方式，用ps aux|grep jetty.xml找到了jetty進程對應的pid。

jstack保存線程快照

我使用jstack完整命令是：“sudo -u jetty /data/java/bin/jstack -l pid >> ~/jstack.txt”。-l 參數是將鎖的信息也打印出來。 這裏，有個比較隱蔽的坑，我們的jetty進程是jetty用戶的。如果在linux上是root用戶或者其他用戶直接執行jstack -l pid，會出現報錯。所以，需要在命令前加上sudo -u jetty，用jetty賬戶來執行這個命令。 而jetty賬戶又不一定將/data/java/bin加入環境變量，所以需要執行jstack的完整路徑。 執行完畢的結果存放在home目錄下的jstack.txt文件中。（這裏是找運維同事協助完成的）

jmap保存堆轉儲快照

同樣，jmap命令也需要註意命令執行的用戶。我使用的完整命令是：“sudo -u jetty /data/java/bin/jmap -dump:format=b,file=~/jmap.hprof pid”。 導出來的hprof文件非常大，保存了當時堆中對象的快照。hprof不能直接閱讀，需要用專門的工具來分析。最常用的是mat和jhat。mat是圖形界面的工具，有windows版的，比較方便。但是mat有個死穴，當分析的hprof文件過大時，會出現內存溢出的錯誤而導致無法得到結果。我曾經嘗試解決這個問題，但是一直沒有找到有效的方法。所以這裏我用的是jhat。

jhat分析堆轉儲快照

jhat是java自帶的命令行工具，比較簡樸。但是對於特別大的文件，好像是唯一的選擇。將hprof文件壓縮，下載到開發環境的虛擬機上，就可以開始用jhat分析了。 我使用的完整命令是：“jhat -J-d64 -J-mx9g -port 5000 jmap.hprof”。來解釋一下參數。-J-d64：因為jetty進程是在64位的系統上運行，所以需要指定64位。-J-mx9g：表示jhat進程最多可以分配9G的堆內存，這就是為什麽jhat可以分析超大文件的原因了，因為可以指定堆內存大小。-port 5000：jhat分析完畢之後，會啟動一個web服務，可以通過指定端口來訪問，這就是指定的端口。 參數就介紹完了，但是這樣的命令會有一個問題。上面的命令執行完，jhat進程是在前臺的。換句話說，如果你ctrl+c（或者xshell連接超時）結束了這個前臺進程，那麽jhat提供的web服務就結束了，你剛才分析了那麽久的文件得重新再來。解決這個問題，用到linux上的nohup和&組合。通過命令“nohup jhat -J-d64 -J-mx9g -port 5000 jmap.hprof &”，就可以將進程放到後臺執行。有興趣可以研究一下nohup，在這裏不做贅述。 jhat分析需要一定時間。可以用top命令看，當jhat進程沒有瘋狂的吃cpu的時候，說明分析已經結束了。此時，可以通過ip:port來訪問剛才分析出的結果了。

三、定位問題

首先，來看剛才的jstack.txt。 在近900個線程裏面，有600+個線程都是wait在同一個對象<0x0000000734afba50>上，而且這600+個線程的調用棧都是一模一樣的。去查了一下，這個org.eclipse.jetty.util.thread.QueuedThreadPool的作用，就是jetty的worker線程池。每當一個請求來臨的時候，jetty就從這個QueuedThreadPool中新建一個線程或者取一個空閑線程來處理這個請求。 看到調用棧裏面的“at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:526)”，感覺好像這些線程都在等待任務來處理。當然，這是猜的。 為了驗證這個猜想，找到剛才jhat已經分析好的堆的快照結果。首先，我找到“class org.eclipse.jetty.util.thread.QueuedThreadPool”這個類，然後依次點擊，進入到QueuedThreadPool的唯一的實例中。

到這裏，就可以看到QueuedThreadPool這個對象中所有成員變量了：

其中，有兩個AtomicInteger型變量在這裏需要關心：_threadsStarted和_threadsIdle。 _threadsStarted表示QueuedThreadPool當前擁有的線程數，而_threadsIdle表示QueuedThreadPool中空閑的線程數。 點擊進去，就看到這兩個成員變量的值，value分別是707和613。 這表示，QueuedThreadPool當前開啟了707個用於處理用戶請求的線程，而其中有613個處於閑置狀態。 到這裏，我們上面的猜想基本得到驗證。那些大量的time_wait的線程，真的是處在等待請求到來的狀態。那麽問題是，既然是閑置的線程，為什麽jetty沒有進行回收，time_wait有這麽長時間嗎？

四、分析jetty源碼，確定原因

要繼續確定為什麽空閑線程沒有被回收原因，分析jetty源碼是一種思路。我只找到和線上jetty大版本一樣，小版本接近的jetty源碼。但是不妨礙理清這部分的邏輯。 繼續回到剛才的jstack的結果中： 熟悉阻塞隊列的人都知道，棧中的“org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:342)”，就是從一個指定的阻塞隊列中去獲取任務。如果此時阻塞隊列中沒有任務可取，線程就會被阻塞住，直到隊列中有任務可取或者超時。如果超時，poll方法將返回null值。進入到idleJobPoll()方法中，也很容易就發現，poll的超時時間也是用了剛才的_maxIdleTimeMs變量，也就是60s。所以才會發生600+個線程同時wait一個條件的情況。這些線程都在等待BlockingArrayQueue中任務來臨這個Condition。那麽，是誰讓線程調用poll的？為什麽poll設置了超時時間，在超時之後，線程沒有結束呢？為什麽這些空閑線程沒有被及時回收呢？ 帶著這些問題，我們來看QueuedThreadPool的源碼。我們直接找到調用了idelJobPoll()方法的這塊代碼，如下： 這裏有幾個變量和方法需要先說明一下。_maxIdelTimeMs是QueuedThreadPool中的一個成員變量，表示超時的毫秒數，默認值是60000（表示60秒），可以在剛才jhat分析的結果中查詢到這個值。_lastShrink也是QueuedThreadPool的一個成員變量，是線程安全的AtomicLong類型，表示上一次線程退出時的時間戳，被所有線程池中的線程共享。campareAndSet方法，就是著名的CAS（比較後賦值）。例如：_lastShrink.compareAndSet(last,now)的意思是，先將_lastShrink和last比較看是否相同，相同則將_lastShrink的值等於now並返回true，否則不進行賦值並返回false。 當一個空閑線程從idelJobPool()方法中超時後獲取到null值，會再次進入while循環。此時的線程數size（700+）是要大於_minThreads（設置的為200），所以會進入框中的if代碼塊。if代碼塊中主要經歷了以下步驟：

1.將last賦值為上一個線程池中的線程退出時的時間戳，將當前時間賦值給now。

2.然後“if (last==0 || (now-last)>_maxIdleTimeMs)”這一句判斷，now距離上一個線程退出是否超過了maxIdleTimeMs（60000，60秒）。

3.如果2步驟中條件成立，會對_lastShrink重新賦值為當前時間，並將QueuedThreadPool中的線程計數減一。

campareAndSet保證了，每一次只會有一個線程能夠賦值成功。

賦值成功後，就會return，讓線程跳出while循環，這個線程就結束了。

對於賦值不成功的線程，會繼續執行到idleJobPoll()，和步驟4相似。

4.如果2步驟中條件不成立，會重新回到idleJobPoll()，阻塞住線程，又會嘗試從阻塞隊列中獲取任務。

也就是說，每當一個空閑線程執行到框中的代碼時，都要判斷現在距離上次有線程退出是否超過60s。如果沒有超過60s，這個線程會繼續回到idelJobPool方法中去等待任務。換句話說，1分鐘之內，QueuedThreadPool最多只能允許一個線程退出。那麽，我們600+個空閑線程如果要全部退出，那就要600分鐘，也就是10個小時！！ 難怪，會有那麽多空閑線程在那裏啊，雖然這些空閑線程可以被重復利用並不影響業務，但也是占用了線程資源。不知道這個算不算是個bug，但是真的很坑。由其影響通過java線程數去判斷業務的繁忙情況，容易受到誤導。

五、實驗驗證

為了進一步驗證這個結論，我在開發環境部署了一樣的業務，純凈且沒有其他人訪問。用ab以1000並發量發起30000個請求，迅速將java線程數提升至1000（最大值）。然後用watch命令，每5分鐘觀察一次java線程數，下面是部分結果：

可以看到，每5分鐘，線程數都下降了5。確實是1分鐘退出一個線程啊！

六、結論

這整個過程最重要的結論就是，當發現java線程數非常高的時候，不必太擔心。有可能只是jetty沒有及時回收空閑線程而已。更重要的是，要掌握分析的工具和方法，查找出現象背後的原因。

java線程數過高原因分析