Skip to content

Commit 45c0363

Browse files
aabmassaabmass
committed
Add colors macros which are only supported on bpftrace 0.24+
1 parent fe1d9bb commit 45c0363

3 files changed

Lines changed: 89 additions & 64 deletions

File tree

‎uprobe-contextvars/README.md‎

Lines changed: 50 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -6,60 +6,57 @@ docker compose up --remove-orphans --build
66

77
## Sample output
88

9-
```console
10-
bpftrace-1 | Trying to attach probe: uretprobe:/usr/lib/libpython3.13.so:context_run*
11-
bpftrace-1 | Attaching to 1 functions
12-
bpftrace-1 | /usr/lib/libpython3.13.so:context_run
13-
bpftrace-1 | Trying to attach probe: uprobe:/usr/lib/libpython3.13.so:context_run*
14-
bpftrace-1 | Attaching to 1 functions
15-
bpftrace-1 | /usr/lib/libpython3.13.so:context_run
16-
bpftrace-1 | Trying to attach probe: uprobe:/usr/lib/libpython3.13.so:PyContext_Exit
17-
bpftrace-1 | Trying to attach probe: uprobe:/usr/lib/libpython3.13.so:PyContext_Enter
18-
bpftrace-1 | Attached 4 probes
19-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd35f88900, .args = 0x7fdd36158a98, .nargs = 3, .kwnames = 0x0 }
20-
bpftrace-1 | tid=3062951 return context_run
21-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd36188240, .args = 0x7fdd35f37098, .nargs = 2, .kwnames = 0x0 }
22-
bpftrace-1 | tid=3062951 return context_run
23-
bpftrace-1 | tid=3062958 context_run { .self = 0x7fdd35f88900, .args = 0x7fdd3722e938, .nargs = 1, .kwnames = 0x0 }
24-
python-1 | 200
25-
bpftrace-1 | tid=3062958 return context_run
26-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd35f8b740, .args = 0x7fdd35ff7758, .nargs = 3, .kwnames = 0x0 }
27-
bpftrace-1 | tid=3062951 return context_run
28-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd364f40c0, .args = 0x7fdd3600d588, .nargs = 1, .kwnames = 0x0 }
29-
bpftrace-1 | tid=3062951 return context_run
30-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd364320c0, .args = 0x7fdd35f36118, .nargs = 2, .kwnames = 0x0 }
31-
bpftrace-1 | tid=3062951 return context_run
32-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd36188240, .args = 0x7fdd35f36118, .nargs = 2, .kwnames = 0x0 }
33-
bpftrace-1 | tid=3062951 return context_run
34-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd35f88900, .args = 0x7fdd36158a98, .nargs = 3, .kwnames = 0x0 }
35-
bpftrace-1 | tid=3062951 return context_run
36-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd36188240, .args = 0x7fdd35f36118, .nargs = 2, .kwnames = 0x0 }
37-
bpftrace-1 | tid=3062951 return context_run
38-
bpftrace-1 | tid=3062958 context_run { .self = 0x7fdd35f88900, .args = 0x7fdd3722e938, .nargs = 1, .kwnames = 0x0 }
39-
bpftrace-1 | tid=3062958 return context_run
40-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd35f8b740, .args = 0x7fdd35ff7758, .nargs = 3, .kwnames = 0x0 }
41-
bpftrace-1 | tid=3062951 return context_run
42-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd364f40c0, .args = 0x7fdd3600d738, .nargs = 1, .kwnames = 0x0 }
43-
bpftrace-1 | tid=3062951 return context_run
44-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd364320c0, .args = 0x7fdd35fbaf58, .nargs = 2, .kwnames = 0x0 }
45-
bpftrace-1 | tid=3062951 return context_run
46-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd36188240, .args = 0x7fdd35fbaf58, .nargs = 2, .kwnames = 0x0 }
9+
Sample output of running [print_calls.bt](./print_calls.bt) with [plain.py](./plain.py) as an example workload. `plain.py` uses `asyncio.to_thread()` to run some blocking IO in a thread pool.
10+
11+
![Alt text](./example.png)
12+
13+
<details>
14+
15+
<summary>Raw output</summary>
16+
17+
```
18+
bpftrace-1 | tid=3108292 context_run ctx=0x7f937844a1c0
19+
bpftrace-1 | tid=3108292 context_run return
20+
bpftrace-1 | tid=3108292 context_run ctx=0x7f93789e4280
21+
bpftrace-1 | tid=3108292 PyContext_CopyCurrent -> ctx=0x7f937844a1c0
22+
bpftrace-1 | tid=3108292 PyContext_CopyCurrent -> ctx=0x7f937844a040
23+
bpftrace-1 | tid=3108292 context_run return
24+
bpftrace-1 | tid=3108296 context_run ctx=0x7f937844a1c0
4725
python-1 | 200
26+
bpftrace-1 | tid=3108296 context_run return
27+
bpftrace-1 | tid=3108296 PyContext_CopyCurrent -> ctx=0x7f93788ef800
28+
bpftrace-1 | tid=3108292 context_run ctx=0x7f93788ef800
29+
bpftrace-1 | tid=3108292 context_run return
30+
bpftrace-1 | tid=3108292 context_run ctx=0x7f93788eff00
31+
bpftrace-1 | tid=3108292 context_run return
32+
bpftrace-1 | tid=3108292 context_run ctx=0x7f937844a040
33+
bpftrace-1 | tid=3108292 context_run return
34+
bpftrace-1 | tid=3108292 context_run ctx=0x7f93789e4280
35+
bpftrace-1 | tid=3108292 PyContext_CopyCurrent -> ctx=0x7f937844a1c0
36+
bpftrace-1 | tid=3108292 context_run return
4837
```
4938

50-
In this example `3062951` is the main event loop thread and `3062958` is a thread pool worker,
51-
given work by `asyncio.to_thread()`. When work is run in the thread pool, asyncio wraps that in
52-
`context_run()` so you can track which thread started the work. The [self
53-
argument](https://github.com/python/cpython/blob/v3.13.9/Python/context.c#L649) is a pointer to
54-
the [Context object](https://docs.python.org/3/library/contextvars.html#contextvars.Context). One thing to note is that python may re-use context objects in memory.
39+
</details>
5540

56-
In the above example, Context `0x7fdd35f88900` moves between the two threads.
57-
```console
58-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd35f88900, .args = 0x7fdd36158a98, .nargs = 3, .kwnames = 0x0 }
59-
...
60-
bpftrace-1 | tid=3062958 context_run { .self = 0x7fdd35f88900, .args = 0x7fdd3722e938, .nargs = 1, .kwnames = 0x0 }
61-
...
62-
bpftrace-1 | tid=3062951 context_run { .self = 0x7fdd35f88900, .args = 0x7fdd36158a98, .nargs = 3, .kwnames = 0x0 }
63-
...
64-
bpftrace-1 | tid=3062958 context_run { .self = 0x7fdd35f88900, .args = 0x7fdd3722e938, .nargs = 1, .kwnames = 0x0 }
65-
```
41+
In this example, `3108292` is the main event loop thread and `3108296` is a thread pool worker
42+
thread, which runs work from `asyncio.to_thread()`. The `ctx=...` values are pointers for
43+
[`contextvars.Context`](https://docs.python.org/3/library/contextvars.html#contextvars.Context)
44+
objects.
45+
46+
In the example,
47+
- the main thread is initially running `0x7f937844a1c0`
48+
- it switches to `0x7f93789e4280`. From here it creates two new child contexts
49+
* `0x7f937844a1c0`[^1]
50+
* `0x7f937844a040`
51+
- the worker thread runs `0x7f937844a1c0` which presumably makes the HTTP request
52+
- ...
53+
54+
The `context_run` calls correspond to `contextvars.run()`, used internally by
55+
asyncio to manage the execution context of tasks, and `PyContext_CopyCurrent()` calls which
56+
correspond to creating "child" contexts.
57+
58+
---
59+
60+
[^1]: Note that Python's memory allocator might reuse
61+
addresses for `Context` objects over time (it keeps a freelist), but the sequence of copy
62+
operations followed by their use in the worker thread should still make sense.

‎uprobe-contextvars/example.png‎

123 KB
Loading

‎uprobe-contextvars/print_calls.bt‎

Lines changed: 39 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -1,46 +1,74 @@
11
#define YELLOW "\033[33m"
22
#define NC "\033[0m" // No Color (resets the terminal color)
33

4+
config = {
5+
unstable_macro=enable;
6+
}
7+
8+
// Consistent coloring for a ptr
9+
macro color_int(val) {
10+
let $hash = val % 7;
11+
12+
// Use 256-color codes: \033[38;5;{ID}m
13+
$hash == 0 ? "\033[38;5;196m" : // Bright Red
14+
$hash == 1 ? "\033[38;5;46m" : // Neon Green
15+
$hash == 2 ? "\033[38;5;226m" : // Bright Yellow
16+
$hash == 3 ? "\033[38;5;39m" : // Bright Blue (easier to see than std blue)
17+
$hash == 4 ? "\033[38;5;201m" : // Hot Pink
18+
$hash == 5 ? "\033[38;5;51m" : // Cyan
19+
"\033[38;5;208m" // Orange
20+
}
21+
22+
macro print_uprobe(func_name, ctx_ptr) {
23+
printf("tid=%s%s%s %s ctx=%s%p%s\n", color_int(tid), tid, NC, func_name, color_int(ctx_ptr), ctx_ptr, NC);
24+
}
25+
macro print_uretprobe_void(func_name, ctx_ptr) {
26+
printf("tid=%s%s%s %s return\n", color_int(tid), tid, NC, func_name);
27+
}
28+
macro print_uretprobe(func_name, ctx_ptr) {
29+
printf("tid=%s%s%s %s -> ctx=%s%p%s\n", color_int(tid), tid, NC, func_name, color_int(ctx_ptr), ctx_ptr, NC);
30+
}
31+
432
// These are the official C API for enter/exiting a context, but is not called by the cpython
533
// internals. Something like uvloop might use this.
634
uprobe:/usr/lib/libpython3.13.so:PyContext_Enter {
7-
printf("%stid=%s%s %s %s\n", YELLOW, tid, NC, func, args);
35+
print_uprobe(func, arg0)
836
}
937

1038
uprobe:/usr/lib/libpython3.13.so:PyContext_Exit {
11-
printf("%stid=%s%s %s %s\n", YELLOW, tid, NC, func, args);
39+
print_uprobe(func, arg0)
1240
}
1341

1442
// This is the C implementation of contextvars.run() python function
1543
// https://github.com/python/cpython/blob/v3.13.9/Python/context.c#L648-L650. This plus the
1644
// PyContext_Enter/PyContext_Exit is probably the most reliable.
1745
uprobe:/usr/lib/libpython3.13.so:context_run* {
18-
printf("%stid=%s%s %s %s\n", YELLOW, tid, NC, func, args);
46+
print_uprobe(func, arg0);
1947
}
2048
uretprobe:/usr/lib/libpython3.13.so:context_run* {
21-
printf("%stid=%s%s return %s\n", YELLOW, tid, NC, func);
49+
print_uretprobe_void(func, retval);
2250
}
2351

2452
// -----------
2553

2654
// These might be useful for tracking parentage of new Context objects
2755
uretprobe:/usr/lib/libpython3.13.so:PyContext_CopyCurrent {
28-
printf("%stid=%s%s %s retval = %p\n", YELLOW, tid, NC, func, retval);
56+
print_uretprobe(func, retval)
2957
}
3058
uprobe:/usr/lib/libpython3.13.so:PyContext_Copy {
31-
printf("%stid=%s%s %s %s\n", YELLOW, tid, NC, func, args);
59+
print_uprobe(func, arg0)
3260
}
3361
uretprobe:/usr/lib/libpython3.13.so:PyContext_Copy {
34-
printf("%stid=%s%s %s retval = %p\n", YELLOW, tid, NC, func, retval);
62+
print_uretprobe(func, retval)
3563
}
3664

3765
// These might be useful for watching the trace context for OTel python instrumented code
3866
/*
3967
uprobe:/usr/lib/libpython3.13.so:PyContextVar_Get {
40-
printf("%s %s\n", func, args);
68+
// ...
4169
}
4270
uprobe:/usr/lib/libpython3.13.so:PyContextVar_Set {
43-
printf("%s %s\n", func, args);
71+
// ...
4472
}
4573
*/
4674

@@ -51,9 +79,9 @@ uprobe:/usr/lib/libpython3.13.so:PyContextVar_Set {
5179
// See https://github.com/python/cpython/blob/v3.13.9/Python/context.c#L112-L113
5280
/*
5381
uprobe:/usr/lib/libpython3.13.so:_PyContext_Enter {
54-
printf("tid=%s %s %s\n", tid, func, args);
82+
// ...
5583
}
5684
uprobe:/usr/lib/libpython3.13.so:_PyContext_Exit {
57-
printf("tid=%s %s %s\n", tid, func, args);
85+
// ...
5886
}
5987
*/

0 commit comments

Comments
 (0)