2

I was checking out this discussion: How slow are Java exceptions? and while experimenting, found out that if I run static methods instead of instance methods, the normal path actually takes more time than try-catch path.

What I'm doing is: create a no-op static foo() method, create static method method1() that calls foo() 100000000 times normally, and another static method method2() which calls foo() 100000000 times in a try-catch block. What I see is, method2 actually takes less time than method1.

Any thoughts?

public class ExceptionsStatic
{
    public static void main(String... args)
    {               
        withNormal();
        withTry();      
    }

    static void foo()
    {

    }

    static void foo2() throws Exception
    {

    }

    static void withTry()
    {
        long t1 = System.currentTimeMillis();

        for(int i = 0; i < 100000000; i++)
        {
            try
            {
                foo2();
            }
            catch(Exception e)
            {

            }
        }

        long t2 = System.currentTimeMillis();

        System.out.println("try time taken " + (t2 - t1));
    }

    static void withNormal()
    {
        long t1 = System.currentTimeMillis();

        for(int i = 0; i < 100000000; i++)
        {
            foo();
        }

        long t2 = System.currentTimeMillis();

        System.out.println("normal time taken " + (t2 - t1));
    }
}
Community
  • 1
  • 1
shrini1000
  • 7,038
  • 12
  • 59
  • 99
  • 5
    Please read [How do I write a correct micro-benchmark in Java?](http://stackoverflow.com/questions/504103/how-do-i-write-a-correct-micro-benchmark-in-java) and follow its suggestions. *Then* post the code and your findings *if* you have any questions about them. – Joachim Sauer Sep 30 '11 at 06:03
  • 2
    Please show your benchmarking code - it's very easy to get wrong, and frankly I'd expect a no-op static method to be inlined out of existence anyway. – Jon Skeet Sep 30 '11 at 06:03
  • 1
    You are seeing random or otherwise unrelated side effects. Maybe JIT at work? Do you get the same result when you flip execution order around? – Thilo Sep 30 '11 at 06:03
  • @Thilo: bang on! But why won't a similar thing happen for instance methods? – shrini1000 Sep 30 '11 at 06:12
  • After running a naive test (a couple of call to `System.currentTimeMillis`), I do get the same results as shrini (regardless of order). But the difference between the two is a handful of milliseconds, so such a straight-forward approach to timing is anything but legitimate. Even so, given the consistency of the timing, regardless of the accuracy, the results are still surprising. Maybe if someone would like to run a proper benchmark, we can see if something truly strange is going? – Ken Wayne VanderLinde Sep 30 '11 at 06:19
  • @Jon Skeet: have added the code. Not sure why the formatting got a little out of hand. – shrini1000 Sep 30 '11 at 06:25
  • @shrini1000: you **didn't** follow the advice in the question I linked. Following that is **really** important, because it's oh-so-easy to get a micro-benchmark wrong. For example, you have no warmup phase, which makes your benchmark worthless. – Joachim Sauer Sep 30 '11 at 06:33
  • what the results of your test? I tried it and it only takes few ms in both cases. – irreputable Sep 30 '11 at 06:38
  • @Joachim Sauer: I wanted to share my 'raw' code so anybody trying it out would have the same base line. Will now write code following the advice and see if the results change. – shrini1000 Sep 30 '11 at 06:47
  • @irreputable: When I call the normal method first and then try-catch method, on an avg the normal method takes 104ms and try-catch method takes 70ms. If I flip the order, try-catch on an avg takes 108ms and normal takes 71ms. – shrini1000 Sep 30 '11 at 06:52
  • @shrini1000 Run it again with this flag `-XX:-PrintCompilation` (your VM may not support it, but it will tell you if that is the case). – Ryan Schipper Sep 30 '11 at 06:57
  • @Ryan Schipper: looks like my VM doesn't suport it, but I did not get any warning/error. It simply printed the output and quit. – shrini1000 Sep 30 '11 at 07:02
  • that's a really slow VM. – irreputable Sep 30 '11 at 07:02

3 Answers3

2

I have attempted to re-create your test code and then run it through javap. These are given at the end so that you don't have to scroll through a large text block.

Note that when there is no absolutely no optimisation performed by the VM, the bytecode is executed as per the javap dump below. Thus, assuming no other external factors, execution of method2() should always take longer as it includes an additional instruction (line 11: goto 15).

Of course, as Joachim mentions below, 'the bytecode says very little about performance'.

There are a lot of flags available for profiling and enabling/disabling JVM optimisations. Have a look around online. For 1.4.2, I found this link which may work with newer JREs also.

Edited to add: In supported VMs, you can enable JIT trace output by using the following VM flag -XX:-PrintCompilation.


javap output:

Ryan-Schippers-MacBook-Pro-2:Miscellaneous work$ javap -c -classpath ./src SlowTryCatch
Compiled from "SlowTryCatch.java"
public class SlowTryCatch extends java.lang.Object{
public SlowTryCatch();
  Code:
   0:   aload_0
   1:   invokespecial   #1; //Method java/lang/Object."<init>":()V
   4:   return

public static void main(java.lang.String[]);
  Code:
   0:   return

public static void foo();
  Code:
   0:   return

public static void method1();
  Code:
   0:   iconst_0
   1:   istore_0
   2:   iload_0
   3:   ldc #2; //int 100000000
   5:   if_icmpge   17
   8:   invokestatic    #3; //Method foo:()V
   11:  iinc    0, 1
   14:  goto    2
   17:  return

public static void method2();
  Code:
   0:   iconst_0
   1:   istore_0
   2:   iload_0
   3:   ldc #2; //int 100000000
   5:   if_icmpge   21
   8:   invokestatic    #3; //Method foo:()V
   11:  goto    15
   14:  astore_1
   15:  iinc    0, 1
   18:  goto    2
   21:  return
  Exception table:
   from   to  target type
     8    11    14   Class java/lang/Exception


}
Ryan Schipper
  • 1,019
  • 7
  • 8
  • 2
    `javap` can tell you *nothing* about the optimizations done by the JVM, because `javap` acts on the same *input* as the JVM does. So the JVM starts optimizing **from** the .class file. – Joachim Sauer Sep 30 '11 at 06:35
  • @JoachimSauer Read the post again. I didn't intend to imply that javap provides any indication about the optimizations that the JVM performs. As you know, it shows what the un-optimized code will do, thereby demonstrating that the reason - all other environmental issues aside - for the behaviour is JIT optimisations. – Ryan Schipper Sep 30 '11 at 06:44
  • 1
    yes, I actually re-read it after I posted the comment, which was the reason I un-did my initial downvote ;-) I get your point, but the problem is that the bytecode says *very little* about performance, because even very simple optimizations can *massively* change the performance characteristics. – Joachim Sauer Sep 30 '11 at 06:45
  • True. Call me a sucker for the 'holistic' answer. – Ryan Schipper Sep 30 '11 at 06:48
0

I have modified your code a bit so the optimizer does not remove code. By running it several times in Sun/Oracle JVM the things I have found are:

  • Execution time is not deterministic. This is usual in HotSpot JVMs, especially in multicore systems
  • Differences between withNormal() and withTry are minimal. This is to be expected as no actual exception is ever thrown and there are no finally blocks.
  • The version that is run first tends to be slower. It might be something related to the HotSpot compiler "warming up", but I am not an expert in HotSpot internals

To summarize, I would not expect any significant difference between code using exceptions or not, when running in Sun/Oracle JVM it is most likely noise from HotSpot.

UPDATE

I have run it with both -server and -client flags and apart from execution being an order of magnitude faster in my machine, the observations above apply.

Modified code below:

public class ExceptionsStatic    {

public static void main(String... args)
{
    withNormal();
    withTry();
}

static int fooVar;
static void foo()
{
    fooVar++;
}

static int foo2Var;
static void foo2() throws Exception
{
    foo2Var++;
}

static void withTry()
{
    long t1 = System.currentTimeMillis();

    foo2Var = 0;
    for(int i = 0; i < 100000000; i++)
    {
        try
        {
            foo2();
        }
        catch(Exception e)
        {

        }
    }

    long t2 = System.currentTimeMillis();

    System.out.println("try time taken " + (t2 - t1) + "; " + foo2Var);
}

static void withNormal()
{
    long t1 = System.currentTimeMillis();

    fooVar = 0;
    for(int i = 0; i < 100000000; i++)
    {
        foo();
    }

    long t2 = System.currentTimeMillis();

    System.out.println("normal time taken " + (t2 - t1) + "; " + fooVar);
}
gpeche
  • 21,974
  • 5
  • 38
  • 51
  • Confirmed your findings. I also made similar modifications to the 'instance based' version of this code, but there the difference between normal vs try is still significant. E.g. for normal-try sequence, the avg is 71ms, 145ms; for try-normal sequence it is 175ms, 104ms. – shrini1000 Sep 30 '11 at 08:09
  • 1
    **Please, please, please** don't make any conclusions from this kind of micro-benchmarks! As you noticed yourself the effects can be affected by very minor changes and are not really saying anything useful. **If** you want useful numbers, do a *proper* micro-benchmark (see the question I linked to above). Anything less than that and you're not getting any useful numbers. – Joachim Sauer Sep 30 '11 at 08:22
  • No conclusions here, just casual guesses. In the real world, all this is pointless: unless you have profiled it and *proved* it is slow it is fast enough – gpeche Sep 30 '11 at 18:22
0

Here is a micro benchmark which sucks less. Use 1 or 2 as program parameters and -XX:+PrintCompilation -verbose:class -verbose:gc as JVM parameters.

public class TryBlockBenchmark {
    private static final int MEASUREMENTS = 100;
    private static int dummy = 0;

    public static void main(String[] args) {
        boolean tryBlock = args[0].equals("1");
        System.out.println(tryBlock ? "try block" : "no try block");

        for (int i = 0; i < MEASUREMENTS; i++) {

            long start = System.currentTimeMillis();
            if (tryBlock) {
                benchmarkTryBlock();
            } else {
                benchmarkNoTryBlock();
            }
            long end = System.currentTimeMillis();

            System.out.println((end - start) + " ms");
        }

        System.out.println("(" + dummy + ")");
    }

    private static void benchmarkTryBlock() {
        for (int i = Integer.MIN_VALUE; i < Integer.MAX_VALUE; i++) {
            try {
                staticMethod();
            } catch (Exception e) {
            }
        }
    }

    private static void benchmarkNoTryBlock() {
        for (int i = Integer.MIN_VALUE; i < Integer.MAX_VALUE; i++) {
            staticMethod();
        }
    }

    private static void staticMethod() {
        dummy++;
    }
}

With Java 1.6.0_24 64-bit HotSpot Server VM on a C2Q6600 @ 3GHz, after the first couple of measurements, the time for both versions stabilizes at 266 ms (+/- 1 ms). The time is the same also when the staticMethod() is inlined manually, which is to be expected from HotSpot. Removing the dummy++ line reduces the time to 0 ms, when HotSpot optimizes it away.

I also tested using Java 1.6.0_24 32-bit and with it the HotSpot Server VM had the same results, but the HotSpot Client VM had both versions producing results around 8660 ms (+/- 20 ms).

So we can conclude that the Server VM has better optimizations than the Client VM and that a try-catch which does nothing is either optimized away by HotSpot or that it does not affect the performance. To find which it is, print the assembly code produced by HotSpot.

Overall, measuring things which do nothing is pretty pointless.

Esko Luontola
  • 73,184
  • 17
  • 117
  • 128