[ruby-core:120930] [Ruby master Bug#21127] Thread deadlock does not display backtraces

10 Feb 2025

Issue #21127 has been reported by pocke (Masataka Kuwabara).

----------------------------------------
Bug #21127: Thread deadlock does not display backtraces
https://bugs.ruby-lang.org/issues/21127

* Author: pocke (Masataka Kuwabara)
* Status: Open
* ruby -v: ruby 3.5.0dev (2025-02-10T00:27:18Z master 135479a58d) +PRISM [arm64-darwin24]
* Backport: 3.1: UNKNOWN, 3.2: UNKNOWN, 3.3: UNKNOWN, 3.4: UNKNOWN
----------------------------------------
Previously, Ruby displayed backtraces for each thread on deadlock. However, it has not been shown since Ruby 3.0.
It should display the backtrace for debugging. (related: https://bugs.ruby-lang.org/issues/8214)

## Step to reproduce

```ruby
def f(q) g(q) end
def g(q) h(q) end
def h(q) q.pop end

q = Thread::Queue.new
th1 = Thread.new { f q }
th2 = Thread.new { f q }

th1.join
th2.join
```

Ruby 2.7.8: It displays the trace.

```
ruby-2.7.8 ruby 2.7.8p225 (2023-03-30 revision 1f4d455848) [x86_64-linux]
           -e:9:in `join': No live threads left. Deadlock? (fatal)
           3 threads, 3 sleeps current:0x0000004000653e80 main thread:0x000000400035da50
           * #<Thread:0x000000400038ad70 sleep_forever>
              rb_thread_t:0x000000400035da50 native:0x0000004002fb7740 int:0
              -e:9:in `join'
              -e:9:in `<main>'
           * #<Thread:0x00000040004fe760 -e:6 sleep_forever>
              rb_thread_t:0x00000040004518a0 native:0x00000040067ae700 int:0
               depended by: tb_thread_id:0x000000400035da50
              -e:3:in `pop'
              -e:3:in `h'
              -e:2:in `g'
              -e:1:in `f'
              -e:6:in `block in <main>'
           * #<Thread:0x00000040004fe620 -e:7 sleep_forever>
              rb_thread_t:0x0000004000653e80 native:0x000000400e9af700 int:0
              -e:3:in `pop'
              -e:3:in `h'
              -e:2:in `g'
              -e:1:in `f'
              -e:7:in `block in <main>'
                from -e:9:in `<main>'
```


Ruby 3.0.0: There is no trace.

```
ruby-3.0.0 ruby 3.0.0p0 (2020-12-25 revision 95aff21468) [x86_64-linux]
           -e:9:in `join': No live threads left. Deadlock? (fatal)
           3 threads, 3 sleeps current:0x00000040006e88c0 main thread:0x00000040003ffa10
           * #<Thread:0x000000400046f448 sleep_forever>
              rb_thread_t:0x00000040003ffa10 native:0x0000004003059740 int:0
              
           * #<Thread:0x000000400073c2e8 -e:6 sleep_forever>
              rb_thread_t:0x00000040006e15a0 native:0x0000004006850700 int:0
               depended by: tb_thread_id:0x00000040003ffa10
              
           * #<Thread:0x000000400073c1f8 -e:7 sleep_forever>
              rb_thread_t:0x00000040006e88c0 native:0x000000400ea51700 int:0
              
                from -e:9:in `<main>'
```


Ruby 3.5.0.dev (latest): There is no trace.


```
ruby 3.5.0dev (2025-02-10T00:27:18Z master 135479a58d) +PRISM [arm64-darwin24]
-e:9:in 'Thread#join': No live threads left. Deadlock? (fatal)
3 threads, 3 sleeps current:0x000000012ae3b530 main thread:0x000000012af04080
* #<Thread:0x0000000104aaaf78 sleep_forever>
   rb_thread_t:0x000000012af04080 native:0x00000001e9d93240 int:0
   
* #<Thread:0x0000000104e5e048 -e:6 sleep_forever>
   rb_thread_t:0x000000012ae23a90 native:0x000000016b5f3000 int:0
    depended by: tb_thread_id:0x000000012af04080
   
* #<Thread:0x0000000104e5deb8 -e:7 sleep_forever>
   rb_thread_t:0x000000012ae3b530 native:0x000000016b6ff000 int:0
   

        from -e:9:in '<main>'
```


Note: The results of 2.7 and 3.0 are indented because I executed them with all-ruby.


## Cause


This commit has introduced this change. https://github.com/ruby/ruby/commit/3b24b7914c16930bfadc89d6aff6326a51c54295
The ticket is https://bugs.ruby-lang.org/issues/17031

It changes `rb_ec_backtrace_str_ary` function in `vm_backtrace.c`. Previously, `rb_ec_backtrace_str_ary(ec, 0, 0)` returns all traces, but it returns an empty array with this change. It should pass `ALL_BACKTRACE_LINES` (`-1`) to get all traces.


I used rubyfarm also to confirm that this commit was the cause.


With the commit, it does not display the traces.
```
docker run --rm -ti rubylang/rubyfarm:3b24b7914c16930bfadc89d6aff6326a51c54295 ruby -ve 'def f(q) g(q) end
def g(q) h(q) end
def h(q) q.pop end

q = Thread::Queue.new
th1 = Thread.new { f q }
th2 = Thread.new { f q }

th1.join
th2.join'

ruby 2.8.0dev (2020-08-27T22:17:36Z :detached: 3b24b7914c) [x86_64-linux]
-e:9:in `join': No live threads left. Deadlock? (fatal)
3 threads, 3 sleeps current:0x0000004000566a80 main thread:0x0000004000202a60
* #<Thread:0x000000400026faf8 sleep_forever>
   rb_thread_t:0x0000004000202a60 native:0x000000400440d740 int:0
   
* #<Thread:0x00000040004f1768 -e:6 sleep_forever>
   rb_thread_t:0x0000004000566710 native:0x00000040081fe700 int:0
    depended by: tb_thread_id:0x0000004000202a60
   
* #<Thread:0x00000040004f1600 -e:7 sleep_forever>
   rb_thread_t:0x0000004000566a80 native:0x00000040103ff700 int:0
   
        from -e:9:in `<main>'
```


With the parent commit, it displays the traces.
```
docker run --rm -ti rubylang/rubyfarm:8095114f1715070fcdc2b29303dcf55a7fcc32a3 ruby -ve 'def f(q) g(q) end
def g(q) h(q) end 
def h(q) q.pop end

q = Thread::Queue.new   
th1 = Thread.new { f q }
th2 = Thread.new { f q }

th1.join 
th2.join'

ruby 2.8.0dev (2020-08-27T19:54:36Z :detached: 8095114f17) [x86_64-linux]
-e:9:in `join': No live threads left. Deadlock? (fatal)
3 threads, 3 sleeps current:0x000000400055b3a0 main thread:0x0000004000202a60
* #<Thread:0x000000400026faf8 sleep_forever>
   rb_thread_t:0x0000004000202a60 native:0x000000400440d740 int:0
   -e:9:in `join'
   -e:9:in `<main>'
* #<Thread:0x00000040004f1768 -e:6 sleep_forever>
   rb_thread_t:0x000000400055afe0 native:0x00000040081fe700 int:0
    depended by: tb_thread_id:0x0000004000202a60
   -e:3:in `pop'
   -e:3:in `h'
   -e:2:in `g'
   -e:1:in `f'
   -e:6:in `block in <main>'
* #<Thread:0x00000040004f1600 -e:7 sleep_forever>
   rb_thread_t:0x000000400055b3a0 native:0x00000040103ff700 int:0
   -e:3:in `pop'
   -e:3:in `h'
   -e:2:in `g'
   -e:1:in `f'
   -e:7:in `block in <main>'
        from -e:9:in `<main>'
```


I think it's not an intentional change. The ticket and NEWS do not mention the backtrace on a deadlock. (And the backtrace is really helpful!)


## Solution


The following patch fixes the problem. I'll make a PR on GitHub soon.

```diff

diff --git a/eval_intern.h b/eval_intern.h
index 9a551120ff..f783c93aff 100644
--- a/eval_intern.h
+++ b/eval_intern.h
@@ -300,6 +300,8 @@ void rb_vm_set_progname(VALUE filename);
 VALUE rb_vm_cbase(void);
 
 /* vm_backtrace.c */
+#define BACKTRACE_START 0
+#define ALL_BACKTRACE_LINES -1
 VALUE rb_ec_backtrace_object(const rb_execution_context_t *ec);
 VALUE rb_ec_backtrace_str_ary(const rb_execution_context_t *ec, long lev, long n);
 VALUE rb_ec_backtrace_location_ary(const rb_execution_context_t *ec, long lev, long n, bool skip_internal);
diff --git a/thread.c b/thread.c
index d40d5140b7..5280c667af 100644
--- a/thread.c
+++ b/thread.c
@@ -5596,7 +5596,7 @@ debug_deadlock_check(rb_ractor_t *r, VALUE msg)
             }
         }
         rb_str_catf(msg, "\n   ");
-        rb_str_concat(msg, rb_ary_join(rb_ec_backtrace_str_ary(th->ec, 0, 0), sep));
+        rb_str_concat(msg, rb_ary_join(rb_ec_backtrace_str_ary(th->ec, BACKTRACE_START, ALL_BACKTRACE_LINES), sep));
         rb_str_catf(msg, "\n");
     }
 }
diff --git a/vm_backtrace.c b/vm_backtrace.c
index 56a0d861d6..6f2cf9e169 100644
--- a/vm_backtrace.c
+++ b/vm_backtrace.c
@@ -31,9 +31,6 @@ id2str(ID id)
 }
 #define rb_id2str(id) id2str(id)
 
-#define BACKTRACE_START 0
-#define ALL_BACKTRACE_LINES -1
-
 inline static int
 calc_pos(const rb_iseq_t *iseq, const VALUE *pc, int *lineno, int *node_id)
 {
```

The result is here:

```
$ ruby -ve 'def f(q) g(q) end
def g(q) h(q) end
def h(q) q.pop end

q = Thread::Queue.new
th1 = Thread.new { f q }
th2 = Thread.new { f q }

th1.join
th2.join'

ruby 3.5.0dev (2025-02-10T00:27:18Z origin/master 135479a58d) +PRISM [arm64-darwin24]
-e:9:in 'Thread#join': No live threads left. Deadlock? (fatal)
3 threads, 3 sleeps current:0x0000000157a053a0 main thread:0x0000000156704080
* #<Thread:0x000000011bcfaf78 sleep_forever>
   rb_thread_t:0x0000000156704080 native:0x00000001e9d93240 int:0
   -e:9:in 'Thread#join'
   -e:9:in '<main>'
* #<Thread:0x000000011d2d0bb8 -e:6 sleep_forever>
   rb_thread_t:0x0000000157a04d40 native:0x000000016dcb7000 int:0
    depended by: tb_thread_id:0x0000000156704080
   <internal:thread_sync>:18:in 'Thread::Queue#pop'
   -e:3:in 'Object#h'
   -e:2:in 'Object#g'
   -e:1:in 'Object#f'
   -e:6:in 'block in <main>'
* #<Thread:0x000000011d2d07a8 -e:7 sleep_forever>
   rb_thread_t:0x0000000157a053a0 native:0x000000016ddc3000 int:0
   <internal:thread_sync>:18:in 'Thread::Queue#pop'
   -e:3:in 'Object#h'
   -e:2:in 'Object#g'
   -e:1:in 'Object#f'
   -e:7:in 'block in <main>'

	from -e:9:in '<main>'

```



-- 
https://bugs.ruby-lang.org/

    