Issue #14435 has been updated by bryanp (Bryan Powell).
Ah, interesting. I looked around for other issues related to `tzset` and found this:
https://stackoverflow.com/questions/41353532/why-is-time-utc-slower-in-a-forked-process-in-ruby-on-os-x-and-not-in-python/41371753
I did confirm that the slowdown only occurs in years without leap seconds... e.g. replace `Time.now` with `Time.new(2016, 12, 01)` in the above examples and the forked version is just as fast as the non-forked version. While I do agree that the issue seems to originate in macOS, would it be worth exploring what an optimization might look like?
----------------------------------------
Bug #14435: Time#gettime slow performance in forked process
https://bugs.ruby-lang.org/issues/14435#change-70257
* Author: bryanp (Bryan Powell)
* Status: Open
* Priority: Normal
* Assignee:
* Target version:
* ruby -v: 2.5.0p0 (2017-12-25 revision 61468) [x86_64-darwin17]
* Backport: 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: UNKNOWN
----------------------------------------
Hi,
I'm seeing poor performance in `Time#gettime` when executing code in a forked process. Perhaps this is expected, but after a good amount of research I could not come to a reasonable conclusion.
See comparisons below:
~~~
require "ruby-prof"
RubyProf.start
10_000.times { Time.now.getlocal }
RubyProf::FlatPrinter.new(RubyProf.stop).print(STDOUT)
# Measure Mode: wall_time
# Thread ID: 70211449654940
# Fiber ID: 70211441152020
# Total: 0.014502
# Sort by: self_time
# %self total self wait child calls name
# 43.02 0.006 0.006 0.000 0.000 10000 Time#getlocal
# 23.78 0.005 0.003 0.000 0.001 10000 <Class::Time>#now
# 19.30 0.014 0.003 0.000 0.011 1 Integer#times
# 8.73 0.001 0.001 0.000 0.000 10000 Time#initialize
# 0.17 0.015 0.000 0.000 0.014 1 [global]#[no method]
# 0.04 0.001 0.000 0.000 0.001 4 *Kernel#require
# 0.04 0.000 0.000 0.000 0.000 2 MonitorMixin#mon_exit
# 0.04 0.000 0.000 0.000 0.000 2 MonitorMixin#mon_enter
# 0.03 0.000 0.000 0.000 0.000 16 Module#method_added
# 0.03 0.000 0.000 0.000 0.000 4 IO#set_encoding
# 0.02 0.000 0.000 0.000 0.000 2 Class#inherited
# 0.02 0.000 0.000 0.000 0.000 2 <Module::Gem>#find_unresolved_default_spec
# 0.02 0.000 0.000 0.000 0.000 6 <Class::Thread>#current
# 0.01 0.000 0.000 0.000 0.000 2 Kernel#respond_to?
# 0.01 0.000 0.000 0.000 0.000 2 <Class::Gem::Specification>#unresolved_deps
# 0.01 0.000 0.000 0.000 0.000 1 Module#private
# 0.01 0.000 0.000 0.000 0.000 2 MonitorMixin#mon_check_owner
# 0.01 0.000 0.000 0.000 0.000 2 Thread::Mutex#unlock
# 0.01 0.000 0.000 0.000 0.000 1 BasicObject#singleton_method_added
# 0.01 0.000 0.000 0.000 0.000 2 Thread::Mutex#lock
~~~
**Forked process:**
~~~
require "ruby-prof"
pid = Process.fork {
RubyProf.start
10_000.times { Time.now.getlocal }
RubyProf::FlatPrinter.new(RubyProf.stop).print(STDOUT)
}
sleep 5; Process.kill("INT", pid)
# Measure Mode: wall_time
# Thread ID: 70295801310860
# Fiber ID: 70295809457020
# Total: 1.113997
# Sort by: self_time
# %self total self wait child calls name
# 98.41 1.096 1.096 0.000 0.000 10000 Time#getlocal
# 0.67 1.113 0.007 0.000 1.105 1 Integer#times
# 0.67 0.009 0.007 0.000 0.002 10000 <Class::Time>#now
# 0.15 0.002 0.002 0.000 0.000 10000 Time#initialize
# 0.00 1.114 0.000 0.000 1.114 1 [global]#[no method]
# 0.00 0.000 0.000 0.000 0.000 4 IO#set_encoding
# 0.00 0.001 0.000 0.000 0.001 4 *Kernel#require
# 0.00 0.000 0.000 0.000 0.000 2 MonitorMixin#mon_exit
# 0.00 0.000 0.000 0.000 0.000 2 MonitorMixin#mon_enter
# 0.00 0.000 0.000 0.000 0.000 6 <Class::Thread>#current
# 0.00 0.000 0.000 0.000 0.000 2 <Module::Gem>#find_unresolved_default_spec
# 0.00 0.000 0.000 0.000 0.000 2 Class#inherited
# 0.00 0.000 0.000 0.000 0.000 2 <Class::Gem::Specification>#unresolved_deps
# 0.00 0.000 0.000 0.000 0.000 2 Thread::Mutex#unlock
# 0.00 0.000 0.000 0.000 0.000 2 MonitorMixin#mon_check_owner
# 0.00 0.000 0.000 0.000 0.000 2 Thread::Mutex#lock
# 0.00 0.000 0.000 0.000 0.000 16 Module#method_added
# 0.00 0.000 0.000 0.000 0.000 1 BasicObject#singleton_method_added
# 0.00 0.000 0.000 0.000 0.000 1 Module#private
# 0.00 0.000 0.000 0.000 0.000 2 Kernel#respond_to?
~~~
*1.11s in a forked process vs 0.01s in the main process.*
I can improve performance somewhat (0.47s) by explicitly setting `ENV["TZ"]`:
~~~
require "ruby-prof"
pid = Process.fork {
ENV["TZ"] = "UTC"
RubyProf.start
10_000.times { Time.now.getlocal }
RubyProf::FlatPrinter.new(RubyProf.stop).print(STDOUT)
}
sleep 5; Process.kill("INT", pid)
# Measure Mode: wall_time
# Thread ID: 70347118612140
# Fiber ID: 70347131000480
# Total: 0.469237
# Sort by: self_time
# %self total self wait child calls name
# 96.17 0.451 0.451 0.000 0.000 10000 Time#getlocal
# 1.74 0.010 0.008 0.000 0.002 10000 <Class::Time>#now
# 1.49 0.468 0.007 0.000 0.461 1 Integer#times
# 0.36 0.002 0.002 0.000 0.000 10000 Time#initialize
# 0.01 0.469 0.000 0.000 0.469 1 [global]#[no method]
# 0.00 0.000 0.000 0.000 0.000 4 IO#set_encoding
# 0.00 0.001 0.000 0.000 0.001 4 *Kernel#require
# 0.00 0.000 0.000 0.000 0.000 2 MonitorMixin#mon_enter
# 0.00 0.000 0.000 0.000 0.000 2 <Module::Gem>#find_unresolved_default_spec
# 0.00 0.000 0.000 0.000 0.000 2 MonitorMixin#mon_exit
# 0.00 0.000 0.000 0.000 0.000 2 Kernel#respond_to?
# 0.00 0.000 0.000 0.000 0.000 6 <Class::Thread>#current
# 0.00 0.000 0.000 0.000 0.000 2 Thread::Mutex#lock
# 0.00 0.000 0.000 0.000 0.000 2 Class#inherited
# 0.00 0.000 0.000 0.000 0.000 2 <Class::Gem::Specification>#unresolved_deps
# 0.00 0.000 0.000 0.000 0.000 16 Module#method_added
# 0.00 0.000 0.000 0.000 0.000 2 MonitorMixin#mon_check_owner
# 0.00 0.000 0.000 0.000 0.000 2 Thread::Mutex#unlock
# 0.00 0.000 0.000 0.000 0.000 1 BasicObject#singleton_method_added
# 0.00 0.000 0.000 0.000 0.000 1 Module#private
~~~
I am running ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-darwin17] on macOS 10.13.3 (17D47).
Happy to help in any way I can.
Bryan P.
--
https://bugs.ruby-lang.org/
Unsubscribe: <mailto:ruby-core-request / ruby-lang.org?subject=unsubscribe>
<http://lists.ruby-lang.org/cgi-bin/mailman/options/ruby-core>