JDK-8023983 : SHA2 calculation extremely slow under unknown conditions
  • Type: Bug
  • Component: security-libs
  • Sub-Component: java.security
  • Affected Version: 7u11
  • Priority: P3
  • Status: Closed
  • Resolution: Cannot Reproduce
  • OS: linux
  • Submitted: 2013-04-04
  • Updated: 2016-06-16
  • Resolved: 2016-05-17
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 9
9Resolved
Related Reports
Duplicate :  
Relates :  
Relates :  
Description
FULL PRODUCT VERSION :
java version  " 1.7.0_11 " 
Java(TM) SE Runtime Environment (build 1.7.0_11-b21)
Java HotSpot(TM) 64-Bit Server VM (build 23.6-b04, mixed mode)

ADDITIONAL OS VERSION INFORMATION :
Linux giantspider 2.6.18-308.el5 #1 SMP Tue Feb 21 20:06:06 EST 2012 x86_64 x86_64 x86_64 GNU/Linux

EXTRA RELEVANT SYSTEM CONFIGURATION :
model name: Intel(R) Xeon(R) CPU           E5520  @ 2.27GHz
16 cores, 48 GB RAM

A DESCRIPTION OF THE PROBLEM :
In some condition, hashing via the SHA2 module becomes extremely slow. It feels like a Hotspot miscompilation of some sort, but it doesn't always occur, and we've been unable to isolate a test case for it. It has happened often enough that it wasn't a one time fluke and happened on at least two different machines in our production infrastructure. The lowest level of the stack trace is usually (always?) one of three places:



at sun.security.provider.SHA2.lf_S(SHA2.java:162)
at sun.security.provider.SHA2.lf_sigma1(SHA2.java:180)
at sun.security.provider.SHA2.implCompress(SHA2.java:225)
at sun.security.provider.SHA2.implDigest(SHA2.java:118)

at sun.misc.Unsafe.putInt(Native Method)
at sun.security.provider.ByteArrayAccess.i2bBig(ByteArrayAccess.java:300)
at sun.security.provider.SHA2.implDigest(SHA2.java:120)

at sun.misc.Unsafe.putInt(Native Method)
at sun.security.provider.ByteArrayAccess.i2bBig4(ByteArrayAccess.java:325)
at sun.security.provider.SHA2.implDigest(SHA2.java:116)


A less trimmed stack trace looks like the following:

2013-03-04 13:03:53,438 INFO  SchedulableTask-com.myorg.common.usage.SlowPages [slowPagesPerformance] RequestURI=/myorg/services/AdminService_1_0;ThreadName=http-0.0.0.0-8080-7;Started at=2013-03-04 13:02:53;Owner=-666;User=Unknown User;Type=Service;Session=B29FDCC4AAD29343C2B642BF0C77CC2E;Method=POST;Resource=/myorg/services/AdminService_1_0/isAdmin;RequestNum=356737;;SNUH=303d3cb7ee2b126544a99802c543d49b;StackTrace=java.lang.Throwable
at sun.security.provider.SHA2.lf_S(SHA2.java:162)
at sun.security.provider.SHA2.lf_delta0(SHA2.java:189)
at sun.security.provider.SHA2.implCompress(SHA2.java:210)
at sun.security.provider.SHA2.implDigest(SHA2.java:118)
at sun.security.provider.DigestBase.engineDigest(DigestBase.java:186)
at sun.security.provider.DigestBase.engineDigest(DigestBase.java:165)
at java.security.MessageDigest$Delegate.engineDigest(MessageDigest.java:576)
at java.security.MessageDigest.digest(MessageDigest.java:353)
at java.security.MessageDigest.digest(MessageDigest.java:399)
at org.jasypt.digest.StandardByteDigester.digest(StandardByteDigester.java:979)
at org.jasypt.digest.StandardByteDigester.matches(StandardByteDigester.java:1099)
at org.jasypt.digest.StandardStringDigester.matches(StandardStringDigester.java:1052)
at org.jasypt.digest.PooledStringDigester.matches(PooledStringDigester.java:693)
at com.myorg.auth.AuthenticationUtil.passwordMatches(AuthenticationUtil.java:53)
at com.myorg.auth.AuthenticationUtil.passwordMatchesWithFallback(AuthenticationUtil.java:61)
at com.myorg.fundbutter.security.JaasPasswordAuthenticator.passwordMatchesWithFallback(JaasPasswordAuthenticator.java:18)
at com.myorg.fundbutter.security.SimpleUser.passwordValid(SimpleUser.java:339)
at com.myorg.fundbutter.webservice.XFireServlet$AuthenticationInHandler.invoke(XFireServlet.java:235)

Normally passwordMatches returns in ~40ms, but it takes ~4000ms when this particular problem occurs.

REGRESSION.  Last worked in version 6u31

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
I've still yet to see this manifest itself when run under a test harness. It averages 40ms a call there rather than ~4000ms. I will attach the harness I have, even though it doesn't seem to ever hit the problem.

When this does manifest itself in the full web application, it is 100% reproducible and doesn't go away or show any form of transience.

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
Each iteration of the full password hash takes ~40ms.
ACTUAL -
Each iteration of the full password hash nearly 4 seconds (~4000 ms).

REPRODUCIBILITY :
This bug can be reproduced occasionally.

---------- BEGIN SOURCE ----------
/ tested with jasypt-1.7.1.jar, available at
// http://sourceforge.net/projects/jasypt/files/jasypt/jasypt%201.7.1/
// run with java -server -cp jasypt-1.7.1.jar:. TestHash

import org.jasy/pt.digest.PooledStringDigester;
import org.jasypt.digest.StringDigester;


public class TestHash {
    private static final int REPORT_INTERVAL = 1;

    private static StringDigester makeStrongDigester() {
        PooledStringDigester digester = new PooledStringDigester();
        digester.setPoolSize(4);

        digester.setAlgorithm( " SHA-256 " );
        digester.setIterations(50000);
        return digester;
    }

    public static void main(String[] args) {
        StringDigester digester = makeStrongDigester();
        final String pass =  " thisisatest " ;
        final long start = System.currentTimeMillis();
        long last = start;
        int count = 0;

        for (int i = 0; i < 200; i++) {
            String fullPass = pass + i;
            String hash = digester.digest(fullPass);
            for (int j = 0; j < 20; j++) {
                boolean matches = digester.matches(fullPass, hash);
                count++;
                if (!matches) {
                    throw new RuntimeException( " Passwords should have matched " );
                }
                matches = digester.matches(fullPass + j, hash);
                count++;
                if (matches) {
                    throw new RuntimeException( " Passwords should not have matched " );
                }
                if (count % REPORT_INTERVAL == 0) {
                    long now = System.currentTimeMillis();
                    System.out.printf( " %d total iterations completed, %.2f ms per iteration this round, %.2f ms overall
 " ,
                            count, (double)(now - last) / REPORT_INTERVAL, (double)(now - start) / count);
                    last = System.currentTimeMillis();
                }
            }
        }
    }
}
---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
We have not found one, short of restarting our production server. Sometimes it does not encounter this problem during day-to-day operation, other times it slows down every single call until the server is restarted.
Comments
The reporter is using an 3rd party crypto API and the jar has not been updated in 3 years old. We have no idea what this API is doing. There have been far to few occurrences of this issue that if it was still valid we would see it reported widely. Chances are this was JIT realated as another project showed very slow performance without the JIT. There have been instances where fastdebug or debug builds don't use the JIT fully. Also running with -X shuts off the JIT. If there was a bug in the JIT, it has been resolved as there have been no further reports of problems. SHA2 doesn't keep state, so why as reported that SHA2 stopped working until the app was rebooted is bizarre and still points outside the SHA2 code itself. If this does occur again, chances are it should be filed under hotspot and must show that the app was using standard crypto APIs and the JIT wasn't disabled.
17-05-2016

It has been suggested that these slow conditions maybe the result of the JIT. The numbers below show the performance difference the JIT offers: JDK9: 1648909 ops/s JDK9 -Xint: 5672 ops/s It is certainly possible in rare situations with low usage in production builds and more likely in debug builds, that the JIT may not activate to optimize SHA. My suspicion is typically the difference between JIT and non-JIT isn't as large and is not as obvious. With SHA's large of a performance difference and given this is a performance test it would only take a few slow operations to drag down performance.
16-04-2015

A workaround was provided for the related JDK-8067664, which was to use buffered I/O.
03-02-2015

feel free to delete. Thanks.
16-12-2014

There are two identical versions of reproducer.jar attached here. Maybe one could be deleted?
16-12-2014

couldn't attach the reproducer here somehow, will attach it to coherence bug19818796.
14-12-2014

We can consistently replicate the problem on linux. Here is the bug link: https://bug.oraclecorp.com/pls/bug/webbug_edit.edit_info_top?rptno=19818796 I have created a standalone test, will attaching the test case to the bug. steps to replicate: 1. ./compile.sh 2. ./run.sh Run the test on both mac (or window) and linux, you should see the slowness on linux.
14-12-2014

Is the submitter still seeing this problem?
05-12-2014

Release build works just fine, something about the fastdebug build that is slowing this to a crawl. Glad to know whatever I'm seeing is not likely to show up in a production build.
19-12-2013

I have run the same tests using promoted builds from 8b120 all the way back to 7u4 and am not able to duplicate my particular situation. Am wondering if there is something in my build. I have been testing with --enable-debug, going to take this out and try again with a "release" build instead.
19-12-2013

SeanC wrote: > would you be able to capture a JFR recording of a troublesome test run? It might help shed more light on who's doing what in the system. Not sure how yet, it only appears for me when I'm stepping through a finite number of lines. Vinnie wrote: > You can demonstrate the issue using EC but you don't think it might > be caused by EC do you? The SunEC JAR has an RSA signature. No, it's apparently the first signed provider in the list. If I remove the SunEC provider and change the code to: Signature sig = Signature.getInstance("MD5withRSA", "SunMSCAPI"); It now stalls when verifying the sunjce_provider.jar file. I then changed it to: Signature sig = Signature.getInstance("MD2withRSA"); and rearranged the provider list: security.provider.1=sun.security.provider.Sun security.provider.2=com.sun.crypto.provider.SunJCE security.provider.3=com.sun.net.ssl.internal.ssl.Provider security.provider.4=sun.security.rsa.SunRsaSign security.provider.5=sun.security.jgss.SunProvider security.provider.6=com.sun.security.sasl.Provider security.provider.7=org.jcp.xml.dsig.internal.dom.XMLDSigRI security.provider.8=sun.security.smartcardio.SunPCSC In this case, SunRsaSign is the selected provider, but only SunJCE is verified. I turned on java.security.debug=jca: ProviderList: provider configuration: [sun.security.provider.Sun, com.sun.crypto.provider.SunJCE, com.sun.net.ssl.internal.ssl.Provider, sun.security.rsa.SunRsaSign, sun.security.jgss.SunProvider, com.sun.security.sasl.Provider, org.jcp.xml.dsig.internal.dom.XMLDSigRI, sun.security.smartcardio.SunPCSC] ProviderConfig: Loading provider: sun.security.provider.Sun ProviderConfig: Loaded provider SUN version 1.8 ProviderConfig: Loading provider: com.sun.crypto.provider.SunJCE ProviderList: ThreadLocal providers: [sun.security.provider.Sun, sun.security.rsa.SunRsaSign, sun.security.ec.SunEC, sun.security.provider.VerificationProvider] ProviderConfig: Loading provider: sun.security.rsa.SunRsaSign ProviderConfig: Loaded provider SunRsaSign version 1.8 ProviderList: Disabling ThreadLocal providers ProviderList: ThreadLocal providers: [sun.security.provider.Sun, sun.security.rsa.SunRsaSign, sun.security.ec.SunEC, sun.security.provider.VerificationProvider] ProviderList: Disabling ThreadLocal providers ProviderConfig: Loaded provider SunJCE version 1.8 ProviderConfig: Loading provider: com.sun.net.ssl.internal.ssl.Provider ProviderConfig: Loaded provider SunJSSE version 1.8
19-12-2013

This can be reproduced reliably using Netbeans 7.4 on my Windows 7 laptop. import java.security.Signature; public class DefaultSSLParameters { /** * @param args the command line arguments */ public static void main(String[] args) throws Exception { Signature sig = Signature.getInstance("NONEwithECDSA"); } } Set a breakpoint at the Signature line. If you run project (f6), the code runs in a few milliseconds. If you debug the project (ctrl+f5), then step over (F8) the breakpointed line, it will stall for 15 seconds. If you suspend the thread during the stall, you will find it is usually stuck in the SHA2 code while doing SHA256 bit signature verification of the sun.security.ec.SunEC/CurveDB/ECDSASignature/etc. "main" sun.security.provider.SHA2.lf_S(SHA2.java:146) sun.security.provider.SHA2.lf_sigma0(SHA2.java:155) sun.security.provider.SHA2.implCompress(SHA2.java:209) sun.security.provider.DigestBase.engineUpdate(DigestBase.java:126) java.security.MessageDigest$Delegate.engineUpdate(MessageDigest.java:568) java.security.MessageDigest.update(MessageDigest.java:313) sun.security.util.ManifestDigester.manifestDigest(ManifestDigester.java:267) sun.security.util.SignatureFileVerifier.verifyManifestHash(SignatureFileVerifier.java:296) sun.security.util.SignatureFileVerifier.processImpl(SignatureFileVerifier.java:234) sun.security.util.SignatureFileVerifier.process(SignatureFileVerifier.java:192) java.util.jar.JarVerifier.processEntry(JarVerifier.java:314) java.util.jar.JarVerifier.update(JarVerifier.java:226) java.util.jar.JarFile.initializeVerifier(JarFile.java:373) java.util.jar.JarFile.getInputStream(JarFile.java:440) sun.misc.URLClassPath$JarLoader$2.getInputStream(URLClassPath.java:776) sun.misc.Resource.cachedInputStream(Resource.java:77) sun.misc.Resource.getByteBuffer(Resource.java:160) java.net.URLClassLoader.defineClass(URLClassLoader.java:442) java.net.URLClassLoader.access$100(URLClassLoader.java:73) java.net.URLClassLoader$1.run(URLClassLoader.java:367) java.net.URLClassLoader$1.run(URLClassLoader.java:361) java.security.AccessController.doPrivileged(AccessController.java) java.net.URLClassLoader.findClass(URLClassLoader.java:360) java.lang.ClassLoader.loadClass(ClassLoader.java:424) java.lang.ClassLoader.loadClass(ClassLoader.java:411) sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308) java.lang.ClassLoader.loadClass(ClassLoader.java:357) sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:215) sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:206) java.security.AccessController.doPrivileged(AccessController.java) sun.security.jca.ProviderConfig.doLoadProvider(ProviderConfig.java:206) sun.security.jca.ProviderConfig.getProvider(ProviderConfig.java:187) sun.security.jca.ProviderList.getProvider(ProviderList.java:233) sun.security.jca.ProviderList$ServiceList.tryGet(ProviderList.java:434) sun.security.jca.ProviderList$ServiceList.access$200(ProviderList.java:376) sun.security.jca.ProviderList$ServiceList$1.hasNext(ProviderList.java:486) java.security.Signature.getInstance(Signature.java:223) defaultsslparameters.DefaultSSLParameters.main(DefaultSSLParameters.java:23) If this code is contained within other code, and I put breakpoints in sufficiently far away from this call, I don't see the stall either. Very strange.
18-12-2013

Unable to reproduce with testcase provided. I tested with jasypt as suggested. Any pointers to reproduce this would be helpful.
29-11-2013

When putting a JCE JDK 8 jar through it's verification steps while under NetBeans, I'm encountering a similar problem. It is taking forever to verify in some cases, but drops right through in others. "main" sun.security.provider.SHA2.lf_delta1(SHA2.java:182) sun.security.provider.SHA2.implCompress(SHA2.java:194) sun.security.provider.DigestBase.engineUpdate(DigestBase.java:126) java.security.MessageDigest$Delegate.engineUpdate(MessageDigest.java:568) java.security.MessageDigest.update(MessageDigest.java:313) sun.security.util.ManifestEntryVerifier.update(ManifestEntryVerifier.java:172) java.util.jar.JarVerifier.update(JarVerifier.java:223) java.util.jar.JarVerifier$VerifierStream.read(JarVerifier.java:477) java.io.BufferedInputStream.read1(BufferedInputStream.java:284) java.io.BufferedInputStream.read(BufferedInputStream.java:345) javax.crypto.JarVerifier.verifySingleJar(JarVerifier.java:429) javax.crypto.JarVerifier.verifyJars(JarVerifier.java:322) javax.crypto.JarVerifier.verify(JarVerifier.java:250) javax.crypto.JceSecurity.verifyProviderJar(JceSecurity.java:160) javax.crypto.JceSecurity.getVerificationResult(JceSecurity.java:186) javax.crypto.Cipher.getInstance(Cipher.java:648) SameBuffer$DESCipherWrapper.<init>(SameBuffer.java:197) SameBuffer.runAll(SameBuffer.java:62) SameBuffer.main(SameBuffer.java:156)
24-10-2013