Skip to content

Commit 037bd7a

Browse files
aabmassaabmass
committed
Add colors macros which are only supported on bpftrace 0.24+
1 parent 23aecde commit 037bd7a

3 files changed

Lines changed: 85 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: 35 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -1,46 +1,70 @@
11
#define YELLOW "\033[33m"
22
#define NC "\033[0m" // No Color (resets the terminal color)
33

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

1034
uprobe:/usr/lib/libpython3.13.so:PyContext_Exit {
11-
printf("%stid=%s%s %s %s\n", YELLOW, tid, NC, func, args);
35+
print_uretprobe(func, arg0)
1236
}
1337

1438
// This is the C implementation of contextvars.run() python function
1539
// https://github.com/python/cpython/blob/v3.13.9/Python/context.c#L648-L650. This plus the
1640
// PyContext_Enter/PyContext_Exit is probably the most reliable.
1741
uprobe:/usr/lib/libpython3.13.so:context_run* {
18-
printf("%stid=%s%s %s %s\n", YELLOW, tid, NC, func, args);
42+
print_uprobe(func, arg0);
1943
}
2044
uretprobe:/usr/lib/libpython3.13.so:context_run* {
21-
printf("%stid=%s%s return %s\n", YELLOW, tid, NC, func);
45+
print_uretprobe_void(func, retval);
2246
}
2347

2448
// -----------
2549

2650
// These might be useful for tracking parentage of new Context objects
2751
uretprobe:/usr/lib/libpython3.13.so:PyContext_CopyCurrent {
28-
printf("%stid=%s%s %s retval = %p\n", YELLOW, tid, NC, func, retval);
52+
print_uretprobe(func, retval)
2953
}
3054
uprobe:/usr/lib/libpython3.13.so:PyContext_Copy {
31-
printf("%stid=%s%s %s %s\n", YELLOW, tid, NC, func, args);
55+
print_uprobe(func, arg0)
3256
}
3357
uretprobe:/usr/lib/libpython3.13.so:PyContext_Copy {
34-
printf("%stid=%s%s %s retval = %p\n", YELLOW, tid, NC, func, retval);
58+
print_uretprobe(func, retval)
3559
}
3660

3761
// These might be useful for watching the trace context for OTel python instrumented code
3862
/*
3963
uprobe:/usr/lib/libpython3.13.so:PyContextVar_Get {
40-
printf("%s %s\n", func, args);
64+
// ...
4165
}
4266
uprobe:/usr/lib/libpython3.13.so:PyContextVar_Set {
43-
printf("%s %s\n", func, args);
67+
// ...
4468
}
4569
*/
4670

@@ -51,9 +75,9 @@ uprobe:/usr/lib/libpython3.13.so:PyContextVar_Set {
5175
// See https://github.com/python/cpython/blob/v3.13.9/Python/context.c#L112-L113
5276
/*
5377
uprobe:/usr/lib/libpython3.13.so:_PyContext_Enter {
54-
printf("tid=%s %s %s\n", tid, func, args);
78+
// ...
5579
}
5680
uprobe:/usr/lib/libpython3.13.so:_PyContext_Exit {
57-
printf("tid=%s %s %s\n", tid, func, args);
81+
// ...
5882
}
5983
*/

0 commit comments

Comments
 (0)