OOM

There is one post tagged OOM.

Fight with Metaspace OOM

公司的 web application, 通常 redpeploy 多次之後, 就會發生 Metaspace OOM, 所以最近花了一些時間來解決這個問題.

現在公司內大部分的 web application 都是使用: Spring MVC (4.1.7) / Data / JPA / Log4j2, run 在 Tomcat 8.0.22 / CentOS.
首先, 要注意的是, Tomcat 在 undeploy web application 所出現的 warning message, like: 
WARNING: The web application [Test] appears to have started a thread named [Test-job_Worker-1] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread
這就代表, 這個 web application 有些 threads 沒有關. 這些 threads 一定要想辦法關掉, 否則 WebappClassLoader 就沒辦法被 GC, 就會造成 Metaspace memory leak 進而導致 Metasapce OOM 的主因.

分析現在手頭上的 web application, 主要有下列幾種 threads 沒有被關:

Log4j2:

Log4j2 本身的文件有提, web application 要放 log4j-web-.jar. 它會在 web application undeploy 時, 自動關閉 Log4j2 的相關 resoruces. 在我們的系統已經放了, 但問題還是沒有解決.

後來 Google 發現, 這和 Spring 也有關係.進一步修改 Log4j2 和 Spring 的 source code 來測試, 原來 Spring 自己的 ContextLoaderListener, 在 contextDestroyed() 時, 也會使用到 Logger.

所以如果 Log4j2 的 Log4jServletContextListener 的執行順序, 在 Spring 的 ContextLoaderListener 之後, 在 contextDestroyed 時, Log4jServletContextListener 的 method 會先執行, 它會盡責的把 Log4j2 的相關 resources 關掉, 然後執行到 Spring 的 ContextLoaderListener 的 contextDestroyed 時, 因為要 log message, Log4j2 又被 initial 一次, 然後… 然後… 然後… 就 leak 了…

而 log4j-web-.jar 本身是 web fragment, 它的 Log4jServletContextListener 會被自動初始化, 但一定是在 web.xml 之後. 所以它的 loading 順序就ㄧ定在 Spring 的 ContextLoaderListener 之後, 這就麻煩了…

後來再仔細看 Log4j2 的文件, “Servlet 3.0 and Newer Web Applications” 下的 “The Long Story” 這一個 section, 要加上 isLog4jAutoInitializationDisabled 的 context-param, 讓 Log4j2 不要被自動 initial: 
 <context-param>
    <param-name>isLog4jAutoInitializationDisabled</param-name>
    <param-value>true</param-value>
</context-param>
再參照 “Servlet 2.5 Web Applications” 這一 section, 將這些設定放在 web.xml 的最上面: 
<listener>
    <listener-class>org.apache.logging.log4j.web.Log4jServletContextListener</listener-class>
</listener>
 
<filter>
    <filter-name>log4jServletFilter</filter-name>
    <filter-class>org.apache.logging.log4j.web.Log4jServletFilter</filter-class>
</filter>
<filter-mapping>
    <filter-name>log4jServletFilter</filter-name>
    <url-pattern>/*</url-pattern>
    <dispatcher>REQUEST</dispatcher>
    <dispatcher>FORWARD</dispatcher>
    <dispatcher>INCLUDE</dispatcher>
    <dispatcher>ERROR</dispatcher>
    <dispatcher>ASYNC</dispatcher><!-- Servlet 3.0 w/ disabled auto-initialization only; not supported in 2.5 -->
</filter-mapping>
總算可以讓Log4jServletContextListener 比 Spring 的 ContextLoaderListener 更早被載入, 解決了第一個大問題.


PS. 可以直接在 web.xml 的最前面加上 Log4jServletContextListener 就好嗎? No… Log4jServletContextListener 這樣會被初始化 and 關閉兩次. 但關第二次的時候, Log4j2 有個 static variable, 判斷這個 Log4j2 是否已經被關過了, 如果被關過一次, 第二次就會跳過…

Tomcat 的 JVM 啟動參數還要加上 -Dlog4j2.disable.jmx=true

Quartz

首先在 web application 自己的 ServletContextListener 的 contextDestroyed() method 內, 要記得關掉 Quartz 的 scheduler 
Scheduler defaultScheduler = 
    StdSchedulerFactory.getDefaultScheduler();
defaultScheduler.shutdown(true);
但這樣還不夠, Tomcat shutdown 時, 還是一直 complain 有 Quartz 的 job_Worker 的 thread 沒有關掉…

後來總算找到, Quartz 的 SchedulerFactoryBean 的初始化參數要加上 waitForJobsToCompleteOnShutdown = true.

因為我們是用 Spring, 所以設定方法如下: 
<bean id="testFactoryBean"
 class="org.springframework.scheduling.quartz.SchedulerFactoryBean">
  ...
  <property name="waitForJobsToCompleteOnShutdown" value="true" />
  ...
</bean>

Others

再來就是 web application 如果自己有開 thread, 使用 ThreadLocal variables, 都要記得在 web application 自己的 ServletContextListener 的 contextDestroyed() 時, 關掉 or 清理.

另外也找到一個 library:
https://github.com/mjiderhamn/classloader-leak-prevention
可以協助找出沒有關的 threads, 另外它也可協助清理 ThreadLocal.

我們的 web applications 自己能清的都清了, 它最後還有幫我們清理 Spring 的 ThreadLocal variables.

Stress Testing

在確認 redeploy web application 時, Tomcat 不會 complain 有 threads 沒關之後, 再來就是 stress testing 了.

我用一個 shell script, 每 30 秒 touch 一次 web.xml,讓 Tomcat 可以 redeploy web application, 並且使用 VisualVM 來 monitor Metaspace.

但….. 請見下圖:
看第 1 點, Metaspace 確認在某個時間點會降下來, 證明應該沒有 Metaspace leak, 但在第 2 點, 就出現了 Metaspace OOM, 然後突然 Metaspace 就又突然降下來…

這我就搞不懂了, 修改 VM 參數, 做了很多測試, 結果還是差不多…
改用 CMS GC, 能夠撐久一點, 但最後還是發生了 OOM …

後來在 Metaspace 的高點時, 我做了一次 heapdump, 用 MAT 分析.
看 duplicate cases, 可以看到很多 class 被 WebappClassLoader 咬住, 這是意料之中的, 意料之外的是… 明明沒有 Metaspace leak, 為什麼這些 WebappClassLoader 沒有被 release …
依照以前抓 OOM 的慣例, right click 其中一個 WebappClassLoader, 然後選 Path To GC Roots | exclude all phatom/weak/soft. etc references, 也證明 WebappClassLoader 就是自己的 GC Root, 那不合理啊 … 它應該要被清掉啊…
這時候同一個 WebappClassLoader 再 click: Path To GC Roots | with all references, 喔… 還有這麼多 soft / weak / phantom references:
因為 weak references 在 GC 時, 一定會被清掉, 所以再點選 exclude weak references 來分析, 原來還有這麼多 soft references:
因為 soft references 的 objects 在 heap 保留一段時間, 所以才導致 Metaspace OOM.

因此再多加一個 JVM 參數: -XX:SoftRefLRUPolicyMSPerMB=10, 縮短 soft references 保留的時間, 這個 web application 就順順利利的被 redeploy 超過 1000 次了…


PS. 因為上到 production 之後, 我們也不可能這麼頻繁地 deploy web application, 所以這個參數也不會上到 production.


PS. 從這篇 https://stackoverflow.com/questions/299659/whats-the-difference-between-softreference-and-weakreference-in-java 可以知道 weak / soft references 的差異:
An object which is only weakly reachable (the strongest references to it are WeakReferences) will be discarded at the next garbage collection cycle, but an object which is softly reachable will generally stick around for a while.

Summary

  • 要注意 Tomcat 在 undeploy web application 所出現的 warning message
  • 如果使用 Log4j2 + Spring, 要讓 Log4jServletContextListener 先被 load
  • 如果使用 Quartz, 要記得關閉 scheduler
  • Web Application 自己開的 threads 要記得自己關, 這個 library 不錯用: https://github.com/mjiderhamn/classloader-leak-prevention
  • 有問題記得儘早抓 heapdump… 而且分析時, 不要只 exclude all phatom/weak/soft. etc references, 要注意 soft reference