Actions
Bug #14435
closedTime#gettime slow performance in forked process
Status:
Closed
Assignee:
-
Target version:
-
ruby -v:
2.5.0p0 (2017-12-25 revision 61468) [x86_64-darwin17]
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.
Actions
Like0
Like0Like0Like0Like0Like0