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

Time precision problem #5558

Closed
dr-itz opened this Issue Jan 14, 2019 · 3 comments

Comments

Projects
None yet
2 participants
@dr-itz
Copy link
Contributor

dr-itz commented Jan 14, 2019

Environment

  • JRuby 9.1.17.0, 9.2.5.0
  • JDK:
    java version "1.8.0_192"
    Java(TM) SE Runtime Environment (build 1.8.0_192-b12)
    Java HotSpot(TM) 64-Bit Server VM (build 25.192-b12, mixed mode)
    

Problem

Running AR-JDBC tests, we have intermittent failures in Rails Time precision tests. See jruby/activerecord-jdbc-adapter#979 for the test exclusion

Extracted test follows. MRI (tested with 2.4.4 and 2.5.1) runs w/o failures, JRuby fails usually between 1000-2000 iterations.

Reproducer

The script contains all relevant parts from Rails (5.2.2 but 5.0.x is affected too), no dependencies

# what active_record's Time.change does internally
def change_time_usec(time, new_usec)
  new_sec = time.sec
  new_sec += Rational(new_usec, 1000000)
  Time.new(time.year, time.month, time.day, time.hour, time.min, new_sec)
end

def change_time_nsec(time, new_nsec)
  change_time_usec(time, Rational(new_nsec, 1000))
end

# from 'activemodel/lib/active_model/type/helpers/time_value.rb'
def apply_seconds_precision(value, precision)
  number_of_insignificant_digits = 6 - precision
  round_power = 10**number_of_insignificant_digits
  new_usec = value.usec - value.usec % round_power
  change_time_usec(value, new_usec)
end

# basically what
#   activerecord/test/cases/date_time_precision_test.rb
# does in #test_datetime_precision_is_truncated_on_assignment
# note: need to repeat and sleep to reproduce, but not 100% reliable even then
5000.times do |i|
  now = Time.now
  time = change_time_nsec(now, 123456789)
  time2 = apply_seconds_precision(time, 6)

  unless time2.nsec == 123456000
    puts "fail after #{i} iterations"
    puts now.strftime "%H:%M:%S.%N"
    puts time.strftime "%H:%M:%S.%N"
    puts time2.strftime "%H:%M:%S.%N"
    break
  end

  sleep 0.01
end
@dr-itz

This comment has been minimized.

Copy link
Contributor Author

dr-itz commented Jan 17, 2019

Ok, 100% reliable reproducer:

def time_change_sec_usec(time, sec, new_usec)
  # problem is the addition here!
  new_sec = sec + Rational(new_usec, 1000000)
  Time.new(time.year, time.month, time.day, time.hour, time.min, new_sec)
end

now = Time.now
for i in 0..59 do
  time = time_change_sec_usec(now, i, 123456)
  unless time.nsec == 123456000
    puts "fail #{i}: " + time2.strftime("%H:%M:%S.%N")
  end
end

this prints:

fail 8: 23:43:08.123455999
fail 32: 23:43:32.123455999
fail 33: 23:43:33.123455999
fail 34: 23:43:34.123455999

@kares this actually starts to make sense in terms of a rounding problem, no?

@kares

This comment has been minimized.

Copy link
Member

kares commented Jan 18, 2019

indeed it does, will need to look down the path ... would no rely on strftime("%H:%M:%S.%N") for now
btw. at some point I added a similar piece of AS to test time-change: https://github.com/jruby/jruby/blob/master/test/jruby/test_time.rb#L96

@dr-itz

This comment has been minimized.

Copy link
Contributor Author

dr-itz commented Jan 18, 2019

@kares I did a little digging myself. Was an easy fix 😃

dr-itz added a commit to dr-itz/jruby that referenced this issue Jan 18, 2019

@kares kares added this to the JRuby 9.2.6.0 milestone Jan 19, 2019

@kares kares added core Rails labels Jan 20, 2019

@enebo enebo closed this in #5564 Jan 21, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.