• Post Reply Bookmark Topic Watch Topic
  • New Topic
programming forums Java Mobile Certification Databases Caching Books Engineering Micro Controllers OS Languages Paradigms IDEs Build Tools Frameworks Application Servers Open Source This Site Careers Other Pie Elite all forums
this forum made possible by our volunteer staff, including ...
Marshals:
  • Campbell Ritchie
  • Jeanne Boyarsky
  • Ron McLeod
  • Paul Clapham
  • Liutauras Vilda
Sheriffs:
  • paul wheaton
  • Rob Spoor
  • Devaka Cooray
Saloon Keepers:
  • Stephan van Hulst
  • Tim Holloway
  • Carey Brown
  • Frits Walraven
  • Tim Moores
Bartenders:
  • Mikalai Zaikin

Measure Time

 
Greenhorn
Posts: 29
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
Hi



Is that a VALID way to measure performance of my code?
Is that a GOOD way to measure performance of my code?
 
Rancher
Posts: 5008
38
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
The System class has two methods that return the current time, one in millisecs and one in nanosecs.
 
Sheriff
Posts: 22783
131
Eclipse IDE Spring VI Editor Chrome Java Windows
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
It's valid alright, but it does require two Calendar objects. Norm's solution doesn't so it's just a little bit better.
 
author
Posts: 5856
7
Android Eclipse IDE Ubuntu
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
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.
 
Ranch Hand
Posts: 102
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
Thanks

but I am wondering why Calendar might be that nasty and System is that good.
 
Rancher
Posts: 4803
7
Mac OS X VI Editor Linux
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator

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
Posts: 102
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
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
Posts: 5856
7
Android Eclipse IDE Ubuntu
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
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
Posts: 22783
131
Eclipse IDE Spring VI Editor Chrome Java Windows
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
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?
 
Marshal
Posts: 79180
377
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
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
Posts: 5856
7
Android Eclipse IDE Ubuntu
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
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:
 
Don't get me started about those stupid light bulbs.
reply
    Bookmark Topic Watch Topic
  • New Topic