Forums Register Login
Measure Time

Is that a VALID way to measure performance of my code?
Is that a GOOD way to measure performance of my code?
The System class has two methods that return the current time, one in millisecs and one in nanosecs.
It's valid alright, but it does require two Calendar objects. Norm's solution doesn't so it's just a little bit better.
Getting a Calendar object is a huge performance/locking issue on Windows (and Linux too, if I recall correctly, but it has been a while since I ran into this issue). I had a multi-threaded app where each thread was repeatedly obtaining Calendar objects. Despite the fact that the app was processor-bound, I noticed that it never used more than 80% of the processor and the vast majority of that usage was system time. When I replace the Calendar.getInstance call with System.getTimeMillis, the CPU usage went to 100%, it showed very little system time, and throughput increased by 15 times! So if you plan on measuring code time, do not use Calender.getInstance.

but I am wondering why Calendar might be that nasty and System is that good.

Originally posted by Costa Lamona:
Is that a VALID way to measure performance of my code?
Is that a GOOD way to measure performance of my code?

Use a profiler. At best, any time from the system is approximate.

You will probably find that your "lots of code" is not really taking very long, unless you are doing huge stuff like a bunch of FFTs.

Nearly all Java programs are blocked by IO, not CPU.

I just tried that I found that c1.getTime().getTime(); takes longer but that because of two method calling, hence it did not appear except after
1000000 iteration, hmmm why I did not try it in Nanos, I would use System.currentTimeMillis(); just in case it will make difference in another situations
My guess is that Calender.getInstance makes a synchronized kernel call, which can cause a lot of contention, if you have multiple threads doing that like I had. (By the way, I had the Calendar.getInstance call within my loop, not outside.)

I suspect that Microsoft was aware of this issue when it built .Net because the corresponding .Net call rarely returns the exact time. For example, you can get the current time, do something in a loop for, oh, 100000 times, get the time again, and find out that the code took no time to run. Repeatedly doubling the number of loops and running the code again would eventually result in a time difference. It would appear that the date/time object is updated only a few times a second by a background thread, and any calls asking for the date/time get that object, thus avoiding the kernel contention exhibited when using Java. Needless to say, blog posts appeared also immediately on how to get an accurate timer for .Net.
When Calendar.getInstance() is called, a new GregorianCalendar object is created (for most of us anyway). Inside this constructor, several objects are created, and even a resource bundle is used. It then still calls setTimeInMillis(System.currentTimeMillis());
I couldn't find anything synchronized or native (except for System.currentTimeMillis()).

As for Calendar.getTime(), that creates a new Date object each and every time.

So yes, in the end using just System.currentTimeMillis() is a lot more efficient. It's going to be called (also in "new Date()"), so why create an object around it if you're going to use that timestamp anyway?
Agree with Rob (well, he is always right anyway). Also there is a delay of several milliseconds in creating the Calendar objects, which may make your timing very inaccurate.
Use the milliseconds or nanoseconds methods of the System class, and compare them with an empty block.
Here is an app that demonstrates the possible locking issue. You must compile and run with JDK 1.4.2 or 1.5 to see the issues - I ran this under JDK 6 and the issue is no longer there. The run command I used was:

%JAVA_HOME%\java.exe -Xmx10124m -Xms1024m -XX:NewSize=300m -XX:MaxNewSize=300m -verbose:gc -classpath . peter.Speed

This command causes the app to use currentTimeMillis. Adding a parameter (for example, "...\java.exe ... peter.Speed true") causes the app to use Calendar.

On my system, I got these results (JDK 1.5.0_16):

* currentTimeMillis: 1 GC, Elapsed millis is 397
* Calendar: 16GC, Elapsed millis is 62749

The Calendar run shows around 40% CPU usage with 1/2 to 2/3 being kernel time (I turned on Show Kernel Times in Task Manager). The currentTimeMillis run showed 100% processor usage with minimal kernel time (I had to increase the outer loop by a factor of 100 to get it to run long enough to notice this).

Whenever I have seen such high kernel times it has usually meant some kind of lock contention. I originally saw this with the 1.3 JVM (when I wrote the original program that experienced this high kernel time behavior), and repeated the behavior with 1.4.x and 1.5. I tried the same program with JDK 1.6.0_07 and this time saw close to 100% CPU usage with about 15-20% kernel time. In addition, the timings were better with the Calendar run time being only 10 times that of the currentTimeMillis run time.

Here is the app:
Wink, wink, nudge, nudge, say no more ... https://richsoil.com/cards

This thread has been viewed 4795 times.

All times above are in ranch (not your local) time.
The current ranch time is
Jun 22, 2018 09:09:14.