eBPF Linux tracepoints

[jb55]

Instead of writing ad-hoc logging everywhere (eg: #19509), we can take advantage of linux user static defined traces, aka. USDTs ( not the stablecoin 😅 )

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

#!/usr/bin/env bpftrace

BEGIN
{
  printf("bitcoin net msgs\n");
  @start = nsecs;
}

usdt:./src/bitcoind:net:push_message
{
  $ip = str(arg0);
  $peer_id = (int64)arg1;
  $command = str(arg2);
  $data_len = arg3;
  $data = buf(arg3,arg4);
  $t = (nsecs - @start) / 100000;

  printf("%zu outbound %s %s %zu %d %r\n", $t, $command, $ip, $peer_id, $data_len, $data);

  @outbound[$command]++;
}

usdt:./src/bitcoind:net:process_message
{
  $ip = str(arg0);
  $peer_id = (int64)arg1;
  $command = str(arg2);
  $data_len = arg3;
  $data = buf(arg3,arg4);
  $t = (nsecs - @start) / 100000;

  printf("%zu inbound %s %s %zu %d %r\n", $t, $command, $ip, $peer_id, $data_len, $data);

  @inbound[$ip, $command]++;
}

$ 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

#!/usr/bin/env bpftrace
BEGIN
{
  printf("IBD to 500,000 bench\n");
}

usdt:./src/bitcoind:CChainState:ConnectBlock
{
  $height = (uint32)arg0;

  if ($height == 1) {
    printf("block 1 found, starting benchmark\n");
    @start = nsecs;
  }

  if ($height >= 500000) {
    @end = nsecs;
    @duration = @end - @start;
    exit();
  }
}

END {
  printf("duration %d ms\n", @duration / 1000000)
}

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

[laanwj]

Concept ACK, thanks for working on this, I think this is a great way to have more visibility into internal metrics (for diagnosing issues, and statistics), without intrusive changes, or having to hand-roll all kind of custom tooling.

[practicalswift]

Concept ACK: more tooling for allowing visibility into internals for power users is good. I don't think this Linux only improvement removes the need for #19509 at all: I would use both in different contexts :)

[DrahtBot]

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

No conflicts as of last run.

[jonatack]

Concept ACK, will review/test.

[jb55]

@jonatack thanks! you need systemtap-sdt-dev if you're on debian-like which I still need to add to the build. This just provides the sdt header file.

[jonatack]

@jonatack thanks! you need systemtap-sdt-dev if you're on debian-like which I still need to add to the build. This just provides the sdt header file.

Thanks for the heads-up! which probably saved me some time even though you mentioned it in the PR description. Done: sudo apt install systemtap-sdt-dev

[laanwj]

Could list the probe points in gdb:

(gdb) info probes
Type Provider            Name            Where              Semaphore Object                                     
stap CChainState         ConnectBlock    0x0000000000294636           /…/bitcoin/src/bitcoind 
stap CConnman            PushMessage     0x000000000009ab40           /…/bitcoin/src/bitcoind 
stap PeerLogicValidation ProcessMessages 0x00000000000d1387           /…/bitcoin/bitcoin/src/bitcoind 

$ sudo bpftrace netmsg.bt -o nettrace.txt -c "./src/bitcoind -datadir=/run/bitcoin "

Is it really necessary to run this as root?
I read @eklitzke's blog post back in the day and he doesn't use it there. But it looks like he uses a different tool, stap instead of bpftrace.

Edit: yes it is necessary to run bpftrace as root,because it uses some privileged kernel functionality. It's probably not necessary to run bitcoind as root though.

[laanwj]

I'm trying the first example, but it complains about a missing function buf. Any idea? Maybe too old bptrace version?

# uname -r
5.4.0-42-generic
# bpftrace --version
bpftrace v0.9.4
# bpftrace -p $(cat ~user/.bitcoin/bitcoind.pid) ../network-messages.bt 
../network-messages.bt:13:11-14: ERROR: Unknown function: buf
  $data = buf(arg1,arg2);
          ~~~

[jb55]

"Wladimir J. van der Laan" <notifications@github.com> writes:

I'm trying the first example, but it complains about a missing function `buf`. Any idea? Maybe too old bptrace version?

yeah buf is a new thing from bpftrace 0.11 and bcc 0.16.0, you can just remove that if you're testing. bpftrace is a pretty high level thing, you can write lower level bpf programs with bcc, I haven't tried that yet but it looks like its more powerful. bpftrace is great for simple stuff though.

[jb55]

Edit: yes it is necessary to run bpftrace as root,because it uses some privileged kernel functionality. It's probably not necessary to run bitcoind as root though.

right, you can run bitcoin without root and then attach to it with bpftrace afterwards.

[jb55]

Could list the probe points in gdb

I wasn't sure how we should name the probes, right now I just have the mapped to class::method but perhaps they could be more abstract like validation:connect_block, net:push_message, net:process_message ?

[laanwj]

yeah buf is a new thing from bpftrace 0.11 and bcc 0.16.0, you can just remove that if you're testing.

Good to know! I've built bpftrace from git and it works now (which is version bpftrace v0.11.0, a lot newer!), thanks.

I wasn't sure how we should name the probes, right now I just have the mapped to class::method but perhaps they could be more abstract like validation:connect_block, net:push_message, net:process_message ?

I think I prefer that. It has the probe point name describe more accurately the action taken and data that is traced.
We'll want to list and document these at some point.

Other ideas: tracepoints for lock contention, threads, what else?

I think these would be good to have too:

• Peer connected
• Peer disconnected

BTW: is it possible to do binary logging with bpftrace or bcc? (e.g. to provide a similar output to #19509). Or is it always text?

[laanwj]

Rebased version here: https://github.com/laanwj/bitcoin/tree/usdt-probes

[laanwj]

I'm not sure we want to pass the sanitized packet type to the probe here or simply the raw data.

Edit: Nah, I guess anyone that wants the raw data already has a pointer to the packet, which is passed too. It's extra information.

[laanwj]

I've also made a start with documentation doc/tracing.md: https://github.com/laanwj/bitcoin/blob/35cad1adbf2bdf98d437e499ea10904d967b0083/doc/tracing.md

[jb55]

@laanwj writes:

I'm not sure we want to pass the sanitized packet type to the probe here or simply the raw data.

I'm not super familiar with the network packet format, is this easy to pull from the raw data? If so we probably don't need it. I wasn't really happy with the current binary capabilities of bpftrace but I imagine this will get better over time once the tooling matures.

Rebased version here: https://github.com/laanwj/bitcoin/tree/usdt-probes

Thanks for moving this along. I reviewed the range diff and looks ok.

I've also made a start with documentation doc/tracing.md: https://github.com/laanwj/bitcoin/blob/35cad1adbf2bdf98d437e499ea10904d967b0083/doc/tracing.md

Amazing, thank you!

[laanwj]

I'm not super familiar with the network packet format, is this easy to
pull from the raw data?

Yea the header is very simple, given that eBPF is used for complex packet fltering and pre-processing setups I'm a bit surprised the binary handling capabilities are still a weak point but it should be able to handle it:

0…3    u8[4]  Start characters
4…15   u8[20] Type (zero padded text)
16…19  u32    Size in bytes
20     u8     Checksum

[laanwj]

I would prefer to rearrange the arguments to push_message to be in the same order as process_message (eg move node_id up front before msgtype_str):

net:push_message(int node_id, char* msgtype_str, uint8_t* tx_data, size_t tx_size)

[laanwj]

I think this is ready to go out of draft and get review for the build system changes. It adds the basic infrastructure for tracing. Further tracepoints and examples can be added in later PRs.

[jb55]

I think this is ready to go out of draft and get review for the build system changes. It adds the basic infrastructure for tracing. Further tracepoints and examples can be added in later PRs.

ok I'll push just those for now

[jb55]

Given that eBPF is used for complex packet fltering and pre-processing setups I'm a bit surprised the binary handling capabilities are still a weak point

This was really a comment on the bpftrace tool, not the capabilities of ebpf itself. You can always write a C/BCC file and load the low level probes that way, but I'm lazy and haven't tried that yet.

[RandyMcMillan]

I remember when you posted about this on Twitter.
Exciting...
Concept ACK

[laanwj]

You can always write a C/BCC file and load the low level probes that way, but I'm lazy and haven't tried that yet.

Yes, that would be interesting. But yes, we can experiment with that later, bpftrace is the most user friendly way to use this so it's good to document it first.

Tested ACK 22eb793

[0xB10C]

Tested ACK 22eb793

Played around with the IBD example and added a TRACE1(validation, mempool_added, fee) to MemPoolAccept::AcceptSingleTransaction to log the fee of incoming transactions via bpftrace. I agree with the earlier discussion on enabling it by default if prerequisites are installed.

I did try to extend the IBD example to log the hash of the connected block, but haven't had any luck getting this to work with bpftrace yet. Might try with bcc later.

[jb55]

0xB10C <notifications@github.com> writes:

I did try to extend the IBD example to log the hash of the connected block, but haven't had any luck getting this to work with bpftrace yet. Might try with `bcc` later.

I had the same experience. perhaps it will be easier once bpftrace has better tooling and more control around printing arbitrary data. This feature was only added recently: bpftrace/bpftrace#1107

[0xB10C]

Example bcc python script for block-connected printing the block height and hash via USDT probes:

click me for code.py and output.txt

from __future__ import print_function
from bcc import BPF, USDT
import sys
from datetime import datetime

if len(sys.argv) < 2:
    print("USAGE:", sys.argv[0], "path/to/bitcoind")
    exit()
path = sys.argv[1]
debug = False

bpf_text = """
#include <uapi/linux/ptrace.h>
struct connect_block_t
{
    u32 height;
    u8 hash[32];
};
BPF_PERF_OUTPUT(connected_blocks);
int do_trace(struct pt_regs *ctx) {
    struct connect_block_t cb = {};
    bpf_usdt_readarg(1, ctx, &cb.height);
    bpf_usdt_readarg_p(2, ctx, &cb.hash, sizeof(cb.hash));
    connected_blocks.perf_submit(ctx, &cb, sizeof(cb));
    return 0;
};
"""

u = USDT(path=str(path))
u.enable_probe(probe="connect_block", fn_name="do_trace")

if debug:
    print(u.get_text())

b = BPF(text=bpf_text, usdt_contexts=[u])

def print_connected_blocks(cpu, data, size):
    event = b["connected_blocks"].event(data)
    height = event.height
    hash_bytes = bytearray(event.hash)
    hash_bytes.reverse()
    hash = hash_bytes.hex()
    print(datetime.now(), "height:", height, "hash:", hash)

b["connected_blocks"].open_perf_buffer(print_connected_blocks)

while 1:
    try:
        b.perf_buffer_poll()
    except KeyboardInterrupt:
        exit()

Output on testnet:

2020-12-31 12:05:40.634456 height: 1901575 hash: 0000000000000012e5bad3eb72856bc8cee92b4da47c7d0ee49db1463345a1f8
2020-12-31 12:10:11.215210 height: 1901576 hash: 00000000000000107e1cef35dc0557a49f5642b0b9b289ebc1cee454797ed1c3
2020-12-31 12:14:00.349253 height: 1901577 hash: 0000000000000004c7abf45ba560c28e7bfa39c19e28284f8a640e33ee4069d1
2020-12-31 12:17:02.398484 height: 1901578 hash: 00000000000000027b2f88e8cc4e4b0f8a7ad9d0142f282d272827201875e7c4
2020-12-31 12:17:17.796756 height: 1901579 hash: 000000000000001a64e5d01f08c3183165fa2d8225d881081c4b80bb1ffba5b8
2020-12-31 12:18:40.852506 height: 1901580 hash: 0000000000000010da1398d31de9d46eac62caf2a2c4ae1f7b91041ba612a0ae

or gist