From owner-freebsd-java@FreeBSD.ORG Thu Oct 28 11:52:28 2004 Return-Path: Delivered-To: freebsd-java@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 3F52316A4CE for ; Thu, 28 Oct 2004 11:52:28 +0000 (GMT) Received: from www.enhyper.com (mailgate.enhyper.com [62.49.250.18]) by mx1.FreeBSD.org (Postfix) with ESMTP id DDB6F43D58 for ; Thu, 28 Oct 2004 11:52:26 +0000 (GMT) (envelope-from iang@systemics.com) Received: from localhost.localdomain (localhost.localdomain [127.0.0.1]) by www.enhyper.com (8.11.6/8.11.6) with SMTP id i9SBpx223045; Thu, 28 Oct 2004 12:52:04 +0100 X-Authentication-Warning: www.enhyper.com: localhost.localdomain [127.0.0.1] didn't use HELO protocol Message-ID: <4180DD57.9060100@systemics.com> Date: Thu, 28 Oct 2004 12:51:51 +0100 From: Ian Grigg User-Agent: Mozilla Thunderbird 0.7.3 (X11/20041002) X-Accept-Language: en-us, en MIME-Version: 1.0 To: Pawel Worach References: <417ECD08.8010805@systemics.com> <417F6596.8050808@telia.com> In-Reply-To: <417F6596.8050808@telia.com> Content-Type: text/plain; charset=us-ascii; format=flowed Content-Transfer-Encoding: 7bit cc: freebsd-java@freebsd.org Subject: Re: Crypto takes 17 seconds to wind up for the throw... X-BeenThere: freebsd-java@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: Porting Java to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 28 Oct 2004 11:52:28 -0000 Pawel, Pawel Worach wrote: > Ian Grigg wrote: > >> Cipher DES: 17025 > > > What takes time in this situation I belive is. > > // this depends on the quality of the randomness your system provides > SecureRandom random = SecureRandom.getInstance("SHA1PRNG"); > > // done by Cipher.getInstance("DES"); in the background, the constructor > // of DESCipher is pretty slow, don't really know what is does, generates > // keys? > com.sun.crypto.provider.DESCipher dc = > new com.sun.crypto.provider.DESCipher(); > > Random stir: 1155 (those two above combined) > Cipher DES: 686 (if above is pre-done this goes faster) OK, thanks for the suggestion. I tried that, and the results do improve the startup of any particular cipher, as the statics are pre-calculated. But they make no change to the issue I am seeing. What it does do is confirm that the problem lies within the JCE, and is not a provider issue, nor a Java issue, nor a FreeBSD issue. (Also shows that Sun's DES is pretty slow by all accounts anyway for startup.) See below. I know what rough problem is, but not precisely. I'm marshalling my traces to provide the full report, first. > Your system must be quite slow if that takes 17 seconds, > getInstance("DES") in your program out of the box took me 1230 msec. My system is a 1.8Ghz Pentium something or other, a thinkpad A31, see below for FreeBSD/Java versions. It's quite snappy for normal things, although I admit thunderbird is straining it. > ps. Any plans for getting the hotspot profiler working? Thanks, iang ===================================================================== galland$ $JAVA -version java version "1.4.2-p6" Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.2-p6-toor_21_jul_2004_13_48) Java HotSpot(TM) Client VM (build 1.4.2-p6-toor_21_jul_2004_13_48, mixed mode) galland$ uname -a FreeBSD galland 4.9-RC FreeBSD 4.9-RC #7: Tue Sep 30 03:21:16 EDT 2003 # thinkpad A31 1.8GHz. ===================================================================== galland$ /usr/local/jdk1.4.2/bin/javac CipherSlowTest.java && CLASSPATH=::$CLASSPATH $JAVA CipherSlowTest . . . . . . . . . . . . . . . . . . . . default provider: SUN MessDig SHA-1: 125 PRNG SHA-1: 0 . . . . . . . . . . . . . . . . . . . . direct call into DES constructors (bypass JCE) cryptix.DES: 88 sun.crypto.DES: 372 . . . . . . . . . . . . . . . . . . . . switching to provider: CryptixCrypto addProvider: 20 MessDig SHA-1: 16 . . . . . . . . . . . . . . . . . . . . first call to Cipher.getInstance() is really slow. Cipher DES: 16861 Cipher Null: 4 Cipher AES: 30 . . . . . . . . . . . . . . . . . . . . default crypto provider: SunJCE SunJCE DES: 51 . . . . . . . . . . . . . . . . . . . . finished total test time: 17578 Notes:regardless of which provider, first Cipher.getInstance() is slow. Same result from KeyGenerator.getInstance(). All times in milliseconds. galland$ ===================================================================== import javax.crypto.*; import java.security.*; /** * JDK 1.4.2 * java version "1.4.2-p6" * Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.2-p6-toor_21_jul_2004_13_48) * Java HotSpot(TM) Client VM (build 1.4.2-p6-toor_21_jul_2004_13_48, mixed mode) * * FreeBSD galland 4.9-RC FreeBSD 4.9-RC #7: Tue Sep 30 03:21:16 EDT 2003 * */ public class CipherSlowTest { static long report(long start, String msg) { long now = System.currentTimeMillis(); System.out.println(msg + (now - start)); return System.currentTimeMillis(); } static String line = ". . . . . . . . . . . . . . . . . . . . "; static SecureRandom random; public static void prelims() throws Exception { long t1 = System.currentTimeMillis(); String provider = "SUN"; System.out.println(line+"default provider: " + provider); MessageDigest.getInstance("SHA-1", provider); t1 = report(t1, "MessDig SHA-1: "); // this depends on the quality of the randomness your system provides random = SecureRandom.getInstance("SHA1PRNG"); t1 = report(t1, "PRNG SHA-1: "); System.out.println(line+"direct call into DES constructors (bypass JCE)"); // done by Cipher.getInstance("DES"); in the background. cryptix.jce.provider.cipher.DES cryptix = new cryptix.jce.provider.cipher.DES(); t1 = report(t1, "cryptix.DES: "); // the constructor of sun.crypto.DESCipher is pretty slow, // don't really know what is does, generates keys? com.sun.crypto.provider.DESCipher sundes = new com.sun.crypto.provider.DESCipher(); t1 = report(t1, "sun.crypto.DES: "); } static void cryptix() throws Exception { long t1 = System.currentTimeMillis(); String provider = "CryptixCrypto"; System.out.println(line+"switching to provider: " + provider); Security.addProvider(new cryptix.jce.provider.CryptixCrypto()); t1 = report(t1, "addProvider: "); MessageDigest.getInstance("SHA-1", provider); t1 = report(t1, "MessDig SHA-1: "); System.out.println(line+"first call to Cipher.getInstance() is really slow."); Cipher.getInstance("DES", provider); t1 = report(t1, "Cipher DES: "); Cipher.getInstance("null", provider); t1 = report(t1, "Cipher Null: "); Cipher.getInstance("Rijndael/ECB/NoPadding", provider); t1 = report(t1, "Cipher AES: "); } static void sunJCE() throws Exception { long t1 = System.currentTimeMillis(); String provider = "SunJCE"; System.out.println(line+"default crypto provider: " + provider); Cipher.getInstance("DES", provider); t1 = report(t1, "SunJCE DES: "); } public static void main(String[] args) throws Exception { long t2 = System.currentTimeMillis(); prelims(); boolean cryptixFirst = true; if (cryptixFirst) // doesn't matter which { cryptix(); sunJCE(); } else { sunJCE(); cryptix(); } System.out.println(line + "finished"); report(t2, "total test time: "); System.out.println(""); System.out.println("Notes:regardless of which provider, first Cipher.getInstance() is slow."); System.out.println(" Same result from KeyGenerator.getInstance()."); System.out.println(" All times in milliseconds."); } }