かんがるーさんの日記

最近自分が興味をもったものを調べた時の手順等を書いています。今は Spring Boot をいじっています。

Spring Boot 1.4.x の Web アプリを 1.5.x へバージョンアップする ( その１５ )( -XX:+ExitOnOutOfMemoryError と -XX:+CrashOnOutOfMemoryError オプションのどちらを指定すべきか？ )

概要

記事一覧はこちらです。

Spring Boot 1.4.x の Web アプリを 1.5.x へバージョンアップする ( その１４ )( request, response のログを出力する RequestAndResponseLogger クラスを修正する ) の続きです。

  • 今回の手順で確認できるのは以下の内容です。
    • stackoverflow の Java - shutting down on Out of Memory Error の QA で 8u92 から -XX:+ExitOnOutOfMemoryError と -XX:+CrashOnOutOfMemoryError のオプションが追加になったと見かけて、そういえばどちらも指定していなかったことに気づきました。
    • ただし、ほとんど似たようなオプションに見えてどちらを指定した方がよいのかよく分からなかったので、その調査をします。

参照したサイト・書籍

  1. Java - shutting down on Out of Memory Error
    https://stackoverflow.com/questions/12096403/java-shutting-down-on-out-of-memory-error

  2. Print All JVM Flags
    https://stackoverflow.com/questions/10486375/print-all-jvm-flags

  3. Implement ExitOnOutOfMemory and CrashOnOutOfMemory in HotSpot
    https://bugs.openjdk.java.net/browse/JDK-8138745

  4. Release Note: New JVM Options: ExitOnOutOfMemoryError and CrashOnOutOfMemoryError
    https://bugs.openjdk.java.net/browse/JDK-8152669

  5. 8u92 Update Release Notes
    http://www.oracle.com/technetwork/java/javase/8u92-relnotes-2949471.html

  6. terazzoの日記 - JavaでOutOfMemoryErrorを出す方法
    http://d.hatena.ne.jp/terazzo/20130320/1363731368

目次

  1. 確認の前に -XX:HeapDumpPath, -XX:ErrorFile で指定するファイル名に日時が付くようにする
  2. -XX:+ExitOnOutOfMemoryError と -XX:+CrashOnOutOfMemoryError のオプションが追加されていることを確認する
  3. 実際に OutOfMemory が発生する処理を追加して相違点を確認する
    1. OutOfMemory が発生する処理を追加する
    2. どちらのオプションも指定していない場合、どうなるのか？
    3. -XX:+ExitOnOutOfMemoryError オプションを指定するとどうなるか？
    4. -XX:+CrashOnOutOfMemoryError オプションを指定するとどうなるか？
  4. まとめ
  5. webapp_startup.bat を修正する

手順

確認の前に -XX:HeapDumpPath, -XX:ErrorFile で指定するファイル名に日時が付くようにする

/webapps/ksbysample-webapp-lending/bat/webapp_startup.bat は現在以下の内容ですが、

@echo on

setlocal
set JAVA_HOME=C:\Java\jdk1.8.0_131
set PATH=%JAVA_HOME%\bin;%PATH%
set WEBAPP_HOME=C:\webapps\ksbysample-webapp-lending
set WEBAPP_JAR=ksbysample-webapp-lending-1.5.4-RELEASE.jar

cd /d %WEBAPP_HOME%
java -server ^
     -Xms1024m -Xmx1024m ^
     -XX:MaxMetaspaceSize=384m ^
     -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled ^
     -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=75 ^
     -XX:+ScavengeBeforeFullGC -XX:+CMSScavengeBeforeRemark ^
     -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps ^
     -Xloggc:%WEBAPP_HOME%/logs/gc.log ^
     -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M ^
     -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=%WEBAPP_HOME%/logs/%date:~0,4%%date:~5,2%%date:~8,2%.hprof ^
     -XX:ErrorFile=%WEBAPP_HOME%/logs/hs_err_pid_%p.log ^
     -Dsun.net.inetaddr.ttl=100 ^
     -Dcom.sun.management.jmxremote ^
     -Dcom.sun.management.jmxremote.port=7900 ^
     -Dcom.sun.management.jmxremote.ssl=false ^
     -Dcom.sun.management.jmxremote.authenticate=false ^
     -Dspring.profiles.active=product ^
     -jar lib\%WEBAPP_JAR%

以下の問題があることに気づきました。

  • -XX:HeapDumpPath=%WEBAPP_HOME%/logs/%date:~0,4%%date:~5,2%%date:~8,2%.hprof だとファイルに日付しか付かず、同じ日に HeapDump が出力された場合に前のファイルが上書きされてしまう。
  • -XX:ErrorFile=%WEBAPP_HOME%/logs/hs_err_pid_%p.log の %p でプロセス ID が付くものと思っていましたが、Windows だからなのかプロセス ID ではなくただの “p” になってしまう。

どちらもファイル名に日時が付くように以下のように変更します。この修正はファイル生成時に日時を付けるものではなく、最終的には -XX:+CrashOnOutOfMemoryError オプションを付けて、java コマンドが終了した後に日時の付いたファイル名に rename する想定のものです。

@echo on

setlocal
set JAVA_HOME=C:\Java\jdk1.8.0_131
set PATH=%JAVA_HOME%\bin;%PATH%
set WEBAPP_HOME=C:\webapps\ksbysample-webapp-lending
set WEBAPP_JAR=ksbysample-webapp-lending-1.5.4-RELEASE.jar
set LOGS_DIR=%WEBAPP_HOME%\logs
set PATH_HEAPDUMPFILE=%LOGS_DIR%\heapdump.hprof
set PATH_ERRORFILE=%LOGS_DIR%\hs_err.log

cd /d %WEBAPP_HOME%
java -server ^
     -Xms1024m -Xmx1024m ^
     -XX:MaxMetaspaceSize=384m ^
     -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled ^
     -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=75 ^
     -XX:+ScavengeBeforeFullGC -XX:+CMSScavengeBeforeRemark ^
     -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps ^
     -Xloggc:%WEBAPP_HOME%/logs/gc.log ^
     -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M ^
     -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=%PATH_HEAPDUMPFILE% ^
     -XX:ErrorFile=%PATH_ERRORFILE% ^
     -Dsun.net.inetaddr.ttl=100 ^
     -Dcom.sun.management.jmxremote ^
     -Dcom.sun.management.jmxremote.port=7900 ^
     -Dcom.sun.management.jmxremote.ssl=false ^
     -Dcom.sun.management.jmxremote.authenticate=false ^
     -Dspring.profiles.active=product ^
     -jar lib\%WEBAPP_JAR%

set YYYYMMDD=%date:~0,4%%date:~5,2%%date:~8,2%
set HHMMSS=%time:~0,8%
set HHMMSS=%HHMMSS::=%
set HHMMSS=%HHMMSS: =%
if exist %PATH_HEAPDUMPFILE% rename %PATH_HEAPDUMPFILE% heapdump_%YYYYMMDD%%HHMMSS%.hprof
if exist %PATH_ERRORFILE% rename %PATH_ERRORFILE% hs_err_%YYYYMMDD%%HHMMSS%.log

-XX:+ExitOnOutOfMemoryError と -XX:+CrashOnOutOfMemoryError のオプションが追加されていることを確認する

オプションが追加されたのは分かったのですが、実際に java.exe を実行する等してオプションを確認する方法があるのか気になったので調べて見ました。Print All JVM Flags を見ると java -XX:+UnlockDiagnosticVMOptions -XX:+PrintFlagsFinal を実行すれば表示されるようです。

8u131 で実行すると以下の行が出力されました。

     bool CrashOnOutOfMemoryError                   = false                               {product}
     bool ExitOnOutOfMemoryError                    = false                               {product}

実際に OutOfMemory が発生する処理を追加して相違点を確認する

OutOfMemory が発生する処理を追加する

src/main/java/ksbysample/webapp/lending/SampleController.java を以下のように変更します。-Xmx1024m と Java ヒープの最大サイズを 1024m で指定しているので、1024m の String を生成しようとすれば OutOfMemory になるはずです。

@Controller
@RequestMapping("/sample")
public class SampleController {

    ..........

    @RequestMapping("/outofmemory")
    @ResponseBody
    public void outofmemory() {
        String msg = StringUtils.repeat('x', 1024 * 1024 * 1024);
    }

}

clean タスク実行 → Rebuild Project 実行 → build タスクを実行して ksbysample-webapp-lending-1.5.4-RELEASE.jar を生成した後、C:\webapps\ksbysample-webapp-lending\lib の下へコピーします。

どちらのオプションも指定していない場合、どうなるのか？

webapp_startup.bat を実行して Tomcat を起動した後、http://localhost:8080/sample/outofmemory にアクセスすると OutOfMemoryError が発生します。

ログファイル ksbysample-webapp-lending.log には at ksbysample.webapp.lending.SampleController.outofmemory(SampleController.java:31) が出力されており、OutOfMemoryError が発生した原因の箇所が分かります。

org.springframework.web.util.NestedServletException: Handler dispatch failed; nested exception is java.lang.OutOfMemoryError: Java heap space
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:982)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:114)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.authentication.rememberme.RememberMeAuthenticationFilter.doFilter(RememberMeAuthenticationFilter.java:150)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:170)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:200)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.csrf.CsrfFilter.doFilterInternal(CsrfFilter.java:100)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:64)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:262)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:105)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:167)
    at org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:80)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:799)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:861)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.OutOfMemoryError: Java heap space
    at org.apache.commons.lang3.StringUtils.repeat(StringUtils.java:6087)
    at ksbysample.webapp.lending.SampleController.outofmemory(SampleController.java:31)
    at ksbysample.webapp.lending.SampleController$$FastClassBySpringCGLIB$$709005bd.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
    at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85)
    at ksbysample.webapp.lending.aspect.logging.RequestAndResponseLogger.logginRequestAndResponse(RequestAndResponseLogger.java:79)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629)
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618)
    at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
    at ksbysample.webapp.lending.SampleController$$EnhancerBySpringCGLIB$$a1afe1d0.outofmemory(<generated>)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)

コンソールには Heap dump file created のログが出力されるだけで、Web アプリケーションは終了しません。

f:id:ksby:20170717154509p:plain

C:\webapps\ksbysample-webapp-lending\logs の下には heapdump.hprof が作成されています。

f:id:ksby:20170717154620p:plain

コンソールで Ctrl+C を押して Tomcat を停止します。

-XX:+ExitOnOutOfMemoryError オプションを指定するとどうなるか？

webapp_startup.bat を以下のように変更します。

  • -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=%WEBAPP_HOME%/logs/%date:~0,4%%date:~5,2%%date:~8,2%.hprof ^ オプションを削除します。
  • -XX:+ExitOnOutOfMemoryError を追加します。
     -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M ^
     -XX:+ExitOnOutOfMemoryError ^
     -XX:ErrorFile=%PATH_ERRORFILE% ^

webapp_startup.bat を実行して Tomcat を起動した後、http://localhost:8080/sample/outofmemory にアクセスして OutOfMemoryError を発生させます。

ログファイル ksbysample-webapp-lending.log には何も出力されませんでした。

コンソールには Terminating due to java.lang.OutOfMemoryError: Java heap space と出力されて Web アプリケーションは終了しています。

f:id:ksby:20170717155253p:plain

C:\webapps\ksbysample-webapp-lending\logs の下には何も作成されません。

f:id:ksby:20170717155352p:plain

-XX:+CrashOnOutOfMemoryError オプションを指定するとどうなるか？

webapp_startup.bat を以下のように変更します。

  • -XX:+ExitOnOutOfMemoryError を削除して、-XX:+CrashOnOutOfMemoryError を追加します。
     -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M ^
     -XX:+CrashOnOutOfMemoryError ^
     -XX:ErrorFile=%PATH_ERRORFILE% ^

webapp_startup.bat を実行して Tomcat を起動した後、http://localhost:8080/sample/outofmemory にアクセスして OutOfMemoryError を発生させます。

-XX:+ExitOnOutOfMemoryError オプションの時と同じくログファイル ksbysample-webapp-lending.log には何も出力されません。

コンソールには Aborting due to java.lang.OutOfMemoryError: Java heap space と出力されて Web アプリケーションは終了しています。

f:id:ksby:20170717160028p:plain

C:\webapps\ksbysample-webapp-lending\logs の下には hs_err_20170717155857.log というファイルが作成されて、

f:id:ksby:20170717160226p:plain

hs_err_20170717155857.log を開くと以下のようなログが出力されています。このログファイルだとクラスとメソッドは分かりますが、行数までは分かりません。

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (debug.cpp:308), pid=10920, tid=0x0000000000002d64
#  fatal error: OutOfMemory encountered: Java heap space
#
# JRE version: Java(TM) SE Runtime Environment (8.0_131-b11) (build 1.8.0_131-b11)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.131-b11 mixed mode windows-amd64 compressed oops)
# Failed to write core dump. Minidumps are not enabled by default on client versions of Windows
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
#

---------------  T H R E A D  ---------------

Current thread (0x000000005f7b4000):  JavaThread "http-nio-8080-exec-1" daemon [_thread_in_vm, id=11620, stack(0x0000000065f00000,0x0000000066000000)]

Stack: [0x0000000065f00000,0x0000000066000000]
[error occurred during error reporting (printing stack bounds), id 0xc0000005]

Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)

Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
j  org.apache.commons.lang3.StringUtils.repeat(CI)Ljava/lang/String;+8
j  ksbysample.webapp.lending.SampleController.outofmemory()V+4
..........

まとめ

  • -XX:+ExitOnOutOfMemoryError オプションを指定すると何もログを出力せずに Web アプリケーションが終了します。
  • -XX:+CrashOnOutOfMemoryError オプションを指定すると -XX:ErrorFile オプションで指定されたファイルにエラーファイルが生成されて Web アプリケーションが終了します。-XX:ErrorFile オプションを指定していない場合にはデフォルトの設定場所（ksbysample-webapp-lending の場合は C:\webapps\ksbysample-webapp-lending でした）に生成されます。このファイルを見ると OutOfMemory が発生したクラスとメソッドは分かりますが、行数までは分かりません。
  • -XX:+ExitOnOutOfMemoryError あるいは -XX:+CrashOnOutOfMemoryError オプションを指定すると Web アプリケーションのログファイルには Caused by: java.lang.OutOfMemoryError: Java heap space のログは出力されません。
  • どちらのオプションも指定しなければ Web アプリケーションは終了しません。また Web アプリケーションのログファイルに Caused by: java.lang.OutOfMemoryError: Java heap space のログが出力されます。このログが出力されると OutOfMemory が発生したファイルと行数が分かります。
  • HeapDump は -XX:+ExitOnOutOfMemoryError あるいは -XX:+CrashOnOutOfMemoryError オプションの有無とは全く関係がなく、-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=... オプションを指定すれば出力されます。

個人的な感想としては、

  • OutOfMemory 発生時に Web アプリケーションのログファイルに発生箇所のファイル名、行番号のログが出力された方がよくて、かつ Web アプリケーションが終了せずエラーが発生し続けても構わないのであれば -XX:+ExitOnOutOfMemoryError も -XX:+CrashOnOutOfMemoryError も指定しません。
  • Web アプリケーションが終了すれば自動的に再起動する仕組みがあり、Web アプリケーションのログファイルに発生箇所のファイル名、行番号のログが出力される必要がないのであれば -XX:+CrashOnOutOfMemoryError を指定して終了するようにして、エラーファイルが生成されるようにします。
  • -XX:+ExitOnOutOfMemoryError あるいは -XX:+CrashOnOutOfMemoryError オプションを指定する／しないに関わらず、-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=... オプションは指定して HeapDump は出力した方がよいです。
  • -XX:+ExitOnOutOfMemoryError は存在意義がよく分かりませんでした。HeapDump だけで OutOfMemory の原因を調査するのは難しい気がします。今回出力された HeapDump を Memory Analyzer で開いてみましたが、今回のような実装が原因であれば Caused by: java.lang.OutOfMemoryError: Java heap space のログが出てくれた方が分かりやすいかな、と思いました。

webapp_startup.bat を修正する

オプションを忘れないようにするために、webapp_startup.bat には -XX:+CrashOnOutOfMemoryError を追加することにします。

@echo on

setlocal
set JAVA_HOME=C:\Java\jdk1.8.0_131
set PATH=%JAVA_HOME%\bin;%PATH%
set WEBAPP_HOME=C:\webapps\ksbysample-webapp-lending
set WEBAPP_JAR=ksbysample-webapp-lending-1.5.4-RELEASE.jar
set LOGS_DIR=%WEBAPP_HOME%\logs
set PATH_HEAPDUMPFILE=%LOGS_DIR%\heapdump.hprof
set PATH_ERRORFILE=%LOGS_DIR%\hs_err.log

cd /d %WEBAPP_HOME%
java -server ^
     -Xms1024m -Xmx1024m ^
     -XX:MaxMetaspaceSize=384m ^
     -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled ^
     -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=75 ^
     -XX:+ScavengeBeforeFullGC -XX:+CMSScavengeBeforeRemark ^
     -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps ^
     -Xloggc:%WEBAPP_HOME%/logs/gc.log ^
     -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M ^
     -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=%PATH_HEAPDUMPFILE% ^
     -XX:+CrashOnOutOfMemoryError ^
     -XX:ErrorFile=%PATH_ERRORFILE% ^
     -Dsun.net.inetaddr.ttl=100 ^
     -Dcom.sun.management.jmxremote ^
     -Dcom.sun.management.jmxremote.port=7900 ^
     -Dcom.sun.management.jmxremote.ssl=false ^
     -Dcom.sun.management.jmxremote.authenticate=false ^
     -Dspring.profiles.active=product ^
     -jar lib\%WEBAPP_JAR%

set YYYYMMDD=%date:~0,4%%date:~5,2%%date:~8,2%
set HHMMSS=%time:~0,8%
set HHMMSS=%HHMMSS::=%
set HHMMSS=%HHMMSS: =%
if exist %PATH_HEAPDUMPFILE% rename %PATH_HEAPDUMPFILE% heapdump_%YYYYMMDD%%HHMMSS%.hprof
if exist %PATH_ERRORFILE% rename %PATH_ERRORFILE% hs_err_%YYYYMMDD%%HHMMSS%.log

履歴

2017/07/17
初版発行。