* [ruby-core:109157] [Ruby master Bug#18900] Missing events(?)/unexpected results using GVL instrumentation API
@ 2022-07-07 10:51 ivoanjo (Ivo Anjo)
2022-07-07 12:28 ` [ruby-core:109158] " byroot (Jean Boussier)
2022-07-07 13:23 ` [ruby-core:109160] " byroot (Jean Boussier)
0 siblings, 2 replies; 3+ messages in thread
From: ivoanjo (Ivo Anjo) @ 2022-07-07 10:51 UTC (permalink / raw
To: ruby-core
Issue #18900 has been reported by ivoanjo (Ivo Anjo).
----------------------------------------
Bug #18900: Missing events(?)/unexpected results using GVL instrumentation API
https://bugs.ruby-lang.org/issues/18900
* Author: ivoanjo (Ivo Anjo)
* Status: Open
* Priority: Normal
* ruby -v: ruby 3.2.0dev (2022-07-06T09:08:31Z master 5ef3c7ea2d) [x86_64-linux]
* Backport: 2.7: UNKNOWN, 3.0: UNKNOWN, 3.1: UNKNOWN
----------------------------------------
I'd like to start by thanking @byroot for his amazing work on the [GVL Instrumentation API](https://bugs.ruby-lang.org/issues/18339). This new API is going to be really useful for those of us doing performance analysis of Ruby apps :)
For context, I'm running a recent ruby master build: `ruby 3.2.0dev (2022-07-06T09:08:31Z master 5ef3c7ea2d) [x86_64-linux]`
### The issue
I'm working at Datadog on the ddtrace gem, and I've been prototyping the use of the GVL Instrumentation API on our Profiler (still an experiment for now).
I've built a trivial GVL event handler ( https://github.com/DataDog/dd-trace-rb/blob/9f98c371f114a037d5c73b1d8efbc1220797c350/ext/ddtrace_profiling_native_extension/gvl_tracing.c ) that prints 3 things to a file for every event: thread id, timestamp, and event.
I've noticed that there are events "missing" that I would've expected to have received. For instance, consider the following code:
```ruby
Datadog::Profiling::GvlTracing._native_start
def fib(n)
return n if n <= 1
fib(n-1) + fib(n-2)
end
1.times.map { Thread.new { fib(35) } }.map(&:join)
Datadog::Profiling::GvlTracing._native_stop
```
and here's the resulting events received from the Ruby VM:
```ruby
# thread id..........timestamp............event
[139927701786432, 1657188684855568392, "suspended"],
[139927701786432, 1657188684855602550, "ready"],
[139927701786432, 1657188684855603318, "resumed"],
[139927633524480, 1657188684855761222, "started"],
[139927633524480, 1657188684855763974, "ready"],
[139927633524480, 1657188684855764431, "resumed"],
[139927633524480, 1657188685610511252, "suspended"],
[139927633524480, 1657188685610517376, "exited"],
[139927701786432, 1657188685610615925, "ready"],
[139927701786432, 1657188685610644531, "resumed"],
```
This seems surprising to me: the main thread that got blocked on `#join` was never marked as `suspended`, even though there's a `resumed` event from a different thread.
When looking at it from a per-thread timeline point-of-view, the events for thread 139927701786432 are "suspended" -> "ready" -> "resumed" -> "ready" which isn't what I was expecting.
This issue doesn't seem to be connected to the `#join` specifically.
For instance if I add a second thread:
```diff
+1.times.map { Thread.new { fib(35) } }.map(&:join)
-2.times.map { Thread.new { fib(35) } }.map(&:join)
```
here's what I get:
```ruby
# thread id..........timestamp............event
[140298252205888, 1657190331866960767, "suspended"],
[140298252205888, 1657190331866997030, "ready"],
[140298252205888, 1657190331866997882, "resumed"],
[140298181732096, 1657190331867188792, "started"],
[140298181732096, 1657190331867190524, "ready"],
[140298181732096, 1657190331867190813, "resumed"], # <--- first fibonacci thread started working without main suspending
[140298183833344, 1657190331867198615, "started"],
[140298183833344, 1657190331867201182, "ready"],
[140298183833344, 1657190331967683212, "resumed"], # <-- second fibonacci thread resumed without a suspend from the first
[140298181732096, 1657190331967765804, "ready"],
[140298181732096, 1657190332067699266, "resumed"], # <--- first fibonacci again, missing suspend event
[140298183833344, 1657190332067722234, "ready"],
[140298183833344, 1657190332167930765, "resumed"],
[140298181732096, 1657190332167949981, "ready"],
[140298181732096, 1657190332268129230, "resumed"],
[140298183833344, 1657190332268153149, "ready"],
[140298183833344, 1657190332368425743, "resumed"],
[140298181732096, 1657190332368450799, "ready"],
[140298181732096, 1657190332468822338, "resumed"],
[140298183833344, 1657190332468908400, "ready"],
[140298183833344, 1657190332568760756, "resumed"],
[140298181732096, 1657190332568807475, "ready"],
[140298181732096, 1657190332669003133, "resumed"],
[140298183833344, 1657190332669041747, "ready"],
[140298183833344, 1657190332769014200, "resumed"],
[140298181732096, 1657190332769035727, "ready"],
[140298181732096, 1657190332869415660, "resumed"],
[140298183833344, 1657190332869531747, "ready"],
[140298183833344, 1657190332969455281, "resumed"],
[140298181732096, 1657190332969512054, "ready"],
[140298181732096, 1657190333069937592, "resumed"],
[140298183833344, 1657190333069992165, "ready"],
[140298183833344, 1657190333169832772, "resumed"],
[140298181732096, 1657190333169860028, "ready"],
[140298181732096, 1657190333270139615, "resumed"],
[140298183833344, 1657190333270239955, "ready"],
[140298181732096, 1657190333323601109, "suspended"],
[140298181732096, 1657190333323642507, "exited"],
[140298183833344, 1657190333323736093, "resumed"],
[140298183833344, 1657190333375825514, "suspended"],
[140298183833344, 1657190333375832829, "exited"],
[140298252205888, 1657190333375867753, "ready"],
[140298252205888, 1657190333375870165, "resumed"],
```
On my prototype, for instance in https://github.com/DataDog/dd-trace-rb/blob/ivoanjo/experiment-gvl-tracing/gvl_tracing_example1.rb, I've taken to simulating a suspend event when I find this kind of gap in the event stream.
### How to reproduce
Here's how to use my tracing experiment code, from scratch:
```bash
$ git clone https://github.com/DataDog/dd-trace-rb.git
Cloning into 'dd-trace-rb'...
remote: Enumerating objects: 78965, done.
remote: Counting objects: 100% (1621/1621), done.
remote: Compressing objects: 100% (857/857), done.
remote: Total 78965 (delta 952), reused 1336 (delta 746), pack-reused 77344
Receiving objects: 100% (78965/78965), 50.54 MiB | 10.98 MiB/s, done.
Resolving deltas: 100% (55760/55760), done.
$ cd dd-trace-rb/
/dd-trace-rb$ git checkout ivoanjo/experiment-gvl-tracing
branch 'ivoanjo/experiment-gvl-tracing' set up to track 'origin/ivoanjo/experiment-gvl-tracing'.
Switched to a new branch 'ivoanjo/experiment-gvl-tracing'
/dd-trace-rb$ docker run --network=host -ti -v `pwd`:/working rubocophq/ruby-snapshot:latest /bin/bash
root@docker-desktop:/# ruby -v
ruby 3.2.0dev (2022-07-06T09:08:31Z master 5ef3c7ea2d) [x86_64-linux]
root@docker-desktop:/# cd working/
root@docker-desktop:/working# bundle install
# ...
Bundle complete! 35 Gemfile dependencies, 70 gems now installed.
# ...
root@docker-desktop:/working# bundle exec rake compile
# ...
root@docker-desktop:/working# bundle exec ruby gvl_tracing_example1.rb
Started!
Stopped!
root@docker-desktop:/working# head gvl_tracing_out.json
[
[140451049381696, 1657190910088942000, "started_tracing"],
[140451049381696, 1657190910088957670, "resumed"],
[140451049381696, 1657190910089018233, "suspended"],
[140450981082880, 1657190910089076610, "resumed"],
[140451049381696, 1657190910089085748, "ready"],
[140451049381696, 1657190910089169091, "resumed"],
[140450981082880, 1657190910143208013, "ready"],
[140450981082880, 1657190910143257050, "resumed"],
[140451049381696, 1657190910143547517, "ready"],
root@docker-desktop:/working# head gvl_tracing_ux_2022-07-07T10\:48\:40Z.json
{
"threads": {
"140451049381696": [
{
"startNs": 1657190910088942000,
"endNs": 1657190910088957670,
"label": "started_tracing",
"durationSeconds": 1.567e-05
},
{
```
--
https://bugs.ruby-lang.org/
^ permalink raw reply [flat|nested] 3+ messages in thread
* [ruby-core:109158] [Ruby master Bug#18900] Missing events(?)/unexpected results using GVL instrumentation API
2022-07-07 10:51 [ruby-core:109157] [Ruby master Bug#18900] Missing events(?)/unexpected results using GVL instrumentation API ivoanjo (Ivo Anjo)
@ 2022-07-07 12:28 ` byroot (Jean Boussier)
2022-07-07 13:23 ` [ruby-core:109160] " byroot (Jean Boussier)
1 sibling, 0 replies; 3+ messages in thread
From: byroot (Jean Boussier) @ 2022-07-07 12:28 UTC (permalink / raw
To: ruby-core
Issue #18900 has been updated by byroot (Jean Boussier).
> This seems surprising to me: the main thread that got blocked on #join was never marked as suspended, even though there's a resumed event from a different thread.
I may have missed some kind of fastpath in which we should trigger that event. I'll have a look.
----------------------------------------
Bug #18900: Missing events(?)/unexpected results using GVL instrumentation API
https://bugs.ruby-lang.org/issues/18900#change-98301
* Author: ivoanjo (Ivo Anjo)
* Status: Open
* Priority: Normal
* ruby -v: ruby 3.2.0dev (2022-07-06T09:08:31Z master 5ef3c7ea2d) [x86_64-linux]
* Backport: 2.7: UNKNOWN, 3.0: UNKNOWN, 3.1: UNKNOWN
----------------------------------------
I'd like to start by thanking @byroot for his amazing work on the [GVL Instrumentation API](https://bugs.ruby-lang.org/issues/18339). This new API is going to be really useful for those of us doing performance analysis of Ruby apps :)
For context, I'm running a recent ruby master build: `ruby 3.2.0dev (2022-07-06T09:08:31Z master 5ef3c7ea2d) [x86_64-linux]`
### The issue
I'm working at Datadog on the ddtrace gem, and I've been prototyping the use of the GVL Instrumentation API on our Profiler (still an experiment for now).
I've built a trivial GVL event handler ( https://github.com/DataDog/dd-trace-rb/blob/9f98c371f114a037d5c73b1d8efbc1220797c350/ext/ddtrace_profiling_native_extension/gvl_tracing.c ) that prints 3 things to a file for every event: thread id, timestamp, and event.
I've noticed that there are events "missing" that I would've expected to have received. For instance, consider the following code:
```ruby
Datadog::Profiling::GvlTracing._native_start
def fib(n)
return n if n <= 1
fib(n-1) + fib(n-2)
end
1.times.map { Thread.new { fib(35) } }.map(&:join)
Datadog::Profiling::GvlTracing._native_stop
```
and here's the resulting events received from the Ruby VM:
```ruby
# thread id..........timestamp............event
[139927701786432, 1657188684855568392, "suspended"],
[139927701786432, 1657188684855602550, "ready"],
[139927701786432, 1657188684855603318, "resumed"],
[139927633524480, 1657188684855761222, "started"],
[139927633524480, 1657188684855763974, "ready"],
[139927633524480, 1657188684855764431, "resumed"],
[139927633524480, 1657188685610511252, "suspended"],
[139927633524480, 1657188685610517376, "exited"],
[139927701786432, 1657188685610615925, "ready"],
[139927701786432, 1657188685610644531, "resumed"],
```
This seems surprising to me: the main thread that got blocked on `#join` was never marked as `suspended`, even though there's a `resumed` event from a different thread.
When looking at it from a per-thread timeline point-of-view, the events for thread 139927701786432 are "suspended" -> "ready" -> "resumed" -> "ready" which isn't what I was expecting.
This issue doesn't seem to be connected to the `#join` specifically.
For instance if I add a second thread:
```diff
+1.times.map { Thread.new { fib(35) } }.map(&:join)
-2.times.map { Thread.new { fib(35) } }.map(&:join)
```
here's what I get:
```ruby
# thread id..........timestamp............event
[140298252205888, 1657190331866960767, "suspended"],
[140298252205888, 1657190331866997030, "ready"],
[140298252205888, 1657190331866997882, "resumed"],
[140298181732096, 1657190331867188792, "started"],
[140298181732096, 1657190331867190524, "ready"],
[140298181732096, 1657190331867190813, "resumed"], # <--- first fibonacci thread started working without main suspending
[140298183833344, 1657190331867198615, "started"],
[140298183833344, 1657190331867201182, "ready"],
[140298183833344, 1657190331967683212, "resumed"], # <-- second fibonacci thread resumed without a suspend from the first
[140298181732096, 1657190331967765804, "ready"],
[140298181732096, 1657190332067699266, "resumed"], # <--- first fibonacci again, missing suspend event
[140298183833344, 1657190332067722234, "ready"],
[140298183833344, 1657190332167930765, "resumed"],
[140298181732096, 1657190332167949981, "ready"],
[140298181732096, 1657190332268129230, "resumed"],
[140298183833344, 1657190332268153149, "ready"],
[140298183833344, 1657190332368425743, "resumed"],
[140298181732096, 1657190332368450799, "ready"],
[140298181732096, 1657190332468822338, "resumed"],
[140298183833344, 1657190332468908400, "ready"],
[140298183833344, 1657190332568760756, "resumed"],
[140298181732096, 1657190332568807475, "ready"],
[140298181732096, 1657190332669003133, "resumed"],
[140298183833344, 1657190332669041747, "ready"],
[140298183833344, 1657190332769014200, "resumed"],
[140298181732096, 1657190332769035727, "ready"],
[140298181732096, 1657190332869415660, "resumed"],
[140298183833344, 1657190332869531747, "ready"],
[140298183833344, 1657190332969455281, "resumed"],
[140298181732096, 1657190332969512054, "ready"],
[140298181732096, 1657190333069937592, "resumed"],
[140298183833344, 1657190333069992165, "ready"],
[140298183833344, 1657190333169832772, "resumed"],
[140298181732096, 1657190333169860028, "ready"],
[140298181732096, 1657190333270139615, "resumed"],
[140298183833344, 1657190333270239955, "ready"],
[140298181732096, 1657190333323601109, "suspended"],
[140298181732096, 1657190333323642507, "exited"],
[140298183833344, 1657190333323736093, "resumed"],
[140298183833344, 1657190333375825514, "suspended"],
[140298183833344, 1657190333375832829, "exited"],
[140298252205888, 1657190333375867753, "ready"],
[140298252205888, 1657190333375870165, "resumed"],
```
On my prototype, for instance in https://github.com/DataDog/dd-trace-rb/blob/ivoanjo/experiment-gvl-tracing/gvl_tracing_example1.rb, I've taken to simulating a suspend event when I find this kind of gap in the event stream.
### How to reproduce
Here's how to use my tracing experiment code, from scratch:
```bash
$ git clone https://github.com/DataDog/dd-trace-rb.git
Cloning into 'dd-trace-rb'...
remote: Enumerating objects: 78965, done.
remote: Counting objects: 100% (1621/1621), done.
remote: Compressing objects: 100% (857/857), done.
remote: Total 78965 (delta 952), reused 1336 (delta 746), pack-reused 77344
Receiving objects: 100% (78965/78965), 50.54 MiB | 10.98 MiB/s, done.
Resolving deltas: 100% (55760/55760), done.
$ cd dd-trace-rb/
/dd-trace-rb$ git checkout ivoanjo/experiment-gvl-tracing
branch 'ivoanjo/experiment-gvl-tracing' set up to track 'origin/ivoanjo/experiment-gvl-tracing'.
Switched to a new branch 'ivoanjo/experiment-gvl-tracing'
/dd-trace-rb$ docker run --network=host -ti -v `pwd`:/working rubocophq/ruby-snapshot:latest /bin/bash
root@docker-desktop:/# ruby -v
ruby 3.2.0dev (2022-07-06T09:08:31Z master 5ef3c7ea2d) [x86_64-linux]
root@docker-desktop:/# cd working/
root@docker-desktop:/working# bundle install
# ...
Bundle complete! 35 Gemfile dependencies, 70 gems now installed.
# ...
root@docker-desktop:/working# bundle exec rake compile
# ...
root@docker-desktop:/working# bundle exec ruby gvl_tracing_example1.rb
Started!
Stopped!
root@docker-desktop:/working# head gvl_tracing_out.json
[
[140451049381696, 1657190910088942000, "started_tracing"],
[140451049381696, 1657190910088957670, "resumed"],
[140451049381696, 1657190910089018233, "suspended"],
[140450981082880, 1657190910089076610, "resumed"],
[140451049381696, 1657190910089085748, "ready"],
[140451049381696, 1657190910089169091, "resumed"],
[140450981082880, 1657190910143208013, "ready"],
[140450981082880, 1657190910143257050, "resumed"],
[140451049381696, 1657190910143547517, "ready"],
root@docker-desktop:/working# head gvl_tracing_ux_2022-07-07T10\:48\:40Z.json
{
"threads": {
"140451049381696": [
{
"startNs": 1657190910088942000,
"endNs": 1657190910088957670,
"label": "started_tracing",
"durationSeconds": 1.567e-05
},
{
```
--
https://bugs.ruby-lang.org/
^ permalink raw reply [flat|nested] 3+ messages in thread
* [ruby-core:109160] [Ruby master Bug#18900] Missing events(?)/unexpected results using GVL instrumentation API
2022-07-07 10:51 [ruby-core:109157] [Ruby master Bug#18900] Missing events(?)/unexpected results using GVL instrumentation API ivoanjo (Ivo Anjo)
2022-07-07 12:28 ` [ruby-core:109158] " byroot (Jean Boussier)
@ 2022-07-07 13:23 ` byroot (Jean Boussier)
1 sibling, 0 replies; 3+ messages in thread
From: byroot (Jean Boussier) @ 2022-07-07 13:23 UTC (permalink / raw
To: ruby-core
Issue #18900 has been updated by byroot (Jean Boussier).
I got a patch for it: https://github.com/ruby/ruby/pull/6101
----------------------------------------
Bug #18900: Missing events(?)/unexpected results using GVL instrumentation API
https://bugs.ruby-lang.org/issues/18900#change-98302
* Author: ivoanjo (Ivo Anjo)
* Status: Open
* Priority: Normal
* ruby -v: ruby 3.2.0dev (2022-07-06T09:08:31Z master 5ef3c7ea2d) [x86_64-linux]
* Backport: 2.7: UNKNOWN, 3.0: UNKNOWN, 3.1: UNKNOWN
----------------------------------------
I'd like to start by thanking @byroot for his amazing work on the [GVL Instrumentation API](https://bugs.ruby-lang.org/issues/18339). This new API is going to be really useful for those of us doing performance analysis of Ruby apps :)
For context, I'm running a recent ruby master build: `ruby 3.2.0dev (2022-07-06T09:08:31Z master 5ef3c7ea2d) [x86_64-linux]`
### The issue
I'm working at Datadog on the ddtrace gem, and I've been prototyping the use of the GVL Instrumentation API on our Profiler (still an experiment for now).
I've built a trivial GVL event handler ( https://github.com/DataDog/dd-trace-rb/blob/9f98c371f114a037d5c73b1d8efbc1220797c350/ext/ddtrace_profiling_native_extension/gvl_tracing.c ) that prints 3 things to a file for every event: thread id, timestamp, and event.
I've noticed that there are events "missing" that I would've expected to have received. For instance, consider the following code:
```ruby
Datadog::Profiling::GvlTracing._native_start
def fib(n)
return n if n <= 1
fib(n-1) + fib(n-2)
end
1.times.map { Thread.new { fib(35) } }.map(&:join)
Datadog::Profiling::GvlTracing._native_stop
```
and here's the resulting events received from the Ruby VM:
```ruby
# thread id..........timestamp............event
[139927701786432, 1657188684855568392, "suspended"],
[139927701786432, 1657188684855602550, "ready"],
[139927701786432, 1657188684855603318, "resumed"],
[139927633524480, 1657188684855761222, "started"],
[139927633524480, 1657188684855763974, "ready"],
[139927633524480, 1657188684855764431, "resumed"],
[139927633524480, 1657188685610511252, "suspended"],
[139927633524480, 1657188685610517376, "exited"],
[139927701786432, 1657188685610615925, "ready"],
[139927701786432, 1657188685610644531, "resumed"],
```
This seems surprising to me: the main thread that got blocked on `#join` was never marked as `suspended`, even though there's a `resumed` event from a different thread.
When looking at it from a per-thread timeline point-of-view, the events for thread 139927701786432 are "suspended" -> "ready" -> "resumed" -> "ready" which isn't what I was expecting.
This issue doesn't seem to be connected to the `#join` specifically.
For instance if I add a second thread:
```diff
+1.times.map { Thread.new { fib(35) } }.map(&:join)
-2.times.map { Thread.new { fib(35) } }.map(&:join)
```
here's what I get:
```ruby
# thread id..........timestamp............event
[140298252205888, 1657190331866960767, "suspended"],
[140298252205888, 1657190331866997030, "ready"],
[140298252205888, 1657190331866997882, "resumed"],
[140298181732096, 1657190331867188792, "started"],
[140298181732096, 1657190331867190524, "ready"],
[140298181732096, 1657190331867190813, "resumed"], # <--- first fibonacci thread started working without main suspending
[140298183833344, 1657190331867198615, "started"],
[140298183833344, 1657190331867201182, "ready"],
[140298183833344, 1657190331967683212, "resumed"], # <-- second fibonacci thread resumed without a suspend from the first
[140298181732096, 1657190331967765804, "ready"],
[140298181732096, 1657190332067699266, "resumed"], # <--- first fibonacci again, missing suspend event
[140298183833344, 1657190332067722234, "ready"],
[140298183833344, 1657190332167930765, "resumed"],
[140298181732096, 1657190332167949981, "ready"],
[140298181732096, 1657190332268129230, "resumed"],
[140298183833344, 1657190332268153149, "ready"],
[140298183833344, 1657190332368425743, "resumed"],
[140298181732096, 1657190332368450799, "ready"],
[140298181732096, 1657190332468822338, "resumed"],
[140298183833344, 1657190332468908400, "ready"],
[140298183833344, 1657190332568760756, "resumed"],
[140298181732096, 1657190332568807475, "ready"],
[140298181732096, 1657190332669003133, "resumed"],
[140298183833344, 1657190332669041747, "ready"],
[140298183833344, 1657190332769014200, "resumed"],
[140298181732096, 1657190332769035727, "ready"],
[140298181732096, 1657190332869415660, "resumed"],
[140298183833344, 1657190332869531747, "ready"],
[140298183833344, 1657190332969455281, "resumed"],
[140298181732096, 1657190332969512054, "ready"],
[140298181732096, 1657190333069937592, "resumed"],
[140298183833344, 1657190333069992165, "ready"],
[140298183833344, 1657190333169832772, "resumed"],
[140298181732096, 1657190333169860028, "ready"],
[140298181732096, 1657190333270139615, "resumed"],
[140298183833344, 1657190333270239955, "ready"],
[140298181732096, 1657190333323601109, "suspended"],
[140298181732096, 1657190333323642507, "exited"],
[140298183833344, 1657190333323736093, "resumed"],
[140298183833344, 1657190333375825514, "suspended"],
[140298183833344, 1657190333375832829, "exited"],
[140298252205888, 1657190333375867753, "ready"],
[140298252205888, 1657190333375870165, "resumed"],
```
On my prototype, for instance in https://github.com/DataDog/dd-trace-rb/blob/ivoanjo/experiment-gvl-tracing/gvl_tracing_example1.rb, I've taken to simulating a suspend event when I find this kind of gap in the event stream.
### How to reproduce
Here's how to use my tracing experiment code, from scratch:
```bash
$ git clone https://github.com/DataDog/dd-trace-rb.git
Cloning into 'dd-trace-rb'...
remote: Enumerating objects: 78965, done.
remote: Counting objects: 100% (1621/1621), done.
remote: Compressing objects: 100% (857/857), done.
remote: Total 78965 (delta 952), reused 1336 (delta 746), pack-reused 77344
Receiving objects: 100% (78965/78965), 50.54 MiB | 10.98 MiB/s, done.
Resolving deltas: 100% (55760/55760), done.
$ cd dd-trace-rb/
/dd-trace-rb$ git checkout ivoanjo/experiment-gvl-tracing
branch 'ivoanjo/experiment-gvl-tracing' set up to track 'origin/ivoanjo/experiment-gvl-tracing'.
Switched to a new branch 'ivoanjo/experiment-gvl-tracing'
/dd-trace-rb$ docker run --network=host -ti -v `pwd`:/working rubocophq/ruby-snapshot:latest /bin/bash
root@docker-desktop:/# ruby -v
ruby 3.2.0dev (2022-07-06T09:08:31Z master 5ef3c7ea2d) [x86_64-linux]
root@docker-desktop:/# cd working/
root@docker-desktop:/working# bundle install
# ...
Bundle complete! 35 Gemfile dependencies, 70 gems now installed.
# ...
root@docker-desktop:/working# bundle exec rake compile
# ...
root@docker-desktop:/working# bundle exec ruby gvl_tracing_example1.rb
Started!
Stopped!
root@docker-desktop:/working# head gvl_tracing_out.json
[
[140451049381696, 1657190910088942000, "started_tracing"],
[140451049381696, 1657190910088957670, "resumed"],
[140451049381696, 1657190910089018233, "suspended"],
[140450981082880, 1657190910089076610, "resumed"],
[140451049381696, 1657190910089085748, "ready"],
[140451049381696, 1657190910089169091, "resumed"],
[140450981082880, 1657190910143208013, "ready"],
[140450981082880, 1657190910143257050, "resumed"],
[140451049381696, 1657190910143547517, "ready"],
root@docker-desktop:/working# head gvl_tracing_ux_2022-07-07T10\:48\:40Z.json
{
"threads": {
"140451049381696": [
{
"startNs": 1657190910088942000,
"endNs": 1657190910088957670,
"label": "started_tracing",
"durationSeconds": 1.567e-05
},
{
```
--
https://bugs.ruby-lang.org/
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2022-07-07 13:24 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2022-07-07 10:51 [ruby-core:109157] [Ruby master Bug#18900] Missing events(?)/unexpected results using GVL instrumentation API ivoanjo (Ivo Anjo)
2022-07-07 12:28 ` [ruby-core:109158] " byroot (Jean Boussier)
2022-07-07 13:23 ` [ruby-core:109160] " byroot (Jean Boussier)
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).