1. 程式人生 > 實用技巧 >Oracle JDK7 bug 發現、分析與解決實戰

Oracle JDK7 bug 發現、分析與解決實戰

本文首發於 vivo網際網路技術 微信公眾號
連結: https://mp.weixin.qq.com/s/8f34CaTp--Wz5pTHKA0Xeg
作者:vivo 官網商城開發團隊

眾所周知,Oracle JDK 是 Java 語言的絕對權威,很多時候 JDK 與 Java 語言近似一個概念。但我們始終要保持實事求是的精神,敢於質疑。本文記錄了一次線上troubleshoot 實戰,包含問題分析、解決並提交Oracle JDKbug 的核心過程。

一、背景現象

總之 就是某系統上線後 CLOSE_WAIT數量隨著時間增加而大量增加,持續觸發多個告警。

二、分析定位過程

部署了一個節點,用來複現之前出現的問題。

Step1 問題聚焦

先檢視到底是哪些IP之間的連線產生了大量CLOSE_WAIT,另外系統還會涉及調第三方,總之要確認連線建立的雙方。

執行命令:

netstat -np | grep tcp|grep "CLOSE_WAIT"

結果:

(ps:xxx、yyy、zzz 均無含義,基於資訊保安考慮,遮蔽掉 ip)。

tcp     3547      0 10.107.17.xxx:34602         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:59088         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:58028         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:51962         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp     3563      0 10.107.17.xxx:46962         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:34608         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:46496         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
           
tcp       38      0 10.107.17.xxx:50774         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:59904         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:40208         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:41064         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:36994         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
  
tcp     3547      0 10.107.17.xxx:45080         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp     6235      0 10.107.17.xxx:60966         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:56178         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp     3547      0 10.107.17.xxx:39922         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:43270         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:40926         zzz.202.32.242:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:44472         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp     2891      0 10.107.17.xxx:43036         zzz.202.32.241:443          CLOSE_WAIT  19819/java         
........
........
 
tcp       38      0 10.107.17.xxx:33472         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:51976         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:57788         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:35638         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:43778         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:46418         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:49914         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:49258         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:48718         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:51480         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:59816         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:49266         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:50246         yyy.12.230.115:443          CLOSE_WAIT  19819/java         
tcp       38      0 10.107.17.xxx:39324         yyy.12.230.115:443          CLOSE_WAIT  19819/java

總之:

yyy.12.230.115
zzz.202.32.241
zzz.202.32.241

這個三個IP是導火索。

Step2 問題分析

這三個IP具體是誰?具體是請求了哪個介面?

暫時無法直接獲知!最直接的導火索暫時斷了線索。接著從側面開始檢視更多資訊,

  • JVM資訊

    外部資源、執行緒 什麼的都看了,未發現明顯異常

  • 抓包

    要抓包獲取更多線索了。對於很久沒有碰過TCP層,有些吃力。

得到線索:發現大量的RST

那麼是什麼操作會導致CLOSE_WAIT呢?什麼樣的連線導致大量RST呢(可參考RST通常原因)?

Step3 程式碼分析定位

運維大佬的協助查詢,得知這三個IP是圖片CDN服務。

至此,可以定位到具體程式碼邏輯,圖片CDN請求可以排查程式碼。

仔細分析這部分原始碼後,推測因為伺服器 發起 URL請求,請求不存在,導致丟擲異常,但是JDK中卻沒有地方關閉Socket。

javax.imageio.read(URL)

/**
   * Returns a <code>BufferedImage</code> as the result of decoding
   * a supplied <code>URL</code> with an <code>ImageReader</code>
   * chosen automatically from among those currently registered.  An
   * <code>InputStream</code> is obtained from the <code>URL</code>,
   * which is wrapped in an <code>ImageInputStream</code>.  If no
   * registered <code>ImageReader</code> claims to be able to read
   * the resulting stream, <code>null</code> is returned.
   *
   * <p> The current cache settings from <code>getUseCache</code>and
   * <code>getCacheDirectory</code> will be used to control caching in the
   * <code>ImageInputStream</code> that is created.
   *
   * <p> This method does not attempt to locate
   * <code>ImageReader</code>s that can read directly from a
   * <code>URL</code>; that may be accomplished using
   * <code>IIORegistry</code> and <code>ImageReaderSpi</code>.
   *
   * @param input a <code>URL</code> to read from.
   *
   * @return a <code>BufferedImage</code> containing the decoded
   * contents of the input, or <code>null</code>.
   *
   * @exception IllegalArgumentException if <code>input</code> is
   * <code>null</code>.
   * @exception IOException if an error occurs during reading.
   */ 
public static BufferedImage read(URL input) throws IOException {
      if (input == null) {
          throw new IllegalArgumentException("input == null!");
      }
 
      InputStream istream = null;
      try {
       //此處,建立TCP連線!並且直接獲取流,因為流資料不存在,進入cache塊,丟擲!
          istream = input.openStream();
      } catch (IOException e) {
          throw new IIOException("Can't get input stream from URL!", e);
      }
      ImageInputStream stream = createImageInputStream(istream);
      BufferedImage bi;
      try {
          bi = read(stream);
          if (bi == null) {
              stream.close();
          }
      } finally {
          istream.close();
      }
      return bi;
  }

可以看到JDK並沒有關閉 ImageIO.read(url) 程式碼中封裝的Socket連線!CDN會請求超時關閉導致伺服器處於CLOSE_WAIT?限於網路經驗有限,並不能100%確認我的想法。所以模擬下吧。

Step4 復現與模擬

根據系統業務原始碼,快速模擬:

public static void main(String[] args) throws InterruptedException {
 
    ExecutorService ex = Executors.newFixedThreadPool(100);
    for (int i = 0; i < 5000; i++) {
        ex.execute(task());
    }
}
 
/**
 * @throws IOException
 * @throws MalformedURLException
 */
private static Runnable task() {
 
    return new Runnable() {
 
        @Override
        public void run() {
            // domain must exists,but file doesnot.
            String vivofsUrl = "https://vivobbs.xx.yy.zz/wiwNWYCFW9ieGbWq/20181129/3a2adfde12cd328d81f965088890eeffff.jpg";
 
            File file = null;
 
            BufferedImage image = null;
 
            try {
                file = File.createTempFile("abc", "jpg");
 
                URL url1 = new URL(vivofsUrl);
                image = ImageIO.read(url1);
 
            } catch (Throwable e) {
                e.printStackTrace();
            } finally {
                if (null != file) {
                    file.delete();
                }
                if (null != image) {
                    image.flush();
                    image = null;
                }
 
            }
        }
    };
}

抓包

TCP檢視

問題復現!

Step5 溝通後提報bug

report 給Oracle。

三、Oracle溝通

提單之後,Oracle跟我聯絡溝通。擷取部分郵件內容,僅供參考。

已被採納

四、疑點與不足

TCP狀態機的流轉不夠熟悉透徹。導致一些問題不能從TCP狀態機分析推理,知識的全面精通需要不斷提高。

更多內容敬請關注vivo 網際網路技術微信公眾號

注:轉載文章請先與微訊號:Labs2020聯絡。