通過jstack定位線上運行java系統故障_案例1

標籤：style   blog   http   java   使用   io   strong   檔案   

問題描述：

在一個線上啟動並執行java web系統中，會定時運行一個FTP上傳的任務，結果有一天發現，檔案正常產生後卻沒有上傳。

問題初步分析：

1.查看記錄檔

發現這個任務只列印了開始進入FTP處理的日誌，但是沒有列印FTP處理完成的日誌。

從代碼上看，FTP上傳處理的代碼異常保護都非常的好，如果出現異常，就會進行列印，而記錄檔中卻沒有相關的資訊，甚是奇怪。懷疑是FTP過程問題，如對方FTP伺服器有什麼問題導致，但是卻找不到證據。

苦於無法窺探java運行系統內部資訊，祭出殺手鐧-jstack。

2.通過jstack分析

在運行系統上，通過jps命令（也可以通過其他方式，如ps）查看運行中的java程式的進程ID，使用jstack pid > jstack.log 將線程堆棧資訊匯出到jstack.log檔案中，找到如下有用的資訊。

通過代碼確認，下方的UploadFtpTask確實就是我們的檔案上傳任務的執行代碼。

通過堆棧資訊看，線程狀態為RUNNABLE,不是BLOCKED狀態，說明不是因為鎖導致線程阻塞，而是阻塞在了網路讀取上。

<span style="font-size:14px;">"DefaultQuartzScheduler_Worker-5" prio=10 tid=0x00002aaaf4382801 nid=0x1874 runnable [0x000000004133b000..0x000000004133bda0]   java.lang.Thread.State: RUNNABLE        at java.net.SocketInputStream.socketRead0(Native Method)        at java.net.SocketInputStream.read(SocketInputStream.java:129)        at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264)        at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306)        at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)        - locked <0x00002aaac3cdd061> (a java.io.InputStreamReader)        at sun.nio.cs.StreamDecoder.read0(StreamDecoder.java:107)        - locked <0x00002aaac3cdd061> (a java.io.InputStreamReader)        at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:93)        at java.io.InputStreamReader.read(InputStreamReader.java:151)        at it.sauronsoftware.ftp4j.NVTASCIIReader.readLine(NVTASCIIReader.java:105)        at it.sauronsoftware.ftp4j.FTPCommunicationChannel.read(FTPCommunicationChannel.java:142)        at it.sauronsoftware.ftp4j.FTPCommunicationChannel.readFTPReply(FTPCommunicationChannel.java:187)        at it.sauronsoftware.ftp4j.FTPClient.connect(FTPClient.java:1034)        - locked <0x00002aaac3cdd109> (a java.lang.Object)        at com.xx.FtpClientImpl.connect(FtpClientImpl.java:56)        at com.xx.UploadFtpTask.execute(UploadFtpTask.java:88)        at org.quartz.core.JobRunShell.run(JobRunShell.java:216)        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)</span>

通過引用的jar包確認，這個FTP功能使用的開源包ftp4j來實現的，使用的版本為1.5.1。

寫個測試程式，看看FTP串連時的呼叫堆疊：

Socket.connect(SocketAddress) line: 469 
Socket.<init>(SocketAddress, SocketAddress, boolean) line: 366 
Socket.<init>(String, int) line: 180 
DirectConnector.connect(String, int) line: 35 
DirectConnector.connectForCommunicationChannel(String, int) line: 40 
FTPClient.connect(String, int) line: 1024 
FTPClient.connect(String) line: 991 
Test.main(String[]) line: 19 

而Socket 的469行是什麼呢？

connect(endpoint, 0); 

這個函數的定義為：public void connect(SocketAddress endpoint, int timeout)  ，上面的調用相當於設定了timeout為0，那就意味著出現網路丟包或者對端服務有問題時，這個串連會無限制等待下去。這就杯具了。

再看看這個開源項目後續是否對此問題做過修改呢？下載1.7.2版本,再次測試，查看呼叫堆疊：

Socket.connect(SocketAddress, int) line: 490 
DirectConnector(FTPConnector).tcpConnectForCommunicationChannel(String, int) line: 208 
DirectConnector.connectForCommunicationChannel(String, int) line: 39 
FTPClient.connect(String, int) line: 1036 
FTPClient.connect(String) line: 1003 
Test.main(String[]) line: 19

通過tcpConnectForCommunicationChannel去調用Socket的connect方法時，傳入了逾時時間，為10秒（10*1000）。這就引入了逾時機制，如果出現上面問題時，就不會死等了。

總結：

1.jstack工具是定位線上運行java系統的利器，可以查看線程堆棧資訊，這對於分析問題非常重要，特別是在日誌分析和程式碼分析無法確定問題時。

2.網路連接時，必須設定逾時，不能無限制等待。發散一下，開發系統時，必須考慮各種異常情況。套用那句話，出來混，總是要還的。