Build with cflags=-DUSE_RUBY_DEBUG_LOG, run with RUBY_DEBUG_LOG=stderr RUBY_DEBUG_LOG_FILTER=... ruby ....
/* RUBY_DEBUG_LOG: Logging debug information mechanism
*
* This feature provides a mechanism to store logging information
* to a file, stderr or memory space with simple macros.
*
* The following information will be stored.
* * (1) __FILE__, __LINE__ in C
* * (2) __FILE__, __LINE__ in Ruby
* * (3) __func__ in C (message title)
* * (4) given string with sprintf format
* * (5) Thread number (if multiple threads are running)
*
* This feature is enabled only USE_RUBY_DEBUG_LOG is enabled.
* Release version should not enable it.
*
* Running with the `RUBY_DEBUG_LOG` environment variable enables
* this feature.
*
* # logging into a file
* RUBY_DEBUG_LOG=/path/to/file STDERR
*
* # logging into STDERR
* RUBY_DEBUG_LOG=stderr
*
* # logging into memory space (check with a debugger)
* # It will help if the timing is important.
* RUBY_DEBUG_LOG=mem
*
* RUBY_DEBUG_LOG_FILTER environment variable can specify the filter string.
* If "(3) __func__ in C (message title)" contains the specified string, the
* information will be stored (example: RUBY_DEBUG_LOG_FILTER=str will enable
* only on str related information).
*
* In a MRI source code, you can use the following macros:
* * RUBY_DEBUG_LOG(fmt, ...): Above (1) to (4) will be logged.
* * RUBY_DEBUG_LOG2(file, line, fmt, ...):
* Same as RUBY_DEBUG_LOG(), but (1) will be replaced with given file, line.
*/https://github.com/ruby/ruby/blob/v3_3_5/vm_debug.h#L38-L75
// RUBY_DEBUG_LOG_FILTER=-foo,-bar,baz,boo
// returns true if
// (func_name or file_name) doesn't contain foo
// and
// (func_name or file_name) doesn't contain bar
// and
// (func_name or file_name) contains baz or boo
//
// RUBY_DEBUG_LOG_FILTER=foo,bar,-baz,-boo
// returns true if
// (func_name or file_name) contains foo or bar
// or
// (func_name or file_name) doesn't contain baz and
// (func_name or file_name) doesn't contain boo and
//
// You can specify "file:" (ex file:foo) or "func:" (ex func:foo)
// prefixes to specify the filter for.https://github.com/ruby/ruby/blob/v3_3_5/debug.c#L485-L503
a.sh:
docker run --rm -t -v /tmp/a.rb:/a.rb -v /tmp/a.patch:/a.patch alpine:3.20.3 sh -euxc '
apk add git build-base autoconf ruby yaml-dev zlib-dev openssl-dev libffi-dev
git clone https://github.com/ruby/ruby
cd ruby
git checkout v3_3_5
patch -p1 < /a.patch
./autogen.sh
./configure cflags=-DUSE_RUBY_DEBUG_LOG --disable-install-doc
make -j8 install
RUBY_DEBUG_LOG=stderr RUBY_DEBUG_LOG_FILTER=rb_thread_schedule_limits,rb_ractor_thread_switch ruby --disable=gems /a.rb
'a.patch:
diff --git a/thread.c b/thread.c
index 104205beb2..375d6a66ac 100644
--- a/thread.c
+++ b/thread.c
@@ -1447,10 +1447,10 @@ rb_thread_schedule_limits(uint32_t limits_us)
{
if (!rb_thread_alone()) {
rb_thread_t *th = GET_THREAD();
- RUBY_DEBUG_LOG("us:%u", (unsigned int)limits_us);
+ // RUBY_DEBUG_LOG("us:%u", (unsigned int)limits_us);
if (th->running_time_us >= limits_us) {
- RUBY_DEBUG_LOG("switch %s", "start");
+ RUBY_DEBUG_LOG("switch %s (running_time_us: %u, limits_us: %u)", "start", th->running_time_us, limits_us);
RB_VM_SAVE_MACHINE_CONTEXT(th);
thread_sched_yield(TH_SCHED(th), th);a.rb:
puts "-- start"
3.times.map {
Thread.new {
(1..10_000_000).reduce(:+)
}
}.each(&:join)
puts "-- end"$ sh a.sh
...
-- start
16: rb_ractor_thread_switch th:1->1 (same) ractor_core.h:288 a.rb:1 nt:1 th:1
17: rb_ractor_thread_switch th:3->2 ractor_core.h:288 nt:2 th:2 (rth:3,sth:2)
18: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:2 th:2 (rth:4,sth:2)
19: rb_ractor_thread_switch th:4->3 ractor_core.h:288 nt:3 th:3 (rth:4,sth:3)
20: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:3 th:3
21: rb_ractor_thread_switch th:3->4 ractor_core.h:288 nt:4 th:4 (rth:3,sth:4)
22: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:4 th:4
23: rb_ractor_thread_switch th:4->2 ractor_core.h:288 a.rb:4 nt:2 th:2 (rth:4,sth:2)
24: rb_ractor_thread_switch th:2->2 (same) ractor_core.h:288 a.rb:4 nt:2 th:2
25: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:2 th:2
26: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:2 th:2
27: rb_ractor_thread_switch th:2->3 ractor_core.h:288 a.rb:4 nt:3 th:3 (rth:2,sth:3)
28: rb_ractor_thread_switch th:3->3 (same) ractor_core.h:288 a.rb:4 nt:3 th:3
29: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:3 th:3
30: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:3 th:3
31: rb_ractor_thread_switch th:3->4 ractor_core.h:288 a.rb:4 nt:4 th:4 (rth:3,sth:4)
32: rb_ractor_thread_switch th:4->4 (same) ractor_core.h:288 a.rb:4 nt:4 th:4
33: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:4 th:4
34: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:4 th:4
35: rb_ractor_thread_switch th:4->2 ractor_core.h:288 a.rb:4 nt:2 th:2 (rth:4,sth:2)
36: rb_ractor_thread_switch th:2->2 (same) ractor_core.h:288 a.rb:4 nt:2 th:2
37: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:2 th:2
38: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:2 th:2
39: rb_ractor_thread_switch th:2->3 ractor_core.h:288 a.rb:4 nt:3 th:3 (rth:2,sth:3)
40: rb_ractor_thread_switch th:3->3 (same) ractor_core.h:288 a.rb:4 nt:3 th:3
41: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:3 th:3
42: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:3 th:3
43: rb_ractor_thread_switch th:3->4 ractor_core.h:288 a.rb:4 nt:4 th:4 (rth:3,sth:4)
44: rb_ractor_thread_switch th:4->4 (same) ractor_core.h:288 a.rb:4 nt:4 th:4
45: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:4 th:4
46: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:4 th:4
47: rb_ractor_thread_switch th:4->2 ractor_core.h:288 a.rb:4 nt:2 th:2 (rth:4,sth:2)
48: rb_ractor_thread_switch th:2->2 (same) ractor_core.h:288 a.rb:4 nt:2 th:2
49: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:2 th:2
50: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:2 th:2
51: rb_ractor_thread_switch th:2->3 ractor_core.h:288 a.rb:4 nt:3 th:3 (rth:2,sth:3)
52: rb_ractor_thread_switch th:3->3 (same) ractor_core.h:288 a.rb:4 nt:3 th:3
53: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:3 th:3
54: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:3 th:3
55: rb_ractor_thread_switch th:3->4 ractor_core.h:288 a.rb:4 nt:4 th:4 (rth:3,sth:4)
56: rb_ractor_thread_switch th:4->4 (same) ractor_core.h:288 a.rb:4 nt:4 th:4
57: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:4 th:4
58: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:4 th:4
59: rb_ractor_thread_switch th:4->2 ractor_core.h:288 a.rb:4 nt:2 th:2 (rth:4,sth:2)
60: rb_ractor_thread_switch th:2->2 (same) ractor_core.h:288 a.rb:4 nt:2 th:2
61: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:2 th:2
62: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:2 th:2
63: rb_ractor_thread_switch th:2->3 ractor_core.h:288 a.rb:4 nt:3 th:3 (rth:2,sth:3)
64: rb_ractor_thread_switch th:3->3 (same) ractor_core.h:288 a.rb:4 nt:3 th:3
65: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:3 th:3
66: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:3 th:3
67: rb_ractor_thread_switch th:3->4 ractor_core.h:288 a.rb:4 nt:4 th:4 (rth:3,sth:4)
68: rb_ractor_thread_switch th:4->4 (same) ractor_core.h:288 a.rb:4 nt:4 th:4
69: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:4 th:4
70: rb_thread_schedule_limits switch start (running_time_us: 100000, limits_us: 100000) thread.c:1455 a.rb:4 nt:4 th:4
71: rb_ractor_thread_switch th:4->2 ractor_core.h:288 a.rb:4 nt:2 th:2 (rth:4,sth:2)
72: rb_ractor_thread_switch th:2->2 (same) ractor_core.h:288 a.rb:4 nt:2 th:2
73: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:2 th:2
74: rb_ractor_thread_switch th:2->3 ractor_core.h:288 a.rb:4 nt:3 th:3 (rth:2,sth:3)
75: rb_ractor_thread_switch th:3->3 (same) ractor_core.h:288 a.rb:4 nt:3 th:3
76: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:3 th:3
77: rb_ractor_thread_switch th:3->4 ractor_core.h:288 a.rb:4 nt:4 th:4 (rth:3,sth:4)
78: rb_ractor_thread_switch th:4->4 (same) ractor_core.h:288 a.rb:4 nt:4 th:4
79: rb_thread_schedule_limits switch done thread.c:1461 a.rb:4 nt:4 th:4
80: rb_ractor_thread_switch th:4->1 ractor_core.h:288 a.rb:6 nt:1 th:1 (rth:4,sth:1)
-- end
81: rb_ractor_thread_switch th:1->1 (same) ractor_core.h:288 a.rb:7 nt:1 th:1