Bug #14435
closed
Time#gettime slow performance in forked process
Description
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.
Updated by tenderlovemaking (Aaron Patterson) about 6 years ago
After searching around, it looks like this is related to tzset implementation on macOS:
https://stackoverflow.com/questions/27932330/why-is-tzset-a-lot-slower-after-forking-on-mac-os-x
This seems like something that should be fixed in macOS, I think.
Updated by bryanp (Bryan Powell) about 6 years ago
Ah, interesting. I looked around for other issues related to tzset and found this:
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?
Updated by rafaelfranca (Rafael França) almost 6 years ago
Looks like r63857 fix this issue.
Naruse-san, can we backport it to 2.4 and 2.5? It is causing some massive performance problems on MacOS.
Updated by naruse (Yui NARUSE) almost 6 years ago
- Related to Bug #14920: Backport r63857 to fix performance problem on Time class in MacOs systems added
Updated by naruse (Yui NARUSE) almost 6 years ago
- Status changed from Open to Closed
Handle backport on #14920, close this ticket.