7

I hear that the System.out.println(); Java statement is costly (it consumes a lot of time)
So I try to evaluate its cost:
When I evaluate 5 statements... The cost = 1.0
So I expect the cost of 1 statement = 0.2
But actually I found The cost = 0.0 !! 

double t1 = 0;
double t2 = 0;

t1 = System.currentTimeMillis();
System.out.println("aa");
System.out.println("aa");
System.out.println("aa");
System.out.println("aa");
System.out.println("aa");
t2 = System.currentTimeMillis();
System.out.println("The cost = " + (t2-t1) ); 
// The cost = 1.0 


t1 = System.currentTimeMillis();
System.out.println("aa");
t2 = System.currentTimeMillis();
System.out.println("The cost = " + (t2-t1) ); 
// The cost = 0.0 
// Expected : 1.0/5 = 0.2 -- But Actual : 0.0

Why that?

Tom Jonckheere
  • 1,630
  • 3
  • 20
  • 37
Ahmed Nabil
  • 17,392
  • 11
  • 61
  • 88
  • 2
    You should increase the count of calls in your benchmark to something like 5000 in a loop. **Then** you probably will get a better output! – bobbel Dec 19 '13 at 13:48
  • Issue is in your code, not in `system.out.println`. – Suresh Atta Dec 19 '13 at 13:51
  • 1
    You do know that even one millisecond is damn costly as a normal cpu can handle a few million instructions in that time? – Matthias Dec 19 '13 at 13:53

4 Answers4

11

System#currentTimeMillis returns long and not double. Thus you're loosing .2.

Testing 5 statements is not a good idea, specially when you almost don't feel the time it takes to perform it. I advise you to have more than 5 statements to test and then reduce the amount to something more than 1 as well.

You want to do a precise measurements time, it's better to use System#nanoTime, since it gives time in nano seconds:

long startTime = System.nanoTime();
// ... the code being measured ...
long estimatedTime = System.nanoTime() - startTime;

Look for "nanoTime vs currentTimeMillis" and you'll get hundreds of articles.

Maroun
  • 94,125
  • 30
  • 188
  • 241
  • 3
    Would you also educate on the difference between `currentTimeMillis` and `nanoTime`? Then I can skip an own attempt at answering yet another invalid benchmarking question :) – Matthias Dec 19 '13 at 13:51
3

When i tested your code, the output is always 0.0. Pls try your benchmark with System.nanoTime(); Or do it with more System.out.println()

    double t1 = 0;
    double t2 = 0;

    t1 = System.currentTimeMillis();
    for(int i = 0; i<1000; i++)
        System.out.println("aa");
    t2 = System.currentTimeMillis();
    System.out.println("The cost = " + (t2-t1) ); 


    t1 = System.currentTimeMillis();
    for(int i = 0; i<100; i++)
        System.out.println("aa");
    t2 = System.currentTimeMillis();
    System.out.println("The cost = " + (t2-t1) );

Output: 62.0 and 5.0

And this difference of 1.2 ms is because the loop gets faster while runtime.

kai
  • 6,702
  • 22
  • 38
3

If the execution time is less than one millisecond, you will see nothing, because the clock hasn't 'ticked' yet. For this type of micro benchmarking, you should use something like:

long t1 = System.nanoTime()

for your time measurements. (this measures time in nanosecond units, although not always with that much granularity)

JVMATL
  • 2,064
  • 15
  • 25
1

Also, the time to complete System.out.println will be different on a more or less powerful computer, and how busy that computer is performing other tasks at that particular moment.

user2810910
  • 279
  • 1
  • 2