Skip to content

Commit fa30e64

Browse files
vchuravyvchuravy
authored
Merge pull request #41685 from JuliaLang/vc/gc_probes
Add support for USDT probes
2 parents d066a8e + 66b40ad commit fa30e64

File tree

11 files changed

+357
-1
lines changed

11 files changed

+357
-1
lines changed

‎.gitignore

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@
2222
*.so
2323
*.dylib
2424
*.dSYM
25+
*.h.gen
2526
*.jl.cov
2627
*.jl.*.cov
2728
*.jl.mem

‎Make.inc

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -75,6 +75,9 @@ HAVE_SSP := 0
7575
WITH_GC_VERIFY := 0
7676
WITH_GC_DEBUG_ENV := 0
7777

78+
# Enable DTrace support
79+
WITH_DTRACE := 0
80+
7881
# Prevent picking up $ARCH from the environment variables
7982
ARCH:=
8083

@@ -759,6 +762,13 @@ JCXXFLAGS += -DGC_DEBUG_ENV
759762
JCFLAGS += -DGC_DEBUG_ENV
760763
endif
761764

765+
ifeq ($(WITH_DTRACE), 1)
766+
JCXXFLAGS += -DUSE_DTRACE
767+
JCFLAGS += -DUSE_DTRACE
768+
DTRACE := dtrace
769+
else
770+
endif
771+
762772
# ===========================================================================
763773

764774
# Select the cpu architecture to target, or automatically detects the user's compiler
@@ -1555,6 +1565,7 @@ LINKCOLOR:="\033[34;1m"
15551565
PERLCOLOR:="\033[35m"
15561566
FLISPCOLOR:="\033[32m"
15571567
JULIACOLOR:="\033[32;1m"
1568+
DTRACECOLOR:="\033[32;1m"
15581569

15591570
SRCCOLOR:="\033[33m"
15601571
BINCOLOR:="\033[37;1m"
@@ -1568,6 +1579,7 @@ PRINT_LINK = printf ' %b %b\n' $(LINKCOLOR)LINK$(ENDCOLOR) $(BINCOLOR)$(GOAL)
15681579
PRINT_PERL = printf ' %b %b\n' $(PERLCOLOR)PERL$(ENDCOLOR) $(BINCOLOR)$(GOAL)$(ENDCOLOR); $(1)
15691580
PRINT_FLISP = printf ' %b %b\n' $(FLISPCOLOR)FLISP$(ENDCOLOR) $(BINCOLOR)$(GOAL)$(ENDCOLOR); $(1)
15701581
PRINT_JULIA = printf ' %b %b\n' $(JULIACOLOR)JULIA$(ENDCOLOR) $(BINCOLOR)$(GOAL)$(ENDCOLOR); $(1)
1582+
PRINT_DTRACE = printf ' %b %b\n' $(DTRACECOLOR)DTRACE$(ENDCOLOR) $(BINCOLOR)$(GOAL)$(ENDCOLOR); $(1)
15711583
15721584
else
15731585
QUIET_MAKE =
@@ -1577,6 +1589,7 @@ PRINT_LINK = echo '$(subst ','\'',$(1))'; $(1)
15771589
PRINT_PERL = echo '$(subst ','\'',$(1))'; $(1)
15781590
PRINT_FLISP = echo '$(subst ','\'',$(1))'; $(1)
15791591
PRINT_JULIA = echo '$(subst ','\'',$(1))'; $(1)
1592+
PRINT_DTRACE = echo '$(subst ','\'',$(1))'; $(1)
15801593

15811594
endif
15821595

‎contrib/bpftrace/gc_all.bt

Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,44 @@
1+
#!/usr/bin/env bpftrace
2+
3+
BEGIN
4+
{
5+
printf("Tracing Julia GC Times... Hit Ctrl-C to end.\n");
6+
}
7+
8+
usdt:usr/lib/libjulia-internal.so:julia:gc__begin
9+
{
10+
$now = nsecs;
11+
@time[pid] = $now;
12+
@start[pid] = $now;
13+
}
14+
15+
usdt:usr/lib/libjulia-internal.so:julia:gc__stop_the_world
16+
/@start[pid]/
17+
{
18+
$now = nsecs;
19+
@stop_the_world_usecs[pid] = hist(($now - @time[pid]) / 1000);
20+
@time[pid] = $now;
21+
}
22+
23+
usdt:usr/lib/libjulia-internal.so:julia:gc__end
24+
/@start[pid]/
25+
{
26+
$now = nsecs;
27+
@gc_total_usecs[pid] = hist(($now - @start[pid]) / 1000);
28+
@gc_phase_usecs[pid] = hist(($now - @time[pid]) / 1000);
29+
@time[pid] = $now;
30+
delete(@start[pid]);
31+
}
32+
33+
usdt:usr/lib/libjulia-internal.so:julia:gc__finalizer
34+
/@time[pid]/
35+
{
36+
@finalizer[pid] = hist((nsecs - @time[pid]) / 1000);
37+
delete(@time[pid]);
38+
}
39+
40+
END
41+
{
42+
clear(@start);
43+
clear(@time);
44+
}

‎contrib/bpftrace/gc_simple.bt

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,23 @@
1+
#!/usr/bin/env bpftrace
2+
3+
BEGIN
4+
{
5+
printf("Tracing Julia GC Times... Hit Ctrl-C to end.\n");
6+
}
7+
8+
usdt:usr/lib/libjulia-internal.so:julia:gc__begin
9+
{
10+
@start[pid] = nsecs;
11+
}
12+
13+
usdt:usr/lib/libjulia-internal.so:julia:gc__end
14+
/@start[pid]/
15+
{
16+
@usecs[pid] = hist((nsecs - @start[pid]) / 1000);
17+
delete(@start[pid]);
18+
}
19+
20+
END
21+
{
22+
clear(@start);
23+
}

‎contrib/bpftrace/gc_stop_the_world_latency.bt

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,23 @@
1+
#!/usr/bin/env bpftrace
2+
3+
BEGIN
4+
{
5+
printf("Tracing Julia GC Stop-The-World Latency... Hit Ctrl-C to end.\n");
6+
}
7+
8+
usdt:usr/lib/libjulia-internal.so:julia:gc__begin
9+
{
10+
@start[pid] = nsecs;
11+
}
12+
13+
usdt:usr/lib/libjulia-internal.so:julia:gc__stop_the_world
14+
/@start[pid]/
15+
{
16+
@usecs[pid] = hist((nsecs - @start[pid]) / 1000);
17+
delete(@start[pid]);
18+
}
19+
20+
END
21+
{
22+
clear(@start);
23+
}

‎doc/make.jl

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -155,6 +155,7 @@ DevDocs = [
155155
"devdocs/debuggingtips.md",
156156
"devdocs/valgrind.md",
157157
"devdocs/sanitizers.md",
158+
"devdocs/probes.md"
158159
]
159160
]
160161

‎doc/src/devdocs/probes.md

Lines changed: 168 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,168 @@
1+
# Instrumenting Julia with DTrace, and bpftrace
2+
3+
DTrace and bpftrace are tools that enable lightweight instrumentation of processes.
4+
You can turn the instrumentation on and off while the process is running,
5+
and with instrumentation off the overhead is minimal.
6+
7+
!!! compat "Julia 1.8"
8+
Support for probes was added in Julia 1.8
9+
10+
!!! note
11+
This documentation has been written from a Linux perspective, most of this
12+
should hold on Mac OS/Darwin and FreeBSD.
13+
14+
## Enabling support
15+
16+
On Linux install the `systemtap` package that has a version of `dtrace`.
17+
18+
```
19+
WITH_DTRACE=1
20+
```
21+
22+
### Verifying
23+
24+
```
25+
> readelf -n usr/lib/libjulia-internal.so.1
26+
27+
Displaying notes found in: .note.gnu.build-id
28+
Owner Data size Description
29+
GNU 0x00000014 NT_GNU_BUILD_ID (unique build ID bitstring)
30+
Build ID: 57161002f35548772a87418d2385c284ceb3ead8
31+
32+
Displaying notes found in: .note.stapsdt
33+
Owner Data size Description
34+
stapsdt 0x00000029 NT_STAPSDT (SystemTap probe descriptors)
35+
Provider: julia
36+
Name: gc__begin
37+
Location: 0x000000000013213e, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cac
38+
Arguments:
39+
stapsdt 0x00000032 NT_STAPSDT (SystemTap probe descriptors)
40+
Provider: julia
41+
Name: gc__stop_the_world
42+
Location: 0x0000000000132144, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cae
43+
Arguments:
44+
stapsdt 0x00000027 NT_STAPSDT (SystemTap probe descriptors)
45+
Provider: julia
46+
Name: gc__end
47+
Location: 0x000000000013214a, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cb0
48+
Arguments:
49+
stapsdt 0x0000002d NT_STAPSDT (SystemTap probe descriptors)
50+
Provider: julia
51+
Name: gc__finalizer
52+
Location: 0x0000000000132150, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cb2
53+
Arguments:
54+
```
55+
56+
## Adding probes in libjulia
57+
58+
Probes are declared in dtraces format in the file `src/uprobes.d`. The generated
59+
header file is included in `src/julia_internal.h` and if you add probes you should
60+
provide a noop implementation there.
61+
62+
The header will contain a semaphore `*_ENABLED` and the actual call to the probe.
63+
If the probe arguments are expensive to compute you should first check if the
64+
probe is enabled and then compute the arguments and call the probe.
65+
66+
```c
67+
if (JL_PROBE_{PROBE}_ENABLED())
68+
auto expensive_arg = ...;
69+
JL_PROBE_{PROBE}(expensive_arg);
70+
```
71+
72+
If your probe has no arguments it is preferred to not include the semaphore check.
73+
With USDT probes enabled the cost of a semaphore is a memory load, irrespective of
74+
the fact that the probe is enabled or not.
75+
76+
```c
77+
#define JL_PROBE_GC_BEGIN_ENABLED() __builtin_expect (julia_gc__begin_semaphore, 0)
78+
__extension__ extern unsigned short julia_gc__begin_semaphore __attribute__ ((unused)) __attribute__ ((section (".probes")));
79+
```
80+
81+
Whereas the probe itself is a noop sled that will be patched to a trampoline to
82+
the probe handler.
83+
84+
## Available probes
85+
86+
### GC probes
87+
88+
1. `julia:gc__begin`: GC begins running on one thread and triggers stop-the-world.
89+
2. `julia:gc__stop_the_world`: All threads have reached a safepoint and GC runs.
90+
3. `julia:gc__mark__begin`: Beginning the mark phase
91+
4. `julia:gc__mark_end(scanned_bytes, perm_scanned)`: Mark phase ended
92+
5. `julia:gc__sweep_begin(full)`: Starting sweep
93+
6. `julia:gc__sweep_end()`: Sweep phase finished
94+
7. `julia:gc__end`: GC is finished, other threads continue work
95+
8. `julia:gc__finalizer`: Initial GC thread has finished running finalizers
96+
97+
#### GC stop-the-world latency
98+
99+
An example `bpftrace` script is given in `contrib/gc_stop_the_world_latency.bt`
100+
and it creates a histogram of the latency for all threads to reach a safepoint.
101+
102+
Running this Julia code, with `julia -t 2`
103+
104+
```
105+
using Base.Threads
106+
107+
fib(x) = x <= 1 ? 1 : fib(x-1) + fib(x-2)
108+
109+
beaver = @spawn begin
110+
while true
111+
fib(30)
112+
# This safepoint is necessary until #41616, since otherwise this
113+
# loop will never yield to GC.
114+
GC.safepoint()
115+
end
116+
end
117+
118+
allocator = @spawn begin
119+
while true
120+
zeros(1024)
121+
end
122+
end
123+
124+
wait(allocator)
125+
```
126+
127+
and in a second terminal
128+
129+
```
130+
> sudo contrib/bpftrace/gc_stop_the_world_latency.bt
131+
Attaching 4 probes...
132+
Tracing Julia GC Stop-The-World Latency... Hit Ctrl-C to end.
133+
^C
134+
135+
136+
@usecs[1743412]:
137+
[4, 8) 971 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
138+
[8, 16) 837 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
139+
[16, 32) 129 |@@@@@@ |
140+
[32, 64) 10 | |
141+
[64, 128) 1 | |
142+
```
143+
144+
We can see the latency distribution of the stop-the-world phase in the executed Julia process.
145+
146+
## Notes on using `bpftrace`
147+
148+
An example probe in the bpftrace format looks like:
149+
150+
```
151+
usdt:usr/lib/libjulia-internal.so:julia:gc__begin
152+
{
153+
@start[pid] = nsecs;
154+
}
155+
```
156+
157+
The probe declaration takes the kind `usdt`, then either the
158+
path to the library or the PID, the provider name `julia`
159+
and the probe name `gc__begin`. Note that I am using a
160+
relative path to the `libjulia-internal.so`, but this might
161+
need to be an absolute path on a production system.
162+
163+
## Useful references:
164+
165+
- [Julia Evans blog on Linux tracing systems](https://jvns.ca/blog/2017/07/05/linux-tracing-systems)
166+
- [LWN article on USDT and BPF](https://lwn.net/Articles/753601/)
167+
- [GDB support for probes](https://sourceware.org/gdb/onlinedocs/gdb/Static-Probe-Points.html)
168+
- [Brendan Gregg -- Linux Performance](https://www.brendangregg.com/linuxperf.html)

‎src/Makefile

Lines changed: 20 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -84,10 +84,18 @@ endif
8484

8585
SRCS += $(RUNTIME_SRCS)
8686

87+
ifeq ($(WITH_DTRACE),1)
88+
DTRACE_HEADERS := uprobes.h.gen
89+
ifneq ($(OS),Darwin)
90+
SRCS += uprobes
91+
endif
92+
else
93+
DTRACE_HEADERS :=
94+
endif
8795

8896
# headers are used for dependency tracking, while public headers will be part of the dist
8997
UV_HEADERS :=
90-
HEADERS := $(BUILDDIR)/julia_version.h $(wildcard $(SRCDIR)/support/*.h) $(addprefix $(SRCDIR)/,julia.h julia_assert.h julia_threads.h julia_fasttls.h locks.h atomics.h julia_internal.h options.h timing.h)
98+
HEADERS := $(BUILDDIR)/julia_version.h $(wildcard $(SRCDIR)/support/*.h) $(addprefix $(SRCDIR)/,julia.h julia_assert.h julia_threads.h julia_fasttls.h locks.h atomics.h julia_internal.h options.h timing.h) $(addprefix $(BUILDDIR)/, $(DTRACE_HEADERS))
9199
PUBLIC_HEADERS := $(BUILDDIR)/julia_version.h $(wildcard $(SRCDIR)/support/*.h) $(addprefix $(SRCDIR)/,julia.h julia_assert.h julia_threads.h julia_fasttls.h locks.h atomics.h julia_gcext.h)
92100
ifeq ($(USE_SYSTEM_LIBUV),0)
93101
UV_HEADERS += uv.h
@@ -163,6 +171,13 @@ $(BUILDDIR):
163171

164172
LLVM_CONFIG_ABSOLUTE := $(shell which $(LLVM_CONFIG))
165173

174+
# Generate the DTrace header file, while also renaming the macros from
175+
# JULIA_ to JL_PROBE to clearly delinate them.
176+
$(BUILDDIR)/%.h.gen : $(SRCDIR)/%.d
177+
@$(call PRINT_DTRACE, $(DTRACE) -h -s $< -o $@)
178+
sed 's/JULIA_/JL_PROBE_/' $@ > $@.tmp
179+
mv $@.tmp $@
180+
166181
# source file rules
167182
$(BUILDDIR)/%.o: $(SRCDIR)/%.c $(HEADERS) | $(BUILDDIR)
168183
@$(call PRINT_CC, $(CC) $(JCPPFLAGS) $(JCFLAGS) $(SHIPFLAGS) $(DISABLE_ASSERTIONS) -c $< -o $@)
@@ -172,6 +187,10 @@ $(BUILDDIR)/%.o: $(SRCDIR)/%.cpp $(SRCDIR)/llvm-version.h $(HEADERS) $(LLVM_CONF
172187
@$(call PRINT_CC, $(CXX) $(LLVM_CXXFLAGS) $(JCPPFLAGS) $(JCXXFLAGS) $(SHIPFLAGS) $(CXX_DISABLE_ASSERTION) -c $< -o $@)
173188
$(BUILDDIR)/%.dbg.obj: $(SRCDIR)/%.cpp $(SRCDIR)/llvm-version.h $(HEADERS) $(LLVM_CONFIG_ABSOLUTE) | $(BUILDDIR)
174189
@$(call PRINT_CC, $(CXX) $(LLVM_CXXFLAGS) $(JCPPFLAGS) $(JCXXFLAGS) $(DEBUGFLAGS) -c $< -o $@)
190+
$(BUILDDIR)/%.o : $(SRCDIR)/%.d
191+
@$(call PRINT_DTRACE, $(DTRACE) -G -s $< -o $@)
192+
$(BUILDDIR)/%.dbg.obj : $(SRCDIR)/%.d
193+
@$(call PRINT_DTRACE, $(DTRACE) -G -s $< -o $@)
175194

176195
# public header rules
177196
$(eval $(call dir_target,$(build_includedir)/julia))

0 commit comments

Comments
 (0)