[#87773] timer thread [was Re: [ruby-alerts:7905] failure alert on trunk-asserts@silicon-docker (NG (r63844))] — Eric Wong <normalperson@...>
> test_all <main>: warning: pthread_create failed for timer: Resource temporarily unavailable, scheduling broken
[#87836] [Ruby trunk Bug#14898] test/lib/test/unit/parallel.rb: TestSocket#test_timestamp stuck sometimes — ko1@...
Issue #14898 has been reported by ko1 (Koichi Sasada).
[email protected] wrote:
On 2018/07/06 18:47, Eric Wong wrote:
[#87847] undefined symbol: mjit_init_p — Leam Hall <leamhall@...>
I pulled Ruby trunk on 3 Jul and am now getting errors similar to the
QXMgSSB0b2xkIHlvdSwgYG1ha2UgaW5zdGFsbGAgaXMgbmVlZGVkIHRvIG1ha2UgUnVieSB3b3Jr
T25lIG1vcmUgcmVhc29uIGZvciBodHRwczovL2J1Z3MucnVieS1sYW5nLm9yZy9pc3N1ZXMvMTM2
[#87986] [Ruby trunk Feature#14915] Deprecate String#crypt, move implementation to string/crypt — mame@...
Issue #14915 has been updated by mame (Yusuke Endoh).
[email protected] wrote:
normalperson (Eric Wong) wrote:
[#88088] [Ruby trunk Misc#14937] [PATCH] thread_pthread: lazy-spawn timer-thread only on contention — normalperson@...
Issue #14937 has been reported by normalperson (Eric Wong).
[#88104] [Ruby trunk Bug#14898] test/lib/test/unit/parallel.rb: TestSocket#test_timestamp stuck sometimes — ko1@...
Issue #14898 has been updated by ko1 (Koichi Sasada).
[#88173] [Ruby trunk Bug#14950] r64109 thread.c: move ppoll wrapper before thread_pthread.c - Windows compile failure - thread.c — Greg.mpls@...
Issue #14950 has been reported by MSP-Greg (Greg L).
[#88189] [Ruby trunk Bug#14950] r64109 thread.c: move ppoll wrapper before thread_pthread.c - Windows compile failure - thread.c — nobu@...
Issue #14950 has been updated by nobu (Nobuyoshi Nakada).
[#88199] [Ruby trunk Misc#14937] [PATCH] thread_pthread: lazy-spawn timer-thread only on contention — takashikkbn@...
Issue #14937 has been updated by k0kubun (Takashi Kokubun).
[email protected] wrote:
> yet, sky3 had a failure at
> http://ci.rvm.jp/results/trunk@P895/1173951
> > http://ci.rvm.jp/results/trunk@P895/1173951
[ruby-core:88005] [Ruby trunk Bug#14435][Closed] Time#gettime slow performance in forked process
Issue #14435 has been updated by naruse (Yui NARUSE).
Status changed from Open to Closed
Handle backport on #14920, close this ticket.
----------------------------------------
Bug #14435: Time#gettime slow performance in forked process
https://bugs.ruby-lang.org/issues/14435#change-73023
* Author: bryanp (Bryan Powell)
* Status: Closed
* 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:[email protected]?subject=unsubscribe>
<http://lists.ruby-lang.org/cgi-bin/mailman/options/ruby-core>