Cipher.getInstance() 在 unix 平台上从多个 JVM 实例调用时变慢

Cipher.getInstance() slow when called from multiple JVM instances on unix platforms

我有一个应用程序生成多个短暂的 java (IBM Java 8) 程序,它们需要在其中向服务器发出 SSL 请求。我正在 运行 遇到一个问题,如果我 运行 并行这些实例的多个实例,它们都需要相同的数量,并且 运行 需要更长的时间。在某些情况下,它几乎没有节省时间,就好像我连续 运行 它们一样。例如,如果 1 个实例需要 3 秒才能达到 运行,如果我 运行 5 个并行,它们可能都需要 15 秒才能达到 运行。

我注意到这在 Windows 系统上似乎不是问题。我对 Java 安全库不是很熟悉,我确实发现了这个 post 这似乎是根本原因,但我无法获得代码片段为 Cipher.getInstance() 电话工作。

为了演示该问题,我将其提炼为以下代码片段:

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();
    }
}

如果您不想安装 IBM Java,我已经在 ibmjava docker 容器中使用以下命令对此进行了测试:

λ  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}

对比 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}

我也注意到调用 SSLSocketFactory.createSocket() 时存在类似的问题,但我希望这个 Cipher 问题的解决方案也能解决这个问题。

非常感谢您。

编辑 1 2020 年 5 月 4 日 @rustyx

root@9a230345867e:/# cat $JAVA_HOME/lib/security/java.security | grep securerandom.source=
securerandom.source=file:/dev/urandom

我还使用 -3 信号杀死了一个 java 子进程(等待大约 7 秒后),其中包括输出:

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 "".

可以找到 java 核心的输出 here

编辑 2 2020 年 5 月 4 日 我应该注意,创建 javacore 时使用的代码将以下行注释掉了。在我测试 open java 上的代码时这样做了,但忘了撤消它。行为仍然相同,但应该提及。

            Provider provider = new com.ibm.crypto.plus.provider.IBMJCEPlusFIPS();
            Security.insertProviderAt( provider, 1 );

IBMJCEPlusFIPS 是 U.S。出口管制供应商。因此,IBM JCE 会验证所有捆绑的安全 JAR 的签名,以尝试强制执行此操作。

如果你拿几个主线程的stacktrace样本,你会发现它确实主要忙于验证JAR文件和自检(此处省略)。

(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.access0(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.run(AnchorCertificates.java:58)
    at com/ibm/security/util/AnchorCertificates.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.access0(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.getManifest(URLClassPath.java:1121)
    at java/net/URLClassLoader.defineClass(URLClassLoader.java:689)
    at java/net/URLClassLoader.access0(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.run(ProviderConfig.java:227)
    at sun/security/jca/ProviderConfig.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 似乎被硬编码来执行这些检查并且 类 被混淆了,因此绕过它并不简单。

如果文件系统 I/O 是瓶颈(在 Windows 上肯定是这种情况,更不用说 Windows 中的 VM 运行),那么您会逐渐看到并行执行的性能更差。

您可以尝试将 OpenJDK 与 BouncyCastle 等提供程序一起作为可能的替代方案。

但总的来说,Java VM 启动很慢,这是另一个例子,说明为什么您应该更喜欢启动 JVM 一次并尽可能多地重复使用它。


如果您想进一步调查,请使用探查器或这个可怜的探查器来查看被测线程在忙什么。

    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();