Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8023983

SHA2 calculation extremely slow under unknown conditions

XMLWordPrintable

      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.

            Unassigned Unassigned
            webbuggrp Webbug Group
            Votes:
            0 Vote for this issue
            Watchers:
            12 Start watching this issue

              Created:
              Updated:
              Resolved: