Duplicate :
|
|
Relates :
|
|
Relates :
|
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.
|