I am trying to debug a few slow responses served by an app deployed on Tomcat.
Right now I am focussing on SecureRandom
and /dev/random
(some of the other probable causes have been investigated and ruled out).
The pattern is as follows:
- The first call takes exactly 30.0xy seconds after Tomcat restart (even if the request arrives 4 minutes after the Startup)
- Later, some calls take exactly 15.0pq seconds (there was no specific pattern that I could establish, pq being the time approximate time taken in TP99)
The service call involves encryption and decryption (AES/ECB/PKCS5Padding).
Is it possible that SecureRandom init/repopulating is leading to this?
(Although, there is a log written in catalina.log that says "Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [28,760] milliseconds."
)
Also, in order to check whether /dev/random
or /dev/urandom
is being used, I used the test from this question. To my surprise, I didn't see reads from either of them unlike the way it happens in the linked question.
These are the last few lines from the strace
log:
3561 lstat("/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/jsse.jar", {st_mode=S_IFREG|0644, st_size=258525, ...}) = 0
3561 open("/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/jsse.jar", O_RDONLY) = 6
3561 stat("/dev/random", {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 8), ...}) = 0
3561 stat("/dev/urandom", {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) = 0
3561 open("/dev/random", O_RDONLY) = 7
3561 open("/dev/urandom", O_RDONLY) = 8
3561 unlink("/tmp/hsperfdata_xxxx/3560") = 0
What is then being used for seeding SecureRandom?
fyi, java -version
java version "1.6.0_32"
OpenJDK Runtime Environment (IcedTea6 1.13.4) (rhel-7.1.13.4.el6_5-x86_64)
OpenJDK 64-Bit Server VM (build 23.25-b01, mixed mode)
I could not check your OpenJDK concrete version, but I could check jdk6-b33.
SecureRandom uses SeedGenerator to get the seed bytes
SeedGenerator gets the
seedSource
(String) from SunEntriesSunEntries
tries to get the source from the system propertyjava.security.egd
first, if is not found then tries to get the propertysecurerandom.source
from thejava.security
properties file, if the property is not found returns a blank string.the
SeedGenerator
check this value to initialize the instanceif the source is
or
uses the
NativeSeedGenerator
, on Windows tries to use the nativeCryptoAPI
on Linux the class simply extends theSeedGenerator.URLSeedGenerator
and call to the superclass constructor who loads
/dev/random
by defaultso, OpenJDK uses
/dev/random
by default until you do not set another value in the system propertyjava.security.egd
or in the propertysecurerandom.source
of security properties file.If you want to see the read results using
strace
you can change the command line and add thetrace=open,read
expressionthe you can see something like this (I did the test with Oracle JDK 6)
The Tomcat Wiki section for faster startup suggest using a non-blocking entropy source like /dev/urandom if you are experiencing delays during startup
More info: https://wiki.apache.org/tomcat/HowTo/FasterStartUp#Entropy_Source
Hope this helps.
The problem is not SecureRandom per se but that /dev/random blocks if it doesn't have enough data. You can use urandom instead but that might not be a good idea if you need cryptographically strong random seeds. On headless Linux systems you can install the haveged daemon. This keeps /dev/random topped up with enough data so that calls don't have to wait for the required entropy to be generated. I've done this on a Debian Aws instance and watched SecureRandom generateBytes calls drop from 25 seconds to sub millisecond (Openjdk 1.7 something, can't remember specifically what version).