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

microsecond accuracy is not supported in class Time #4393

Closed
amarkowitz opened this Issue Dec 16, 2016 · 27 comments

Comments

Projects
None yet
4 participants
@amarkowitz

amarkowitz commented Dec 16, 2016

Environment

  • JRuby version
jruby 9.1.6.0 (2.3.1) 2016-11-09 0150a76 Java HotSpot(TM) 64-Bit Server VM 25.112-b16 on 1.8.0_112-b16 +jit [darwin-x86_64]
  • Operating system and platform
Darwin <machine_name> 16.1.0 Darwin Kernel Version 16.1.0: Wed Oct 19 20:31:56 PDT 2016; root:xnu-3789.21.4~4/RELEASE_X86_64 x86_64

Expected Behavior

I expect that Time.now.to_f will give me results that include both millisecond and microsecond accuracy.

Here is MRI ruby 2.3.0

user@ ~/dev/helltool (master)$ rvm use ruby-2.3.0
Using /Users/user/.rvm/gems/ruby-2.3.0
user@ ~/dev/helltool (master)$ ruby -e "puts \"%10.6f\" % Time.now.to_f"
1481922323.986732

Note that we get actual microsecond accuracy on the right of the decimal point (in this case 732)

Actual Behavior

master, 9.1.6.0, 9.1.5.0 versions of jruby will never give you the microseconds. The time value appears to only ever have millisecond accuracy.

user@ ~/dev/jruby (master)$ rvm use system
Now using system ruby.
user@ ~/dev/jruby (master)$ bin/jruby -e "puts \"%10.6f\" % Time.now.to_f"
1481923116.233000
user@ ~/dev/helltool (master)$ rvm use jruby-9.1.6.0
Using /Users/user/.rvm/gems/jruby-9.1.6.0
user@ ~/dev/helltool (master)$ ruby -e "puts \"%10.6f\" % Time.now.to_f"
1481922293.736000
user@ ~/dev/helltool (master)$ rvm use jruby-9.1.5.0
Using /Users/user/.rvm/gems/jruby-9.1.5.0
user@ ~/dev/helltool (master)$ ruby -e "puts \"%10.6f\" % Time.now.to_f"
1481922302.957000

@amarkowitz amarkowitz changed the title from microsecond accuracy is not available in class Time to microsecond accuracy is not supported in class Time Dec 16, 2016

@kares

This comment has been minimized.

Show comment
Hide comment
@kares

kares Dec 16, 2016

Member

this is a fairly (although not for newcomers) known issue, do you really need Time.now to be that accurate?

Member

kares commented Dec 16, 2016

this is a fairly (although not for newcomers) known issue, do you really need Time.now to be that accurate?

@amarkowitz

This comment has been minimized.

Show comment
Hide comment
@amarkowitz

amarkowitz Dec 16, 2016

Apologies for creating additional noise. I searched through existing open/closed tickets, but was unable to find a reference to this/a similar issue.

It would be helpful for logging purposes/performance measurements in our application.

amarkowitz commented Dec 16, 2016

Apologies for creating additional noise. I searched through existing open/closed tickets, but was unable to find a reference to this/a similar issue.

It would be helpful for logging purposes/performance measurements in our application.

@kares

This comment has been minimized.

Show comment
Hide comment
@kares

kares Dec 16, 2016

Member

there's java.lang.System.nanoTime but I am not sure how it differs from its currentTimeMillis cousin (implementation wise) which is used in Time.now.

millis time should be sufficient unless you plan micro-benchmarking in which case its best to loop several times to let the code paths warmup.

Member

kares commented Dec 16, 2016

there's java.lang.System.nanoTime but I am not sure how it differs from its currentTimeMillis cousin (implementation wise) which is used in Time.now.

millis time should be sufficient unless you plan micro-benchmarking in which case its best to loop several times to let the code paths warmup.

@amarkowitz

This comment has been minimized.

Show comment
Hide comment
@amarkowitz

amarkowitz Dec 16, 2016

In this particular case, we are including 3rd party gems that do the measurements using Time#to_f calculations which are then dumped into our logs which complicates using our own timing mechanism.

It would be ideal if jrubys Time matched the expectations set out by MRI Ruby

Another example:

user@ ~/dev/helltool (master)$ rvm use jruby-9.1.6.0
Using /Users/user/.rvm/gems/jruby-9.1.6.0
user@ ~/dev/helltool (master)$ ruby -e "puts Time.now.usec"
143000

vs MRI Ruby

user@ ~/dev/helltool (master)$ rvm use ruby-2.3.0
Using /Users/user/.rvm/gems/ruby-2.3.0
user@ ~/dev/helltool (master)$ ruby -e "puts Time.now.usec"
309139

And the corresponding docs: http://ruby-doc.org/core-2.3.0/Time.html#method-i-usec

image

amarkowitz commented Dec 16, 2016

In this particular case, we are including 3rd party gems that do the measurements using Time#to_f calculations which are then dumped into our logs which complicates using our own timing mechanism.

It would be ideal if jrubys Time matched the expectations set out by MRI Ruby

Another example:

user@ ~/dev/helltool (master)$ rvm use jruby-9.1.6.0
Using /Users/user/.rvm/gems/jruby-9.1.6.0
user@ ~/dev/helltool (master)$ ruby -e "puts Time.now.usec"
143000

vs MRI Ruby

user@ ~/dev/helltool (master)$ rvm use ruby-2.3.0
Using /Users/user/.rvm/gems/ruby-2.3.0
user@ ~/dev/helltool (master)$ ruby -e "puts Time.now.usec"
309139

And the corresponding docs: http://ruby-doc.org/core-2.3.0/Time.html#method-i-usec

image

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Dec 16, 2016

Member

We don't have a lot of good options here. System.currentTimeMillis is obviously millisecond resolution. System.nanoTime may provide nanosecond resolution (nanoseconds since the JVM started) but if I remember right it's subject to drift, such as when a system sleeps or hibernates. We got enough bugs trying to use nanoTime that we abandoned it.

Now we could also make a native call, which would give us the same accuracy as MRI, but it would be more overhead to make that call.

Member

headius commented Dec 16, 2016

We don't have a lot of good options here. System.currentTimeMillis is obviously millisecond resolution. System.nanoTime may provide nanosecond resolution (nanoseconds since the JVM started) but if I remember right it's subject to drift, such as when a system sleeps or hibernates. We got enough bugs trying to use nanoTime that we abandoned it.

Now we could also make a native call, which would give us the same accuracy as MRI, but it would be more overhead to make that call.

@amarkowitz

This comment has been minimized.

Show comment
Hide comment
@amarkowitz

amarkowitz Dec 17, 2016

For the native call, are you suggesting clock_gettime? I haven't delved into the MRI Ruby code much yet, but it looks like that's what might be getting called: https://github.com/ruby/ruby/blob/trunk/ext/date/date_core.c#L7649-L7657

How much do you estimate the additional overhead to cost?

amarkowitz commented Dec 17, 2016

For the native call, are you suggesting clock_gettime? I haven't delved into the MRI Ruby code much yet, but it looks like that's what might be getting called: https://github.com/ruby/ruby/blob/trunk/ext/date/date_core.c#L7649-L7657

How much do you estimate the additional overhead to cost?

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 6, 2017

Member

@amarkowitz Unsure about the overhead. The other complication using click_gettime is properly setting up the time structure across platforms.

As a side question...why do you need microsecond granularity from this API? Wouldn't Process::clock_gettime suffice? It uses nanoTime for CLOCK_MONOTONIC on JRuby.

[headius@localhost jruby]$ ruby -v -e "p Process.clock_gettime(Process::CLOCK_MONOTONIC)"
jruby 9.1.7.0-SNAPSHOT (2.3.1) 2017-01-06 db207c1 OpenJDK 64-Bit Server VM 25.111-b16 on 1.8.0_111-b16 +jit [linux-x86_64]
17835.340517158
[headius@localhost jruby]$ rvm ruby-2.3.3 do ruby -v -e "p Process.clock_gettime(Process::CLOCK_MONOTONIC)"
ruby 2.3.3p222 (2016-11-21 revision 56859) [x86_64-linux]
17844.553037418
Member

headius commented Jan 6, 2017

@amarkowitz Unsure about the overhead. The other complication using click_gettime is properly setting up the time structure across platforms.

As a side question...why do you need microsecond granularity from this API? Wouldn't Process::clock_gettime suffice? It uses nanoTime for CLOCK_MONOTONIC on JRuby.

[headius@localhost jruby]$ ruby -v -e "p Process.clock_gettime(Process::CLOCK_MONOTONIC)"
jruby 9.1.7.0-SNAPSHOT (2.3.1) 2017-01-06 db207c1 OpenJDK 64-Bit Server VM 25.111-b16 on 1.8.0_111-b16 +jit [linux-x86_64]
17835.340517158
[headius@localhost jruby]$ rvm ruby-2.3.3 do ruby -v -e "p Process.clock_gettime(Process::CLOCK_MONOTONIC)"
ruby 2.3.3p222 (2016-11-21 revision 56859) [x86_64-linux]
17844.553037418
@amarkowitz

This comment has been minimized.

Show comment
Hide comment
@amarkowitz

amarkowitz Jan 7, 2017

@headius - Great questions. Here are some of my thoughts about why we'd rather not use Process::clock_gettime directly:

def log_time_for_block
  start = Time.now
  begin
    yield
  ensure
    write_to_log_file(Time.now - start)
  end
end

The expectation here is that we get microsecond granularity written to the log files, however in JRuby we only ever get millisecond granularity. We either need to ignore the fact that we don't get the granularity we expect or we need to introduce a lot of forking and/or monkey patching + tests, etc (engineering man hours of work). Both are not ideal.

I'm hoping that this doesn't come across as complainy or whiny as we absolutely appreciate the effort you all put in to JRuby!

amarkowitz commented Jan 7, 2017

@headius - Great questions. Here are some of my thoughts about why we'd rather not use Process::clock_gettime directly:

def log_time_for_block
  start = Time.now
  begin
    yield
  ensure
    write_to_log_file(Time.now - start)
  end
end

The expectation here is that we get microsecond granularity written to the log files, however in JRuby we only ever get millisecond granularity. We either need to ignore the fact that we don't get the granularity we expect or we need to introduce a lot of forking and/or monkey patching + tests, etc (engineering man hours of work). Both are not ideal.

I'm hoping that this doesn't come across as complainy or whiny as we absolutely appreciate the effort you all put in to JRuby!

@kares

This comment has been minimized.

Show comment
Hide comment
@kares

kares Jan 7, 2017

Member

Rails is doing ~ same logging SQL timings, however no one complained so far about only having millis.
... just saying its not the perfect example to want more than millisecond precision on SQL operations :)

Member

kares commented Jan 7, 2017

Rails is doing ~ same logging SQL timings, however no one complained so far about only having millis.
... just saying its not the perfect example to want more than millisecond precision on SQL operations :)

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 9, 2017

Member

By JRuby not supporting microsecond granularity for the methods within the Time class, JRuby very clearly is not in parity with MRI Ruby as stated by the docs (specs?). As pointed out in #4393 (comment) which, as an example, shows how JRuby differs from MRI Ruby with respect to http://ruby-doc.org/core-2.3.0/Time.html#method-i-usec. This lowers confidence in JRuby's parity with MRI Ruby.

It's in the docs but a great deal of what goes in MRI's docs don't work consistently across platforms. Fork is in the docs but doesn't work on Windows (or JRuby). The etc module always can be required but returns bogus values on some platforms. The only real spec is the ISO spec, which just says that Time#usec returns current time modulo 10^6. The spec also says, in the description of the Time class: "The value of microseconds attributes is rounded to fit in the representation of microseconds in an implementation-defined way."

This line of argument is unlikely to convince me :-)

Of course we do want to support microseconds...I don't think anyone is arguing that we wouldn't do so if we knew how. I was suggesting clock_gettime as a workaround until we're able to do so.

SO

The bottom line here is that our Time class is based on Java time, which is milliseconds, and uses the now-standard Joda Time implementation of date/time logic, which also only goes down to milliseconds. In order to support microseconds, we would potentially have to rewrite/duplicate all that logic, or tack on an artificial microsecond field that may or may not actually reflect anything real.

Member

headius commented Jan 9, 2017

By JRuby not supporting microsecond granularity for the methods within the Time class, JRuby very clearly is not in parity with MRI Ruby as stated by the docs (specs?). As pointed out in #4393 (comment) which, as an example, shows how JRuby differs from MRI Ruby with respect to http://ruby-doc.org/core-2.3.0/Time.html#method-i-usec. This lowers confidence in JRuby's parity with MRI Ruby.

It's in the docs but a great deal of what goes in MRI's docs don't work consistently across platforms. Fork is in the docs but doesn't work on Windows (or JRuby). The etc module always can be required but returns bogus values on some platforms. The only real spec is the ISO spec, which just says that Time#usec returns current time modulo 10^6. The spec also says, in the description of the Time class: "The value of microseconds attributes is rounded to fit in the representation of microseconds in an implementation-defined way."

This line of argument is unlikely to convince me :-)

Of course we do want to support microseconds...I don't think anyone is arguing that we wouldn't do so if we knew how. I was suggesting clock_gettime as a workaround until we're able to do so.

SO

The bottom line here is that our Time class is based on Java time, which is milliseconds, and uses the now-standard Joda Time implementation of date/time logic, which also only goes down to milliseconds. In order to support microseconds, we would potentially have to rewrite/duplicate all that logic, or tack on an artificial microsecond field that may or may not actually reflect anything real.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 9, 2017

Member

Ok, my memory regarding nanoTime is coming back.

System.nanoTime is the highest-resolution clock we have on the JVM. It registers the number of nanoseconds since the JVM started. On some platforms, it may not have nanosecond granularity and instead only represent microseconds.

nanoTime does not reflect current time against any universal clock. It's simply measuring ticks since the JVM started.

For a while our Time class captured the current time and nanoTime at the beginning of JRuby startup and used nanoTime from then on to calculate the true current time. Unfortunately nanoTime does not continue to increment while a system is asleep (I assume it's measuring cpu ticks) and it's not possible for us to accurately capture the current nanos since we have to make two separate calls (one for real time, one for nanoTime).

I think the only viable option is to wire up a call to something native that can capture time down to microsecond or nanosecond granularity and then feed that into our Time class.

Member

headius commented Jan 9, 2017

Ok, my memory regarding nanoTime is coming back.

System.nanoTime is the highest-resolution clock we have on the JVM. It registers the number of nanoseconds since the JVM started. On some platforms, it may not have nanosecond granularity and instead only represent microseconds.

nanoTime does not reflect current time against any universal clock. It's simply measuring ticks since the JVM started.

For a while our Time class captured the current time and nanoTime at the beginning of JRuby startup and used nanoTime from then on to calculate the true current time. Unfortunately nanoTime does not continue to increment while a system is asleep (I assume it's measuring cpu ticks) and it's not possible for us to accurately capture the current nanos since we have to make two separate calls (one for real time, one for nanoTime).

I think the only viable option is to wire up a call to something native that can capture time down to microsecond or nanosecond granularity and then feed that into our Time class.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 10, 2017

Member

Ok, so I managed to make a clock_gettime binding in jnr-posix, use that from JRuby, and get proper time resolution down to nanoseconds.

Of course there's a snag. It appears that clock_gettime is not quite standard enough to exist in libc on all platforms. On my Fedora machine, jnr-posix loads fine with clock_gettime being bound. However on Ubuntu, it's contained in a separate library -- librt, the real time library -- so we would need extra magic to only load that library when needed. This is similar to problems @enebo had with the crypt function.

So I'm taking a step back and looking at binding gettimeofday, which should still give us at least microsecond resolution and which should be in every platform's C library.

Member

headius commented Jan 10, 2017

Ok, so I managed to make a clock_gettime binding in jnr-posix, use that from JRuby, and get proper time resolution down to nanoseconds.

Of course there's a snag. It appears that clock_gettime is not quite standard enough to exist in libc on all platforms. On my Fedora machine, jnr-posix loads fine with clock_gettime being bound. However on Ubuntu, it's contained in a separate library -- librt, the real time library -- so we would need extra magic to only load that library when needed. This is similar to problems @enebo had with the crypt function.

So I'm taking a step back and looking at binding gettimeofday, which should still give us at least microsecond resolution and which should be in every platform's C library.

@kares

This comment has been minimized.

Show comment
Hide comment
@kares

kares Jan 10, 2017

Member

it might be worth considering a cli option for this. if a function is common enough its OK to be on, but some platforms (Android) or embed setups might prefer having it the way it has been (System.currentTimeMillis)

Member

kares commented Jan 10, 2017

it might be worth considering a cli option for this. if a function is common enough its OK to be on, but some platforms (Android) or embed setups might prefer having it the way it has been (System.currentTimeMillis)

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 10, 2017

Member

@kares Other than -Xnative.enabled=false? :-)

Seriously though...gettimeofday appears to be a bit more reliable across platforms, and I have a working branch with usec support here: https://github.com/jruby/jruby/tree/gettimeofday

Maybe we can close this in 9170.

Member

headius commented Jan 10, 2017

@kares Other than -Xnative.enabled=false? :-)

Seriously though...gettimeofday appears to be a bit more reliable across platforms, and I have a working branch with usec support here: https://github.com/jruby/jruby/tree/gettimeofday

Maybe we can close this in 9170.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 10, 2017

Member

Bleh, something's not right there, but it's close. If someone wants to fix it before morning, go for it.

Member

headius commented Jan 10, 2017

Bleh, something's not right there, but it's close. If someone wants to fix it before morning, go for it.

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Jan 10, 2017

Member

@headius heh...wow I totally forgot about the sleep issue with nanoTime. We do need a "crap we tried in the past page" on our wiki.

Member

enebo commented Jan 10, 2017

@headius heh...wow I totally forgot about the sleep issue with nanoTime. We do need a "crap we tried in the past page" on our wiki.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 10, 2017

Member

@enebo I think it was before we moved issues to Github too. At least now we can go back and search for "nanoTime" and this bug should surface :-)

Member

headius commented Jan 10, 2017

@enebo I think it was before we moved issues to Github too. At least now we can go back and search for "nanoTime" and this bug should surface :-)

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 10, 2017

Member

Ok, I don't know why I got a bunch of spec failures last night, but it's green today. And I just pushed a fix for Process.clock_gettime to use the same API, which fixes the remaining failure on this branch.

Member

headius commented Jan 10, 2017

Ok, I don't know why I got a bunch of spec failures last night, but it's green today. And I just pushed a fix for Process.clock_gettime to use the same API, which fixes the remaining failure on this branch.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 10, 2017

Member

Ok, so now that we have working microseconds, I can quantify the perf hit of doing the native call: it's about 2x slower. So calling Time.now 1M times takes about 0.27s versus 0.13s on JRuby 9.1.6.0, taking each call from 13 microseconds to 27 microseconds.

I'm not sure if this is enough to be concerned about, but I would guess that Time.now is called a lot in most applications. What say you, @enebo?

Member

headius commented Jan 10, 2017

Ok, so now that we have working microseconds, I can quantify the perf hit of doing the native call: it's about 2x slower. So calling Time.now 1M times takes about 0.27s versus 0.13s on JRuby 9.1.6.0, taking each call from 13 microseconds to 27 microseconds.

I'm not sure if this is enough to be concerned about, but I would guess that Time.now is called a lot in most applications. What say you, @enebo?

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 10, 2017

Member

My math was off...the perf goes from 130ns to 270ns. So we're talking about 0.14 microseconds of extra overhead now.

Member

headius commented Jan 10, 2017

My math was off...the perf goes from 130ns to 270ns. So we're talking about 0.14 microseconds of extra overhead now.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 10, 2017

Member

Oh, I should mention that the numbers above are for a version that uses a thread-local cache of the Timeval struct, so it doesn't have to be allocated every time. Without that change it's another 0.03-0.4s overhead.

Member

headius commented Jan 10, 2017

Oh, I should mention that the numbers above are for a version that uses a thread-local cache of the Timeval struct, so it doesn't have to be allocated every time. Without that change it's another 0.03-0.4s overhead.

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Jan 10, 2017

Member

@headius doesn't seem too bad to me and hey if we were smarter about the timezone calc we can probably get that time back in the allocator.

Member

enebo commented Jan 10, 2017

@headius doesn't seem too bad to me and hey if we were smarter about the timezone calc we can probably get that time back in the allocator.

@kares

This comment has been minimized.

Show comment
Hide comment
@kares

kares Jan 11, 2017

Member

this is great and all well for pure Ruby setups but what about e.g. a Tomcat deployment -> is there any chance System.currentTimeMillis (used by Java loggers) and Time.now (used by Ruby loggers) would get out of sync e.g. a Time.now happening after currentTimeMillis reporting it was vice versa (asking since I am not sure about how currentTimeMillis is implemented on the JVM level) ?

Member

kares commented Jan 11, 2017

this is great and all well for pure Ruby setups but what about e.g. a Tomcat deployment -> is there any chance System.currentTimeMillis (used by Java loggers) and Time.now (used by Ruby loggers) would get out of sync e.g. a Time.now happening after currentTimeMillis reporting it was vice versa (asking since I am not sure about how currentTimeMillis is implemented on the JVM level) ?

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 11, 2017

Member

@kares Well I would hope both Java and the OS think it's the same time of day! If they don't, there's a much more serious problem, since the JVM would not be in sync with any of the non-JVM services on that machine.

And if there's any lingering doubt, here's the implementation of currentTimeMillis in OpenJDK (I suspect other JVMs are similar):

jlong os::javaTimeMillis() {
  timeval time;
  int status = gettimeofday(&time, NULL);
  assert(status != -1, "linux error");
  return jlong(time.tv_sec) * 1000  +  jlong(time.tv_usec / 1000);
}
Member

headius commented Jan 11, 2017

@kares Well I would hope both Java and the OS think it's the same time of day! If they don't, there's a much more serious problem, since the JVM would not be in sync with any of the non-JVM services on that machine.

And if there's any lingering doubt, here's the implementation of currentTimeMillis in OpenJDK (I suspect other JVMs are similar):

jlong os::javaTimeMillis() {
  timeval time;
  int status = gettimeofday(&time, NULL);
  assert(status != -1, "linux error");
  return jlong(time.tv_sec) * 1000  +  jlong(time.tv_usec / 1000);
}

@headius headius closed this in 29c6009 Jan 11, 2017

@headius headius added this to the JRuby 9.1.8.0 milestone Jan 11, 2017

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 11, 2017

Member

I've merged the use of gettimeofday to master. It will be in JRuby 9.1.6.0.

Member

headius commented Jan 11, 2017

I've merged the use of gettimeofday to master. It will be in JRuby 9.1.6.0.

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Jan 11, 2017

Member

@headius not unless it can climb into a time machine my friend!

Member

enebo commented Jan 11, 2017

@headius not unless it can climb into a time machine my friend!

@kares

This comment has been minimized.

Show comment
Hide comment
@kares

kares Jan 12, 2017

Member

Great - my worries were irrelevant than. Thanks.

Member

kares commented Jan 12, 2017

Great - my worries were irrelevant than. Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment