JVM処理の遅延対策

このセクションでは、乱数生成に伴う JVM の処理遅延を回避する方法について、紹介します。 JVM には、認証フィルターでランダム値を生成しそのランダム値が認証チェック中に値が変更されていないかを確認した上で、ログインチェックを行い、認証成功と判断する機能があり、その処理が遅いために Tomcat の起動が遅くなる問題が発生します。

Tomcat 起動時に、Tomcat の catalina.out（ /usr/local/tomcat/logs/catalina.out ）を確認すると、Creation of SecureRandom に 820,211 ミリ秒かかっていることがわかります。状況によってはもっと遅くなることがあります。

[root@java-1 ~]# tail -F /usr/local/tomcat/logs/catalina.out 
30-Dec-2018 19:35:38.413 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/usr/local/tomcat
30-Dec-2018 19:35:38.415 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/local/tomcat
30-Dec-2018 19:35:38.416 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/usr/local/tomcat/temp
30-Dec-2018 19:35:38.425 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib]
30-Dec-2018 19:35:39.937 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
30-Dec-2018 19:35:40.917 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-8009"]
30-Dec-2018 19:35:40.971 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [12,177] milliseconds
30-Dec-2018 19:35:42.190 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
30-Dec-2018 19:35:42.207 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.14]
30-Dec-2018 19:35:42.643 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/ROOT]
30-Dec-2018 19:49:29.888 WARNING [main] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [820,211] milliseconds.

インストールされた JVM のパスを確認します。ここでは、JVM のパスが /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.191.b12-1.el7_6.x86_64 であることが確認できます。

[root@java-1 ~]# dirname $(dirname $(readlink $(readlink $(which javac))))
/usr/lib/jvm/java-1.8.0-openjdk-1.8.0.191.b12-1.el7_6.x86_64
[root@java-1 ~]#

java.security ファイル（ /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.191.b12-1.el7_6.x86_64/jre/lib/security/java.security ）を編集し、以下設定を変更します。

[root@java-1 ~]# vi /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.191.b12-1.el7_6.x86_64/jre/lib/security/java.security

securerandom.source=file:/dev/random
↓
securerandom.source=file:/dev/./urandom

変更後、Tomcat を再起動します。

[root@java-1 ~]# systemctl restart tomcat
[root@java-1 ~]#

Tomcat の catalina.out（ /usr/local/tomcat/logs/catalina.out ）を再度確認すると、Creation of SecureRandom に 188 ミリ秒で処理されていることがわかります。この対策で、Tomcat の起動がこれまでより早くなります。

[root@java-1 ~]# tail -F /usr/local/tomcat/logs/catalina.out 
30-Dec-2018 19:55:47.057 INFO [main] org.apache.catalina.core.StandardServer.await A valid shutdown command was received via the shutdown port. Stopping the Server instance.
30-Dec-2018 19:55:47.109 INFO [main] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8080"]
30-Dec-2018 19:56:03.450 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name:   Apache Tomcat/9.0.14
30-Dec-2018 19:56:03.502 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Dec 6 2018 21:13:53 UTC
30-Dec-2018 19:56:03.504 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 9.0.14.0
30-Dec-2018 19:56:03.505 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
30-Dec-2018 19:56:03.505 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            3.10.0-957.1.3.el7.x86_64
30-Dec-2018 19:56:03.506 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
30-Dec-2018 19:56:03.533 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.191.b12-1.el7_6.x86_64/jre
30-Dec-2018 19:56:03.535 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           1.8.0_191-b12
30-Dec-2018 19:56:03.536 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
30-Dec-2018 19:56:03.537 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /usr/local/tomcat
30-Dec-2018 19:56:03.538 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/local/tomcat
30-Dec-2018 19:56:03.542 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties
30-Dec-2018 19:56:03.575 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
30-Dec-2018 19:56:03.588 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
30-Dec-2018 19:56:03.592 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
30-Dec-2018 19:56:03.618 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
30-Dec-2018 19:56:03.623 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
30-Dec-2018 19:56:03.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/usr/local/tomcat
30-Dec-2018 19:56:03.634 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/local/tomcat
30-Dec-2018 19:56:03.640 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/usr/local/tomcat/temp
30-Dec-2018 19:56:03.658 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib]
30-Dec-2018 19:56:05.741 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
30-Dec-2018 19:56:06.705 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-8009"]
30-Dec-2018 19:56:06.827 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [12,365] milliseconds
30-Dec-2018 19:56:07.427 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
30-Dec-2018 19:56:07.429 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.14]
30-Dec-2018 19:56:07.686 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/ROOT]
30-Dec-2018 19:56:14.499 WARNING [main] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [188] milliseconds.