【2016-06-13】一次BufferReader沒有close引起的血案

Hive-Web是我司Web端查詢Hive數據的服務，功能上比較簡單，用戶在Web上寫一個SQL，Hive-Web將SQL提交到後端的服務執行查詢，獲得結果的hdfs路徑，而後經過hadoop的fs讀取文件，將其返回給用戶。

這樣簡單地一個應用最近常常OldGC次數超多，用戶反映說網頁上日誌不刷新了，查詢還在Running，可是狀態確實Failed的了，總之就是服務端不響應請求了。

性能調優上我一直比較懵，此次也同樣，沒轍，仔細查吧~

主機：dw-hive-web02.nh
心跳時間：2016-05-24 20:03:31
查看了當時告警機器的CAT心跳，發現catalina-exec線程數120個，正常狀況下爲10個。
其中：
BLOCKED：35個
RUNNABLE：32個
TIMED_WAITING：32個
WAITING：21個
 
BLOCKED的線程都卡在這裏：

145: "catalina-exec-411" Id=172907 BLOCKED on org.apache.log4j.spi.RootLogger@625fc53f owned by "catalina-exec-542" Id=174535
at org.apache.log4j.Category.callAppenders(Category.java:204)
- blocked on org.apache.log4j.spi.RootLogger@625fc53f
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.log(Category.java:856)
at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:517)
at com.dianping.cache.memcached.MemcachedClientImpl.get(MemcachedClientImpl.java:801)
at com.dianping.avatar.cache.CacheServiceContainer.get(CacheServiceContainer.java:401)
at com.dianping.avatar.cache.CacheServiceContainer.get(CacheServiceContainer.java:372)
at com.dianping.avatar.cache.DefaultCacheService$8.execute(DefaultCacheService.java:199)

catalina-exec-542以下：

194: "catalina-exec-542" Id=174535 RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:282)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202)
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272)
at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276)
at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122)
at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)
at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:59)

dw-hive-web主機上tomcat配置的最大線程數爲120個，排隊數最大30個，超過maxQueueSize會拒絕請求：

<Executor name="tomcatThreadPool" namePrefix="catalina-exec-"
         maxThreads="120" maxQueueSize="30" minSpareThreads="10" maxIdleTime="60000"/>
<Connector executor="tomcatThreadPool" protocol="org.apache.coyote.http11.Http11Protocol"
        port="8080" URIEncoding="UTF-8" compression="off" enableLookups="false" maxPostSize="0"
        maxKeepAliveRequests="20" bufferSize="8192" connectionTimeout="5000"
        redirectPort="8443" server="DPServer"  emptySessionPath="true"/>

bug修復前的tcp連接數：

bug修復以後，tcp減小的很明顯：

代碼修改以下，finally中的代碼是後加的，以前的bufferedReader沒有close：

緣由猜測是沒有關閉的bufferReader佔用了內存，連接的釋放時間是20分鐘，負載高的時候這部分堆內存短期是釋放不掉的，內存逐漸吃緊引發了Old GC（歡迎看到博客的小夥伴拍磚，對於JVM調優之類的我簡直就是小白）

後記：

一、修改以前每臺機器上有3000+處於CLOSE_WAIT的TCP鏈接（並且處於接收隊列的數據量都不爲0），都是連到hadoop的，TCP斷開的四次揮手中說是hadoop端主動斷開了連接，沒有收到本應用的FIN，因而鏈接處於CLOSE_WAIT狀態。

二、認真寫代碼真的很重要，生產環境中任何一個小bug均可能引發嚴重問題，而定位問題之路還挺漫長，少給後人挖坑是一個程序員的終極追求之一~

三、誰能告訴我怎麼修改博客的模板，整個模板都很難看有木有！

refer：

一、https://tomcat.apache.org/tomcat-6.0-doc/config/executor.html

二、TCP鏈接斷開過程-四次揮手：http://blog.163.com/guixl_001/blog/static/4176410420128310597692/