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

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.

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.

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

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.

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 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

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

• 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 microsecond accuracy is not supported in class Time #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.
• In our app, we'd like to have microsecond timing as output by various third party logging facilities, however many of these 3rd party gems just use Time math to calculate duration. Sequel, for example follows this pattern (https://github.com/jeremyevans/sequel/blob/3a61daac311985bfea5566e2ad2c4a5a7a936580/lib/sequel/database/logging.rb#L43-L55) which roughly translates to:

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!

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 :)

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.

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.

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.

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)

@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.

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

@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.

@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 :-)

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.

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?

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

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.

@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.

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) ?

@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);
}

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

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

Great - my worries were irrelevant than. Thanks.