Instead of writing ad-hoc logging everywhere (eg: #19509), we can take advantage of linux user static defined traces, aka. USDTs ( not the stablecoin :sweat_smile: )
The linux kernel can hook into these tracepoints at runtime, but otherwise they have little to no performance impact. Traces can pass data which can be printed externally via tools such as bpftrace. For example, here’s one that prints incoming and outgoing network messages:
Examples
Network Messages
0#!/usr/bin/env bpftrace
1
2BEGIN
3{
4 printf("bitcoin net msgs\n"); [@start](/bitcoin-bitcoin/contributor/start/) = nsecs;
5}
6
7usdt:./src/bitcoind:net:push_message
8{
9 $ip = str(arg0);
10 $peer_id = (int64)arg1;
11 $command = str(arg2);
12 $data_len = arg3;
13 $data = buf(arg3,arg4);
14 $t = (nsecs - [@start](/bitcoin-bitcoin/contributor/start/)) / 100000;
15
16 printf("%zu outbound %s %s %zu %d %r\n", $t, $command, $ip, $peer_id, $data_len, $data); [@outbound](/bitcoin-bitcoin/contributor/outbound/)[$command]++;
17}
18
19usdt:./src/bitcoind:net:process_message
20{
21 $ip = str(arg0);
22 $peer_id = (int64)arg1;
23 $command = str(arg2);
24 $data_len = arg3;
25 $data = buf(arg3,arg4);
26 $t = (nsecs - [@start](/bitcoin-bitcoin/contributor/start/)) / 100000;
27
28 printf("%zu inbound %s %s %zu %d %r\n", $t, $command, $ip, $peer_id, $data_len, $data); [@inbound](/bitcoin-bitcoin/contributor/inbound/)[$ip, $command]++;
29}
$ sudo bpftrace netmsg.bt
output: https://jb55.com/s/b11312484b601fb3.txt
if you look at the bottom of the output you can see a histogram of all the messages grouped by message type and IP. nice!
IBD Benchmarking
0#!/usr/bin/env bpftrace
1BEGIN
2{
3 printf("IBD to 500,000 bench\n");
4}
5
6usdt:./src/bitcoind:CChainState:ConnectBlock
7{
8 $height = (uint32)arg0;
9
10 if ($height == 1) {
11 printf("block 1 found, starting benchmark\n"); [@start](/bitcoin-bitcoin/contributor/start/) = nsecs;
12 }
13
14 if ($height >= 500000) { [@end](/bitcoin-bitcoin/contributor/end/) = nsecs; [@duration](/bitcoin-bitcoin/contributor/duration/) = [@end](/bitcoin-bitcoin/contributor/end/) - [@start](/bitcoin-bitcoin/contributor/start/);
15 exit();
16 }
17}
18
19END {
20 printf("duration %d ms\n", [@duration](/bitcoin-bitcoin/contributor/duration/) / 1000000)
21}
This one hooks into ConnectBlock and prints the IBD time to height 500,000 starting from the first call to ConnectBlock
Userspace static tracepoints give lots of flexibility without invasive logging code. It’s also more flexible than ad-hoc logging code, allowing you to instrument many different aspects of the system without having to enable per-subsystem logging.
Other ideas: tracepoints for lock contention, threads, what else?
Let me know what ya’ll think and if this is worth adding to bitcoin.
TODO
- docs?
- Integrate systemtap-std-dev/libsystemtap into build (provides the <sys/sdt.h> header)
- ~dtrace macos support? (is this still a thing?)~ going to focus on linux for now
