8
class testx
{
  public testx()
  {
    long startTime = System.nanoTime();
    System.out.println((System.nanoTime() - startTime));
  }

  public static void main(String args[])
  {
      new testx();
      new testx();
      new testx();
  }
}

I always get results similar to this 7806 660 517. Why the first call takes 10 times more time than other ones?

SJuan76
  • 24,532
  • 6
  • 47
  • 87
good_evening
  • 21,085
  • 65
  • 193
  • 298

2 Answers2

22

Because the JVM loads a bunch o' classes for the first time at that point. Once that first System.nanoTime() returns, you have already loaded System.class and testx.class, but once System.out.println comes into the picture, I suspect a lot of I/O classes get loaded up, and that takes some time.

In any event, this is not a good benchmarking technique; you should really be warming up the JIT by running something for ~10000 iterations before you start measuring it. Alternately (and preferably), use a pre-built benchmarking tool like Caliper.

Louis Wasserman
  • 191,574
  • 25
  • 345
  • 413
  • Wouldn't it be loaded before running `main`? – SJuan76 Aug 17 '12 at 19:58
  • Is it not already loaded when this line is executed `long startTime = System.nanoTime();`? – good_evening Aug 17 '12 at 19:58
  • Sorry, you were sort of right. `testx.class` is already loaded, but the first time you call `System.out.println`, the JVM almost certainly needs to load a bunch more classes into memory. – Louis Wasserman Aug 17 '12 at 20:00
  • Step through with a debugger and profile it. You'll get your answer. – km1 Aug 17 '12 at 20:17
  • 2
    @LouisWasserman The way things are today, it is very probable that all those classes are already loaded, but are not **initialized** because there are precise semantics defined by the JLS as to the exact moment when a class is initialized. This doesn't upend your main point, just clarifies it. – Marko Topolnik Aug 17 '12 at 20:24
  • To measure real first time constructor call performance you could do same things before (I mean System.nanoTime() and sout) and after that call your constructor. – Rrr Aug 17 '12 at 20:27
  • Warming up JIT should be done only if production code will ever get chance to meet JIT. 10k or 15k repeats is a big number. – dantuch Aug 17 '12 at 20:34
  • @dantuch I cannot think of a need to benchmark an object that is not created in mass quantities. – ahodder Aug 17 '12 at 20:43
  • @AedonEtLIRA So think of a tool that is standalone application, that is used to validate huge data sets. On our production side this tool will never meet JIT, because it is used from time to time, and it would require few day of all-day-work. And yet tool like this needs to be profiled, to remove bottlenecks. – dantuch Aug 18 '12 at 08:50
3

It is definitely as Louis Wasserman, It takes longer on its first round as it has to load all the necessary System classes, you can get around this by calling a blank println() before creating new instances of the class, because look what happens when we do this:

public class testx
{
  public testx()
  {
    long startTime = System.nanoTime();
    System.out.println((System.nanoTime() - startTime));
  }

  public static void main(String args[])
  {
    //loads all System.* classes before calling constructor to decrease time it takes
    System.out.println();
      new testx();
      new testx();
      new testx();
  }
}

output:

405 0 405

where as your initial code outputted:

7293 0 405

David Kroukamp
  • 36,155
  • 13
  • 81
  • 138