nanoTime & currentMilliSeconds used in a loop in java

Question

I am trying to measure the speed of different encryption algorithms. I thought I would start of with logging the current time (either nano or milli) then run the actions needed, once done, grab the time and and compare.

It all worked for one iteration, but once I try and add a loop to automatically test multiple algorithms, the numbers don't add up.

 public static void main(String[] args) throws Exception {

    Map<String, int[]> algorKey = new HashMap<String, int[]>() {
        {
            put("AES", new int[] { 128 });
            put("DES", new int[] { 56 });
        }
    };
    Iterator it = algorKey.entrySet().iterator();
    while (it.hasNext()) {
        Map.Entry pairs = (Map.Entry) it.next();
        String algorithm = (String) pairs.getKey();
        int[] keyLengths = (int[]) pairs.getValue();

        for (int i = 0; i < keyLengths.length; i++) {
            int keySize = keyLengths[i];

            Long startT = System.nanoTime();
            System.out.println(startT);
            // Generate key
            KeyGenerator kgen = KeyGenerator.getInstance(algorithm);
            kgen.init(keySize);
            SecretKey key = kgen.generateKey();
            Long endT = System.nanoTime();
            System.out.println(endT);

            System.out.print("Algorithm: " + algorithm + "\nKey Size: "
                    + keySize + "\nTime to Generate: " + (endT - startT)
                    / 1000000 + "ms\n\n");
        }
    }
}

Results come out as follows, the first result is correct (I tested both algorithms individually) but the second is far far far too small.

11223817758736
11224385930995
Algorithm: DES
Key Size: 56
Time to Generate: 568ms

11224386324864
11224401644040
Algorithm: AES
Key Size: 128
Time to Generate: 15ms

(I used snippet to keep the formatting of my results)

I am not sure why the subsequent results happen so fast, or why the time is not counting as it should or something. Is there a possibility that there is caching of data going on that speeds up the process?

I added even more loops and each subsequent iteration got smaller than the last.

Thanks a lot

Answer 1

I really do belive that you should test the algorithms opening a new process with a new jvm in each loop. I think the wrong measurement is a result of classes and runtime being loading in the first loop.

Maybe best way could be run the loop once not measuring and then do the real measurement after the whole code and dependencies are setup.