First call of Time.now is slow and confuses benchmark result
------------------------------------------------------------
Key: JRUBY-5804
URL: http://jira.codehaus.org/browse/JRUBY-5804
Project: JRuby
Issue Type: Bug
Components: Core Classes/Modules
Affects Versions: JRuby 1.6.1
Reporter: Hiroshi Nakamura
Initial invocation of 'Time.now' is slow. jodatime loading perhaps?
It's really slow especially on JRockit.
{noformat}
# With JRockit. See the 'total' of initial benchmark.
% JAVA_HOME=/home/nahi/java/jrockit-jdk1.6.0_24-R28.1.3-4.0.1 jruby -X-C
-rbenchmark -e '3.times { Benchmark.bm { |x| x.report { sleep 1 }}}'
user system total real
1.768000 0.000000 1.768000 ( 1.039000)
^^^^^^^^ 1.768[sec] for 'sleep 1'.
user system total real
1.002000 0.000000 1.002000 ( 1.003000)
user system total real
1.002000 0.000000 1.002000 ( 1.002000)
# With JRockit + dummy Time.now call.
% JAVA_HOME=/home/nahi/java/jrockit-jdk1.6.0_24-R28.1.3-4.0.1 jruby -X-C
-rbenchmark -e 'Time.now; 3.times { Benchmark.bm { |x| x.report { sleep 1 }}}'
user system total real
1.016000 0.000000 1.016000 ( 1.014000)
^^^^^^^^
user system total real
1.003000 0.000000 1.003000 ( 1.002000)
user system total real
1.001000 0.000000 1.001000 ( 1.001000)
# With Sun JDK.
% JAVA_HOME=/home/nahi/java/jdk1.6.0_25 jruby -X-C -rbenchmark -e '3.times {
Benchmark.bm { |x| x.report { sleep 1 }}}'
user system total real
1.066000 0.000000 1.066000 ( 1.010000)
^^^^^^^^ a little slow on Sun JDK.
user system total real
1.001000 0.000000 1.001000 ( 1.001000)
user system total real
1.001000 0.000000 1.001000 ( 1.001000)
# With Sun JDK + dummy Time.now call.
% JAVA_HOME=/home/nahi/java/jdk1.6.0_25 jruby -X-C -rbenchmark -e 'Time.now;
3.times { Benchmark.bm { |x| x.report { sleep 1 }}}'
user system total real
1.001000 0.000000 1.001000 ( 1.002000)
^^^^^^^^
user system total real
1.001000 0.000000 1.001000 ( 1.001000)
user system total real
1.000000 0.000000 1.000000 ( 1.000000)
{noformat}
Here's 'measure' in benchmark.rb
{noformat}
def measure(label = "") # :yield:
t0, r0 = Benchmark.times, Time.now
yield
t1, r1 = Benchmark.times, Time.now
{noformat}
So measure calls Benchmark.times(calls Process.times) at first, then calls
Time.now.
Initial 'Time.now' is considerably slow on JRockit so we see 0.7[sec] difference
between 'total' and 'real'. (0.05[sec] on Sun JDK.)
How do we fix this?
1. Load jodatime at startup. Startup time slows down.
2. Add dummy Time.now at benchmark.rb loading. Uglish...
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.codehaus.org/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
To unsubscribe from this list, please visit:
http://xircles.codehaus.org/manage_email
