javasimon performance overhead

[Yuval Shavit]

Hi there,

I'm looking into javasimon, but I was wondering if there's any data
out there about its performance overhead. I would be interested in the
overhead vs. plain System.nanoTime(), the overhead of disabled Simons,
how javasimon scales with threads, and anything else I haven't thought
to ask. :)

Thanks!
Yuval

[Richard Richter]

Hi Yuval

We have a lot of examples, but today I updated some of them to recheck the answers + I had to implement multithreading test. Read on.

OVERHEAD

Big part of the overhead is caused by System.nanoTimer() or System.currentTimeMillis (for usage timestamps) - but these times lately became much better than few years ago. That means two things - overead compared to the timer call got bigger ;-) and the overal performance penalty waaaay lower. We even go so far that for Stopwatch (that uses nanos) we reuse the nano value to calculate the timestamp - but again with shorter timer calls this is less of an issue, but still some saved time.

Example org.javasimon.examples.NanoMillisComparison - check the code here: http://code.google.com/p/javasimon/source/browse/trunk/examples/src/main/java/org/javasimon/examples/NanoMillisComparison.java

I ran it with -server option. My setup: HP ProBook 6550b, i5@2400, 32bit Windows 7

SUMMARY:
empty: Simon Stopwatch: total 8.13 us, counter 5, max 3.85 us, min 855 ns, mean 1.62 us [empty INHERIT]
millis: Simon Stopwatch: total 878 ms, counter 5, max 179 ms, min 173 ms, mean 176 ms [millis INHERIT]
nanos: Simon Stopwatch: total 2.05 s, counter 5, max 411 ms, min 404 ms, mean 409 ms [nanos INHERIT]
assign-ms: Simon Stopwatch: total 878 ms, counter 5, max 177 ms, min 171 ms, mean 176 ms [assign-ms INHERIT]
assign-ns: Simon Stopwatch: total 2.03 s, counter 5, max 410 ms, min 403 ms, mean 406 ms [assign-ns INHERIT]
just-start: Simon Stopwatch: total 3.86 s, counter 5, max 780 ms, min 762 ms, mean 772 ms [just-start INHERIT]
start-stop: Simon Stopwatch: total 10.5 s, counter 5, max 2.13 s, min 2.05 s, mean 2.10 s [start-stop INHERIT]
get-start-stop: Simon Stopwatch: total 11.8 s, counter 5, max 2.40 s, min 2.35 s, mean 2.37 s [get-start-stop INHERIT]

Google Chart avg:
http://chart.apis.google.com/chart?chs=740x320&cht=bvg&chbh=a,3,40&chco=2d69f9,a6c9fd,d0eeff&chxt=x,x,y&chtt=10M-loop+duration&chxr=2,0,3000&chds=0,3000&chxl=0:|empty|millis|nanos|assign-ms|assign-ns|just-start|start-stop|get-start-stop|1:|0.00+ms|175.56+ms|409.08+ms|175.66+ms|406.11+ms|771.76+ms|2097.00+ms|2369.71+ms|2:|0|1000|2000|3000&chd=t:0.00,175.56,409.08,175.66,406.11,771.76,2097.00,2369.71&chdl=avg&.png

Please note, that start/stop means two nanoTimer calls. Stopwatch updates some statistics and checks for Callbacks (hook/extension system), throw in some synchronization and you have roughly triple time of two nanoTimer calls for the whole getStopwatch/start/stop case.

DISABLE/ENABLE

I ran the example class org.javasimon.examples.DisabledEnabledComparison that performs 10,000,000 iterations of basic stopwatch scenarios and the results are following (total is for 50 mils, benchmark is repeated 5 time, mean is the value you are interested in). Code is here: http://code.google.com/p/javasimon/source/browse/trunk/examples/src/main/java/org/javasimon/examples/DisabledEnabledComparison.java

SUMMARY:
enabled: Simon Stopwatch: total 16.4 s, counter 5, max 3.28 s, min 3.26 s, mean 3.27 s [enabled INHERIT]
disabled: Simon Stopwatch: total 3.37 s, counter 5, max 675 ms, min 672 ms, mean 674 ms [disabled INHERIT]
mgr-enabled: Simon Stopwatch: total 21.4 s, counter 5, max 4.30 s, min 4.28 s, mean 4.29 s [mgr-enabled INHERIT]
mgr-disabled: Simon Stopwatch: total 1.43 s, counter 5, max 286 ms, min 283 ms, mean 285 ms [mgr-disabled INHERIT]

Google Chart avg:
http://chart.apis.google.com/chart?chs=420x320&cht=bvg&chbh=a,3,40&chco=2d69f9,a6c9fd,d0eeff&chxt=x,x,y&chtt=10M-loop+duration&chxr=2,0,5000&chds=0,5000&chxl=0:|enabled|disabled|mgr-enabled|mgr-disabled|1:|3270.76+ms|673.66+ms|4290.00+ms|285.32+ms|2:|0|1000|2000|3000|4000|5000&chd=t:3270.76,673.66,4290.00,285.32&chdl=avg&.png

Third case is the most typical and most recommended (generally it's not recommended to keep Stopwatch - especially if you plan disabling the manager). I think we're talking about pretty low-to-nothing overhead unless you want to measure something ridiculously small/short.

MULTITHREADING

We use pragmatic aproach with synchronized blocks or methods where consistency or locking is required. I managed to add example that should demonstrate the contention penalty - the class is org.javasimon.examples.MultithreadedTester and you can find it in the trunk here: http://code.google.com/p/javasimon/source/browse/trunk/examples/src/main/java/org/javasimon/examples/MultithreadedStopwatchLoad.java

I tested the same total number of get/start/stop cycles on various number of threads from 1 to 2500 and the results are following (again, check the mean number or the chart):

SUMMARY:
1: Simon Stopwatch: total 4.99 s, counter 2, max 2.53 s, min 2.47 s, mean 2.50 s [1 INHERIT]
10: Simon Stopwatch: total 13.4 s, counter 2, max 6.74 s, min 6.69 s, mean 6.71 s [10 INHERIT]
100: Simon Stopwatch: total 13.9 s, counter 2, max 7.06 s, min 6.80 s, mean 6.93 s [100 INHERIT]
500: Simon Stopwatch: total 15.1 s, counter 2, max 7.68 s, min 7.45 s, mean 7.57 s [500 INHERIT]
2500: Simon Stopwatch: total 16.0 s, counter 2, max 8.01 s, min 7.99 s, mean 8.00 s [2500 INHERIT]

Google Chart avg:
http://chart.apis.google.com/chart?chs=500x320&cht=bvg&chbh=a,3,40&chco=2d69f9,a6c9fd,d0eeff&chxt=x,x,y&chtt=Multithreaded+test&chxr=2,0,8000&chds=0,8000&chxl=0:|1|10|100|500|2500|1:|2497.37+ms|6711.90+ms|6928.58+ms|7568.50+ms|7999.17+ms|2:|0|1000|2000|3000|4000|5000|6000|7000|8000&chd=t:2497.37,6711.90,6928.58,7568.50,7999.17&chdl=avg&.png

Consider that there is no "real-stuff" code, so there are only synchronized calls everywhere (the worst case probably) - I think it's not that bad. I couldn't run more threads on my machine (OOM Error). I ran the example with -server option, without it (client VM) it performs significantly worse in overall - but I can't imagne reason not to use -server in enterprise. Client results:

http://chart.apis.google.com/chart?chs=500x320&cht=bvg&chbh=a,3,40&chco=2d69f9,a6c9fd,d0eeff&chxt=x,x,y&chtt=Multithreaded+test&chxr=2,0,20000&chds=0,20000&chxl=0:|1|10|100|500|2500|1:|6886.22+ms|13039.27+ms|13251.06+ms|14025.85+ms|18627.32+ms|2:|0|10000|20000&chd=t:6886.22,13039.27,13251.06,14025.85,18627.32&chdl=avg&.png

You can see that the overall shape of the chart is more or less the same.

I hope I answered most of your questions. :-)

Cheers

Virgo

Yuval

--
You received this message because you are subscribed to the Google Groups "javasimon" group.
To post to this group, send email to java...@googlegroups.com.
To unsubscribe from this group, send email to javasimon+...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/javasimon?hl=en.

[Richard Richter]

Please, copy&paste some chart URLs, links got somehow messy, but the URLs are alright.

[Yuval Shavit]

Thanks, Virgo! I'll report that back to my team. :)  Looks promising!