I have an application that spawns multiple short-lived java (IBM Java 8) programs in which they need to make an SSL request to a server. I am running into an issue where if I run several instances of these in parallel they all take an equal amount, and much longer time to run. In some cases it saves almost no time as if I had run them serially. For example, if 1 instance takes 3 seconds to run, if I run 5 in parallel they might all take 15 seconds to run.
I have noticed that this does not seem to be an issue on Windows systems. I'm not very familiar with the Java security libraries, and I did find this post Slow SecureRandom initialization which seems like it might be the root cause, but I was unable to get the code snippets to work for the Cipher.getInstance() call.
To demonstrate the problem, I have distilled it down to this code snippet:
import java.io.IOException;
import java.io.InputStreamReader;
import java.lang.management.ManagementFactory;
import java.security.Provider;
import java.security.Security;
import java.util.ArrayList;
import java.util.IntSummaryStatistics;
import java.util.List;
import java.util.concurrent.Callable;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
import java.util.concurrent.ThreadPoolExecutor;
import java.util.concurrent.TimeUnit;
import javax.crypto.Cipher;
public class CipherTesting {
private static final int DEFAULT = 20;
public static void main( String[] args ) throws Exception {
int num = parseArg( args );
if ( num > 1 ) {
ThreadPoolExecutor executor = (ThreadPoolExecutor) Executors.newFixedThreadPool( num );
List<Future<String>> results = new ArrayList<>();
for ( int i = 0 ; i < num ; i++ ) {
results.add( executor.submit( new Callable<String>() {
@Override
public String call() throws Exception {
String output = execute( "java", "-cp", System.getProperty( "java.class.path" ),
CipherTesting.class.getSimpleName(), "" + 1 );
return output;
}
} ) );
}
executor.shutdown();
executor.awaitTermination( 1, TimeUnit.MINUTES );
List<Integer> times = new ArrayList<>( num );
for ( Future<String> result : results ) {
System.err.println( result.get() );
times.add( Integer.parseInt( result.get().split( ":" )[1].trim() ) );
}
IntSummaryStatistics stats = times.stream().mapToInt( ( x ) -> x ).summaryStatistics();
System.out.println( stats.toString() );
} else {
test();
}
}
private static void test() {
try {
Provider provider = new com.ibm.crypto.plus.provider.IBMJCEPlusFIPS();
Security.insertProviderAt( provider, 1 );
long start = System.currentTimeMillis();
Cipher.getInstance( "AES/CBC/PKCS5Padding", provider.getClass().getSimpleName() );
long end = System.currentTimeMillis();
System.out.println( "JVM" + ManagementFactory.getRuntimeMXBean().getName().replaceAll( "@.+", "" )
+ " Time: " + ( end - start ) );
} catch ( Exception e ) {
e.printStackTrace();
}
}
private static int parseArg( String[] args ) {
if ( args.length == 0 ) {
return DEFAULT;
} else if ( args.length == 1 && args[0].trim().matches( "\\d+" ) ) {
return Integer.parseInt( args[0] );
} else {
System.out.println( "first argument must be a number" );
System.exit( 1 );
return 0;
}
}
private static String execute( String... commands ) throws IOException {
Runtime rt = Runtime.getRuntime();
Process proc = rt.exec( commands );
BufferedReader stdInput = new BufferedReader( new InputStreamReader( proc.getInputStream() ) );
// Read the output from the command
String s = null;
StringBuilder sb = new StringBuilder();
while ( ( s = stdInput.readLine() ) != null ) {
sb.append( s );
}
return sb.toString();
}
}
If you don't want to install IBM Java, I have tested this in the ibmjava docker container using the command:
λ docker run -it --rm -v %CD%:/example ibmjava:8 java -cp /example/bin/ CipherTestingSimple 20
JVM76 Time: 15469
JVM77 Time: 17598
JVM80 Time: 15173
JVM55 Time: 14612
JVM78 Time: 16281
JVM58 Time: 17610
JVM49 Time: 17600
JVM48 Time: 16641
JVM75 Time: 16497
JVM54 Time: 19725
JVM59 Time: 16494
JVM61 Time: 17435
JVM56 Time: 18056
JVM73 Time: 16212
JVM81 Time: 18385
JVM74 Time: 17136
JVM60 Time: 17857
JVM57 Time: 17073
JVM72 Time: 16422
JVM79 Time: 15348
IntSummaryStatistics{count=20, sum=337624, min=14612, average=16881.200000, max=19725}
Vs on windows:
JVM5476 Time: 906
JVM34144 Time: 3576
JVM28468 Time: 2751
JVM36084 Time: 2741
JVM16700 Time: 2560
JVM8640 Time: 2454
JVM34112 Time: 3140
JVM33364 Time: 3362
JVM17132 Time: 3999
JVM14160 Time: 3683
JVM11816 Time: 933
JVM33252 Time: 2878
JVM13660 Time: 2315
JVM12068 Time: 2416
JVM24240 Time: 3218
JVM30032 Time: 2965
JVM32316 Time: 3081
JVM14436 Time: 4532
JVM12764 Time: 2793
JVM14692 Time: 962
IntSummaryStatistics{count=20, sum=55265, min=906, average=2763.250000, max=4532}
I have also noticed a similar issue with calls to SSLSocketFactory.createSocket() but am hopeful that the solution to this Cipher problem would also solve that.
Thank you very much in advance.
Edit 1 05/04/2020 @rustyx
root@9a230345867e:/# cat $JAVA_HOME/lib/security/java.security | grep securerandom.source=
securerandom.source=file:/dev/urandom
I also killed one of the child java processes (after waiting about 7 seconds) using the -3 signal, which included the output:
JVMDUMP039I Processing dump event "user", detail "" at 2020/05/04 16:23:13 - please wait.
JVMDUMP032I JVM requested Java dump using '//javacore.20200504.162313.2812.0001.txt' in response to an event
JVMDUMP010I Java dump written to //javacore.20200504.162313.2812.0001.txt
JVMDUMP013I Processed dump event "user", detail "".
The output from that javacore can be found here.
Edit 2 05/04/2020 I should note, the code used when creating the javacore had the following lines commented out. Did this during my testing the code on open java and forgot to undo it. Behavior is still the same, but figured should mention.
Provider provider = new com.ibm.crypto.plus.provider.IBMJCEPlusFIPS();
Security.insertProviderAt( provider, 1 );
IBMJCEPlusFIPS is a U.S. export-controlled provider. Due to this, IBM JCE verifies the signatures of all bundled security JARs, in an attempt to enforce this.
If you take a few stacktrace samples of the main thread, you will see that it is indeed mainly busy verifying JAR files and a self-test (omitted here).
(sample) Java callstack:
at java/nio/DirectByteBuffer$Deallocator.<init>(DirectByteBuffer.java:72)
at java/nio/DirectByteBuffer.<init>(DirectByteBuffer.java:139)
at java/nio/ByteBuffer.allocateDirect(ByteBuffer.java:311)
at com/ibm/crypto/plus/provider/icc/FastJNIBuffer.<init>(FastJNIBuffer.java:24)
at com/ibm/crypto/plus/provider/icc/FastJNIBuffer.create(FastJNIBuffer.java:5)
at com/ibm/crypto/plus/provider/icc/Digest.<clinit>(Digest.java:129)
at com/ibm/crypto/plus/provider/icc/Signature.<init>(Signature.java:16)
at com/ibm/crypto/plus/provider/icc/Signature.getInstance(Signature.java:3)
at com/ibm/crypto/plus/provider/s.<init>(s.java:20)
at com/ibm/crypto/plus/provider/DSASignature$SHA1withDSA.<init>(DSASignature.java:1)
at sun/reflect/NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun/reflect/NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:83)
at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:57)
at java/lang/reflect/Constructor.newInstance(Constructor.java:437)
at com/ibm/crypto/plus/provider/r.newInstance(r.java:8)
at java/security/Signature.isSpi(Signature.java:297)
at java/security/Signature.getInstance(Signature.java:240)
at com/ibm/security/x509/X509CertImpl.verify(X509CertImpl.java:702)
(entered lock: com/ibm/security/x509/X509CertImpl@0x00000000FFF3DE78, entry count: 1)
at com/ibm/security/x509/X509CertImpl.verify(X509CertImpl.java:623)
at javax/crypto/b.a(Bytecode PC:80)
at javax/crypto/b.access$500(Bytecode PC:1)
at javax/crypto/b$a.run(Bytecode PC:88)
at java/security/AccessController.doPrivileged(AccessController.java:734)
at javax/crypto/b.<clinit>(Bytecode PC:1211)
at javax/crypto/Cipher.getInstance(Bytecode PC:93)
at javax/crypto/Cipher.getInstance(Bytecode PC:73)
at Test.test(Test.java:56)
at Test.main(Test.java:47)
(sample) Java callstack:
at com/ibm/security/bootstrap/InternalSHA.update(InternalSHA.java:128)
at com/ibm/security/bootstrap/DSASignature.engineUpdate(DSASignature.java:274)
at java/security/Signature.update(Signature.java:770)
at java/security/Signature.update(Signature.java:743)
at sun/security/pkcs/SignerInfo.verify(SignerInfo.java:516)
at sun/security/pkcs/PKCS7.verify(PKCS7.java:592)
at sun/security/pkcs/PKCS7.verify(PKCS7.java:609)
at sun/security/util/SignatureFileVerifier.processImpl(SignatureFileVerifier.java:297)
at sun/security/util/SignatureFileVerifier.process(SignatureFileVerifier.java:273)
at java/util/jar/JarVerifier.processEntry(JarVerifier.java:329(Compiled Code))
at java/util/jar/JarVerifier.update(JarVerifier.java:241(Compiled Code))
at java/util/jar/JarFile.initializeVerifier(JarFile.java:459)
at java/util/jar/JarFile.getInputStream(JarFile.java:526)
(entered lock: sun/net/www/protocol/jar/URLJarFile@0x00000000FFEF0438, entry count: 1)
at javax/crypto/a.a(Bytecode PC:165)
at javax/crypto/a.a(Bytecode PC:23)
at javax/crypto/a.a(Bytecode PC:28)
at javax/crypto/b.b(Bytecode PC:14)
at javax/crypto/b.a(Bytecode PC:79)
(entered lock: javax/crypto/b@0x00000000E0179208, entry count: 1)
at javax/crypto/Cipher.getInstance(Bytecode PC:93)
at javax/crypto/Cipher.getInstance(Bytecode PC:73)
at Test.test(Test.java:56)
at Test.main(Test.java:47)
(sample) Java callstack:
at java/lang/StringBuffer.append(StringBuffer.java:450)
(entered lock: java/lang/StringBuffer@0x00000000FFDF5068, entry count: 1)
at com/ibm/security/util/ObjectIdentifier.toString(ObjectIdentifier.java:479)
at com/ibm/security/x509/AVAKeyword.getKeyword(AVA.java:2093)
at com/ibm/security/x509/AVA.toKeyword(AVA.java:1092)
at com/ibm/security/x509/AVA.toString(AVA.java:1146)
at com/ibm/security/x509/RDN.toString(RDN.java:450)
at com/ibm/security/x509/X500Name.generateDN(X500Name.java:1231(Compiled Code))
at com/ibm/security/x509/X500Name.toString(X500Name.java:775)
at com/ibm/security/x509/X509CertInfo.parse(X509CertInfo.java:986)
at com/ibm/security/x509/X509CertInfo.<init>(X509CertInfo.java:240)
at com/ibm/security/x509/X509CertImpl.parse(X509CertImpl.java:2714)
at com/ibm/security/x509/X509CertImpl.<init>(X509CertImpl.java:231)
at com/ibm/crypto/provider/X509Factory.engineGenerateCertificate(Bytecode PC:91)
at java/security/cert/CertificateFactory.generateCertificate(CertificateFactory.java:350)
at com/ibm/crypto/provider/JavaKeyStore.engineLoad(Bytecode PC:585)
(entered lock: java/util/Hashtable@0x00000000FFCC9900, entry count: 1)
at java/security/KeyStore.load(KeyStore.java:1456)
at com/ibm/security/util/AnchorCertificates$1.run(AnchorCertificates.java:58)
at com/ibm/security/util/AnchorCertificates$1.run(AnchorCertificates.java:49)
at java/security/AccessController.doPrivileged(AccessController.java:678)
at com/ibm/security/util/AnchorCertificates.<clinit>(AnchorCertificates.java:49)
at com/ibm/security/cert/AlgorithmChecker.checkFingerprint(AlgorithmChecker.java:233)
at com/ibm/security/cert/AlgorithmChecker.<init>(AlgorithmChecker.java:174)
at com/ibm/security/cert/AlgorithmChecker.<init>(AlgorithmChecker.java:114)
at com/ibm/security/validator/SimpleValidator.engineValidate(SimpleValidator.java:151)
at com/ibm/security/validator/Validator.validate(Validator.java:257)
at com/ibm/security/validator/Validator.validate(Validator.java:233)
at com/ibm/security/validator/Validator.validate(Validator.java:202)
at javax/crypto/a.a(Bytecode PC:5)
at javax/crypto/a.a(Bytecode PC:451)
at javax/crypto/a.a(Bytecode PC:23)
at javax/crypto/a.a(Bytecode PC:28)
at javax/crypto/b.b(Bytecode PC:14)
at javax/crypto/b.a(Bytecode PC:79)
(entered lock: javax/crypto/b@0x00000000E0179208, entry count: 1)
at javax/crypto/Cipher.getInstance(Bytecode PC:93)
at javax/crypto/Cipher.getInstance(Bytecode PC:73)
at Test.test(Test.java:56)
at Test.main(Test.java:47)
(sample) Java callstack:
at java/util/ArrayDeque.add(ArrayDeque.java:434)
at java/util/zip/ZipFile.releaseInflater(ZipFile.java:533)
(entered lock: java/util/ArrayDeque@0x00000000E0150D08, entry count: 1)
at java/util/zip/ZipFile.access$100(ZipFile.java:76)
at java/util/zip/ZipFile$ZipFileInflaterInputStream.close(ZipFile.java:473)
at java/util/jar/JarVerifier$VerifierStream.close(JarVerifier.java:506)
at java/io/BufferedInputStream.close(BufferedInputStream.java:494)
at javax/crypto/a.a(Bytecode PC:193)
at javax/crypto/a.a(Bytecode PC:23)
at javax/crypto/a.a(Bytecode PC:28)
at javax/crypto/b.b(Bytecode PC:14)
at javax/crypto/b.a(Bytecode PC:79)
(entered lock: javax/crypto/b@0x00000000E00FC1E8, entry count: 1)
at javax/crypto/b.b(Bytecode PC:1)
at javax/crypto/Cipher.getInstance(Bytecode PC:117)
at CipherTesting.test(CipherTesting.java:77)
at CipherTesting.main(CipherTesting.java:56)
(sample) Java callstack:
at java/math/Division.modInverseMontgomery(Division.java:547)
at java/math/BigInteger.modInverse(BigInteger.java:1352)
at com/ibm/security/bootstrap/DSASignature.generateW(DSASignature.java:202)
at com/ibm/security/bootstrap/DSASignature.engineVerify(DSASignature.java:170)
at java/security/Signature.verify(Signature.java:661)
at sun/security/pkcs/SignerInfo.verify(SignerInfo.java:517)
at sun/security/pkcs/PKCS7.verify(PKCS7.java:592)
at sun/security/pkcs/PKCS7.verify(PKCS7.java:609)
at sun/security/util/SignatureFileVerifier.processImpl(SignatureFileVerifier.java:297)
at sun/security/util/SignatureFileVerifier.process(SignatureFileVerifier.java:273)
at java/util/jar/JarVerifier.processEntry(JarVerifier.java:329)
at java/util/jar/JarVerifier.update(JarVerifier.java:241(Compiled Code))
at java/util/jar/JarFile.initializeVerifier(JarFile.java:459)
at java/util/jar/JarFile.ensureInitialization(JarFile.java:708)
(entered lock: java/util/jar/JarFile@0x00000000E004B5E0, entry count: 1)
at java/util/jar/JavaUtilJarAccessImpl.ensureInitialization(JavaUtilJarAccessImpl.java:80)
at sun/misc/URLClassPath$JarLoader$2.getManifest(URLClassPath.java:1121)
at java/net/URLClassLoader.defineClass(URLClassLoader.java:689)
at java/net/URLClassLoader.access$400(URLClassLoader.java:96)
at java/net/URLClassLoader$ClassFinder.run(URLClassLoader.java:1187)
at java/security/AccessController.doPrivileged(AccessController.java:770)
at java/net/URLClassLoader.findClass(URLClassLoader.java:605)
at java/lang/ClassLoader.loadClassHelper(ClassLoader.java:944)
(entered lock: java/lang/ClassLoader$ClassNameBasedLock@0x00000000E00DA6B0, entry count: 1)
at java/lang/ClassLoader.loadClass(ClassLoader.java:889)
at java/lang/ClassLoader.loadClassHelper(ClassLoader.java:933)
(entered lock: java/lang/ClassLoader$ClassNameBasedLock@0x00000000E00DA6C0, entry count: 1)
at java/lang/ClassLoader.loadClass(ClassLoader.java:889)
at sun/misc/Launcher$AppClassLoader.loadClass(Launcher.java:349)
at java/lang/ClassLoader.loadClass(ClassLoader.java:872)
at sun/security/jca/ProviderConfig$2.run(ProviderConfig.java:227)
at sun/security/jca/ProviderConfig$2.run(ProviderConfig.java:218)
at java/security/AccessController.doPrivileged(AccessController.java:678)
at sun/security/jca/ProviderConfig.doLoadProvider(ProviderConfig.java:218)
at sun/security/jca/ProviderConfig.getProvider(ProviderConfig.java:199)
(entered lock: sun/security/jca/ProviderConfig@0x00000000E00716F0, entry count: 1)
at sun/security/jca/ProviderList.loadAll(ProviderList.java:294)
at sun/security/jca/ProviderList.removeInvalid(ProviderList.java:311)
at sun/security/jca/Providers.getFullProviderList(Providers.java:181)
at java/security/Security.insertProviderAt(Security.java:371)
(entered lock: java/security/Security@0x00000000E0019898, entry count: 1)
at Test.test(Test.java:54)
at Test.main(Test.java:47)
IBM JCE seems to be hard-coded to perform these checks and the classes are obfuscated, so bypassing it would not be straightforward.
If filesystem I/O is the bottleneck (which is definitely the case on Windows, let alone a VM running inside Windows), then you will see progressively worse performance from parallel execution.
You could try OpenJDK with a provider like BouncyCastle as a possible alternative.
But in general, Java VM startup is slow and this is another example of why you should prefer to start a JVM once and re-use it as much as possible.
If you want to investigate this further, use a profiler or this poor-mans profiler to see what the thread under test is busy with.
final Thread t = Thread.currentThread();
final String pid = ManagementFactory.getRuntimeMXBean().getName().replaceFirst("@.*", "");
Thread dumper = new Thread(() -> {
StringBuilder sb = new StringBuilder(4096);
for (int i = 0, step = 50; ; i += step) {
try { Thread.sleep(step); } catch (InterruptedException e) { break; }
sb.setLength(0);
for (StackTraceElement e : t.getStackTrace()) {
sb.append(" ").append(e).append("\n");
}
System.out.print(pid + " @" + i + "ms: [" + t.getName() + "]:\n" + sb);
}
});
dumper.start();
test(); // <-- work to be profiled goes here
dumper.interrupt();