【原創】大叔問題定位分享（6）Dubbo monitor服務iowait高，負載高

一 問題

Dubbo monitor所在服務器狀態異常，iowait一直很高，load也一直很高，監控以下：

iowait如圖：

load如圖：

 

二 分析

經過iotop命令能夠查看當前系統中磁盤io狀況以及進程佔用磁盤io的狀況

 

從中能夠定位到佔用io進程的pid；

經過

cat /proc/${pid}/io

能夠查看一個進程具體的讀寫情況；

經過

ps aux|grep ${pid}

能夠查到這個進程具體的命令；

 

經過以上命令定位到進程爲dubbo的monitor進程，用jstack打印線程棧發現處於RUNNABLE的進程除了

java.lang.Thread.State: RUNNABLE

       at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)

 

以外，有兩個線程很可疑

 

"DubboMonitorTimer-thread-1" daemon prio=10 tid=0x00007f53b0593000 nid=0x363e runnable [0x00007f53ac36d000]

   java.lang.Thread.State: RUNNABLE

       at java.io.FileInputStream.readBytes(Native Method)

       at java.io.FileInputStream.read(FileInputStream.java:272)

       at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283)

       at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325)

       at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177)

       - locked <0x0000000779d506f8> (a java.io.FileReader)

       at java.io.InputStreamReader.read(InputStreamReader.java:184)

       at java.io.BufferedReader.fill(BufferedReader.java:154)

       at java.io.BufferedReader.readLine(BufferedReader.java:317)

       - locked <0x0000000779d506f8> (a java.io.FileReader)

       at java.io.BufferedReader.readLine(BufferedReader.java:382)

       at com.alibaba.dubbo.monitor.simple.SimpleMonitorService.appendData(SimpleMonitorService.java:322)

       at com.alibaba.dubbo.monitor.simple.SimpleMonitorService.draw(SimpleMonitorService.java:263)

       at com.alibaba.dubbo.monitor.simple.SimpleMonitorService.access$300(SimpleMonitorService.java:64)

       at com.alibaba.dubbo.monitor.simple.SimpleMonitorService$2.run(SimpleMonitorService.java:137)

       at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)

       at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)

       at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)

       at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)

       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

       at java.lang.Thread.run(Thread.java:744)

 

   Locked ownable synchronizers:

       - <0x0000000788104268> (a java.util.concurrent.ThreadPoolExecutor$Worker)

 

"DubboMonitorAsyncWriteLogThread" daemon prio=10 tid=0x00007f53b05ba000 nid=0x363d runnable [0x00007f53ac3af000]

   java.lang.Thread.State: RUNNABLE

       at java.io.FileOutputStream.writeBytes(Native Method)

       at java.io.FileOutputStream.write(FileOutputStream.java:345)

       at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)

       at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)

       at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)

       at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)

       - locked <0x000000077a028918> (a java.io.FileWriter)

       at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)

       at com.alibaba.dubbo.monitor.simple.SimpleMonitorService.write(SimpleMonitorService.java:213)

       at com.alibaba.dubbo.monitor.simple.SimpleMonitorService.access$100(SimpleMonitorService.java:64)

       at com.alibaba.dubbo.monitor.simple.SimpleMonitorService$1.run(SimpleMonitorService.java:120)

       at java.lang.Thread.run(Thread.java:744)

 

   Locked ownable synchronizers:

       - None

 

這兩個線程一個在read，一個在write，查看dubbo monitor的源代碼發現：

 

monitor中會有兩個線程，一個不停地寫統計日誌，一個每隔300s進行一次draw操做；

monitor中天天的日誌都會保存在一個日誌目錄中，進入其中一天的日誌目錄查看日誌大小：

發現一天的日誌只有幾十M，而上邊iotop查看的結果是read是1520K/s,write是3.43M/s，因此排除write的問題，問題應該出在draw身上，查看draw的源代碼發現draw會不斷的讀取統計日誌同時進行繪圖操做，

 

draw中會遍歷日誌目錄，同時在appendData方法中會進行日誌讀取操做，因爲monitor已經運行很長時間，因此按天保存的目錄很是多，每次draw都須要去遍歷這些目錄而且進行讀取文件操做，歷史數據沒有改動但卻會不斷的從新進行日誌讀取和繪圖，問題應該出在這裏；

 

三 解決

修改代碼以下

 

即讓draw只對當天的日誌進行處理，修改以後服務器iowait如圖：

 

load如圖：

 

問題解決