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