Crypto takes 17 seconds to wind up for the throw...

[Ian Grigg]

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.");
    }
}