-
-
Notifications
You must be signed in to change notification settings - Fork 925
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
Comments
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 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 It would be ideal if jrubys Another example:
vs MRI Ruby
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 How much do you estimate the additional overhead to cost? |
@amarkowitz Unsure about the overhead. The other complication using As a side question...why do you need microsecond granularity from this API? Wouldn't Process::clock_gettime suffice? It uses
|
@headius - Great questions. Here are some of my thoughts about why we'd rather not use
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. |
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 ( |
@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 |
@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. |
Environment
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
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.
The text was updated successfully, but these errors were encountered: