aspose file tools*
The moose likes Java in General and the fly likes Measure Time Big Moose Saloon
  Search | Java FAQ | Recent Topics | Flagged Topics | Hot Topics | Zero Replies
Register / Login
JavaRanch » Java Forums » Java » Java in General
Bookmark "Measure Time" Watch "Measure Time" New topic
Author

Measure Time

Costa Lamona
Greenhorn

Joined: Sep 17, 2006
Posts: 29
Hi



Is that a VALID way to measure performance of my code?
Is that a GOOD way to measure performance of my code?
Norm Radder
Ranch Hand

Joined: Aug 10, 2005
Posts: 690
    
    1
The System class has two methods that return the current time, one in millisecs and one in nanosecs.
Rob Spoor
Sheriff

Joined: Oct 27, 2005
Posts: 19790
    
  20

It's valid alright, but it does require two Calendar objects. Norm's solution doesn't so it's just a little bit better.


SCJP 1.4 - SCJP 6 - SCWCD 5 - OCEEJBD 6
How To Ask Questions How To Answer Questions
Peter Johnson
author
Bartender

Joined: May 14, 2008
Posts: 5845
    
    7

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.


JBoss In Action
Costa lamona
Ranch Hand

Joined: Sep 24, 2006
Posts: 102
Thanks

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


SCJP 5
Pat Farrell
Rancher

Joined: Aug 11, 2007
Posts: 4659
    
    5

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.
Costa lamona
Ranch Hand

Joined: Sep 24, 2006
Posts: 102
Hi



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
Peter Johnson
author
Bartender

Joined: May 14, 2008
Posts: 5845
    
    7

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.
Rob Spoor
Sheriff

Joined: Oct 27, 2005
Posts: 19790
    
  20

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?
Campbell Ritchie
Sheriff

Joined: Oct 13, 2005
Posts: 40059
    
  28
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.
Peter Johnson
author
Bartender

Joined: May 14, 2008
Posts: 5845
    
    7

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:
 
I agree. Here's the link: http://aspose.com/file-tools
 
subject: Measure Time