Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

GC::Profiler.total_time reported in wrong units (and spews to STDOUT) #1620

Closed
benweint opened this issue Apr 11, 2014 · 1 comment
Closed

Comments

@benweint
Copy link

According to the MRI docs GC::Profiler.total_time should return a timing in seconds.

JRuby implements this method, but returns a value that appears to not actually be in seconds (looks like it might actually be milliseconds). You can demonstrate this with a simple test case.

On MRI, this test case returns output like this:

Elapsed time (s): 0.155596
GC time (s?):     0.03427699999999959

On JRuby 1.7.11, the output looks like this:

   ID  Type                      Timestamp(sec)    Before(kB)     After(kB)    Delta(kB)        Heap(kB)          GC Time(ms) 
Elapsed time (s): 0.424
GC time (s?):     29.75

Two things about the output on JRuby:

  1. The GC time is higher than the elapsed time, suggesting that the two measurements are not using the same units (though they should both be in seconds).
  2. The first row of output is some spew that doesn't appear under MRI, and doesn't seem to be useful.

The implementation of total_time in JRuby seems to assume that GCInfo.getDuration returns a value in milliseconds (which is consistent with what the docs say), but it looks like that may not actually be the case. I found one reference to someone hitting a similar problem on StackOverflow, suggesting that the units changed recently.

Version info:

$ uname -a
Darwin koan.local 13.1.0 Darwin Kernel Version 13.1.0: Thu Jan 16 19:40:37 PST 2014; root:xnu-2422.90.20~2/RELEASE_X86_64 x86_64
$ java -version
java version "1.7.0_21"
Java(TM) SE Runtime Environment (build 1.7.0_21-b12)
Java HotSpot(TM) 64-Bit Server VM (build 23.21-b01, mixed mode)
$ jruby -v
jruby 1.7.11 (1.9.3p392) 2014-02-24 86339bb on Java HotSpot(TM) 64-Bit Server VM 1.7.0_21-b12 [darwin-x86_64]
@MSNexploder
Copy link
Contributor

Apparently this was a JVM bug until 7u51 (http://bugs.java.com/bugdatabase/view_bug.do?bug_id=7087969).

Running the test case using:

$ uname -a
Darwin Stefans-MBP.local 16.6.0 Darwin Kernel Version 16.6.0: Fri Apr 14 16:21:16 PDT 2017; root:xnu-3789.60.24~6/RELEASE_X86_64 x86_64
$ java -version
java version "1.8.0_131"
Java(TM) SE Runtime Environment (build 1.8.0_131-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)
$ ruby -v
jruby 9.1.9.0 (2.3.3) 2017-05-15 28aa830 Java HotSpot(TM) 64-Bit Server VM 25.131-b11 on 1.8.0_131-b11 [darwin-x86_64]

yields a rather promising

Elapsed time (s): 0.545985
GC time (s?):     0.02

@kares kares closed this as completed May 29, 2017
@kares kares added this to the Invalid or Duplicate milestone May 29, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants