tracing: reduce instructions generated by net:message tracepoints #23809

jb55 · 2021-12-18T01:30:23Z

In the net:{inbound,outbound}_message tracepoint, we are calling the
ConnectionTypeAsString helper function that converts the enum to a
string. This has been shown to generate quite a few instructions, even
when there is no code hooked into the tracepoint.

Here's the output from gdb when tracing the number of instructions
between two breakpoints around this tracepoint (see [1] for how to do
this):

Recorded 293 instructions in 27 functions

Tracepoints should be almost zero cost, 293 instructions is a bit much
for effectively doing nothing most of the time.

Instead of calling the ConnectionTypeAsString function, simply add a
ConnectionType getter that returns the connection type enum directly.
This way the tracepoint simplifies to nine instructions that load values
into registers in preparation for a tracepoint call, which may or may
not be there depending on if there are any attached ebpf programs.

With this patch applied:

Recorded 9 instructions in 1 functions

This tightens up these tracepoints in preparation for enabling tracing
in release builds[2].

Signed-off-by: William Casarin jb55@jb55.com

[1] #23724 (comment)
[2] #23724

jb55 · 2021-12-18T01:35:55Z

~~Looks like I need to still need to~~:

update the outbound_message tracepoint
update docs

In the net:{inbound,outbound}_message tracepoint, we are calling the ConnectionTypeAsString helper function that converts the enum to a string. This has been shown to generate quite a few instructions, even when there is no code hooked into the tracepoint. Here's the output from gdb when tracing the number of instructions between two breakpoints around this tracepoint (see [1] for how to do this): Recorded 293 instructions in 27 functions Tracepoints should be almost zero cost, 293 instructions is a bit much for effectively doing nothing most of the time. Instead of calling the ConnectionTypeAsString function, simply add a ConnectionType getter that returns the connection type enum directly. This way the tracepoint simplifies to nine instructions that load values into registers in preparation for a tracepoint call, which may or may not be there depending on if there are any attached ebpf programs. With this patch applied: Recorded 9 instructions in 1 functions This tightens up these tracepoints in preparation for enabling tracing in release builds[2]. Signed-off-by: William Casarin <jb55@jb55.com> [1] bitcoin#23724 (comment) [2] bitcoin#23724

fanquake · 2021-12-18T02:53:16Z

cc @laanwj @0xB10C

0xB10C · 2021-12-18T13:24:46Z

Concept and tested ACK (modulo ❌). This is a important step for #23724.

One possible problem I see with this is that some tracing script will get confused when we remove and then add a new connection type: e.g. the enum with the value 5 has a new meaning. Tracepoint documentation would be outdated too.

checked (with gdb) that the net:{in,out}bound_message tracepoints now execute only a few instructions: ✔️
checked that the order of connection_types in contrib/tracing/net_common.py matches [0]: ✔️
checked that the order of connection_types in the tracepoint documentation doc/tracing.md matches [0]: ✔️
tested contrib/tracing/log_raw_p2p_msgs.py: ✔️
tested contrib/tracing/p2p_monitor.py: ✔️
tested contrib/tracing/log_p2p_traffic.bt: ❌
- tries to read argument 2 as string $peer_type = str(arg2); (two occurrences)
- see [1] for a inelegant patch that solves this

[0]

bitcoin/src/net.h

Line 120 in 98a2ddc

enum class ConnectionType {

[1] I didn't find any other way of doing this in bpftrace. Would be nice if the if-else could at least be extracted into a function..

diff --git a/contrib/tracing/log_p2p_traffic.bt b/contrib/tracing/log_p2p_traffic.bt
index f62956aa5..f038ae1b2 100755
--- a/contrib/tracing/log_p2p_traffic.bt
+++ b/contrib/tracing/log_p2p_traffic.bt
@@ -9,20 +9,51 @@ usdt:./src/bitcoind:net:inbound_message
 {
   $peer_id = (int64) arg0;
   $peer_addr = str(arg1);
-  $peer_type = str(arg2);
+  $peer_type = (int32) arg2;
   $msg_type = str(arg3);
   $msg_len = arg4;
-  printf("inbound '%s' msg from peer %d (%s, %s) with %d bytes\n", $msg_type, $peer_id, $peer_type, $peer_addr, $msg_len);
+
+  $peer_type_str = "unknown";
+  if ($peer_type == 0) {
+    $peer_type_str = "inbound";
+  } else if ($peer_type == 1) {
+    $peer_type_str = "outbound-full-relay";
+  } else if ($peer_type == 2) {
+    $peer_type_str = "manual";
+  } else if ($peer_type == 3) {
+    $peer_type_str = "feeler";
+  } else if ($peer_type == 4) {
+    $peer_type_str = "block-relay";
+  } else if ($peer_type == 5) {
+    $peer_type_str = "addr-fetch";
+  }
+
+  printf("inbound '%s' msg from peer %d (%s, %s) with %d bytes\n", $msg_type, $peer_id, $peer_type_str, $peer_addr, $msg_len);
 }

 usdt:./src/bitcoind:net:outbound_message
 {
   $peer_id = (int64) arg0;
   $peer_addr = str(arg1);
-  $peer_type = str(arg2);
+  $peer_type = (int32) arg2;
   $msg_type = str(arg3);
   $msg_len = arg4;

-  printf("outbound '%s' msg to peer %d (%s, %s) with %d bytes\n", $msg_type, $peer_id, $peer_type, $peer_addr, $msg_len);
+  $peer_type_str = "unknown";
+  if ($peer_type == 0) {
+    $peer_type_str = "inbound";
+  } else if ($peer_type == 1) {
+    $peer_type_str = "outbound-full-relay";
+  } else if ($peer_type == 2) {
+    $peer_type_str = "manual";
+  } else if ($peer_type == 3) {
+    $peer_type_str = "feeler";
+  } else if ($peer_type == 4) {
+    $peer_type_str = "block-relay";
+  } else if ($peer_type == 5) {
+    $peer_type_str = "addr-fetch";
+  }
+
+  printf("outbound '%s' msg to peer %d (%s, %s) with %d bytes\n", $msg_type, $peer_id, $peer_type_str, $peer_addr, $msg_len);
 }

0xB10C · 2021-12-18T14:32:10Z

Should probably also change the example tracepoint in doc/tracing.md

bitcoin/doc/tracing.md

Line 193 in ca7a124

pnode->ConnectionTypeAsString().c_str(),

jb55 · 2021-12-18T18:58:48Z

On Sat, Dec 18, 2021 at 06:32:22AM -0800, 0xB10C wrote: Should probably also change the example tracepoint in `doc/tracing.md` https://github.com/bitcoin/bitcoin/blob/ca7a12479a9aae6ff20de355cc28dcd2f71a74cb/doc/tracing.md?plain=1#L193

good catch

jb55 · 2021-12-18T19:10:06Z

[0] https://github.com/bitcoin/bitcoin/blob/98a2ddcd6ed01a38cd0dad7c1abc7023a60d3fd0/src/net.h#L120 [1] I didn't find any other way of doing this in bpftrace. Would be nice if the if-else could at least be extracted into a function..

oops missed this one. perhaps we can just use a map here. will update.

jb55 · 2021-12-18T20:22:19Z

bpftrace doesn't support functions, best I could do was with a pre-processor macro but that seems like a somewhat horrible solution which now would require a build step:

diff --git a/contrib/tracing/log_p2p_traffic.bt b/contrib/tracing/log_p2p_traffic.bt
index f62956aa5e..9ed8a6aa10 100755
--- a/contrib/tracing/log_p2p_traffic.bt
+++ b/contrib/tracing/log_p2p_traffic.bt
@@ -1,15 +1,25 @@
 #!/usr/bin/env bpftrace
 
+#define CONNTYPE(ct) \
+  (ct == 0 ? "inbound":\
+  (ct == 1 ? "outbound-full-relay":\
+  (ct == 2 ? "manual":\
+  (ct == 3 ? "feeler":\
+  (ct == 4 ? "block-relay":\
+  (ct == 5 ? "addr-fetch":\
+   "unknown"\
+  ))))))
+
 BEGIN
 {
-  printf("Logging P2P traffic\n")
+  printf("Logging P2P traffic\n");
 }
 
 usdt:./src/bitcoind:net:inbound_message
 {
   $peer_id = (int64) arg0;
   $peer_addr = str(arg1);
-  $peer_type = str(arg2);
+  $peer_type = CONNTYPE(arg2);
   $msg_type = str(arg3);
   $msg_len = arg4;
   printf("inbound '%s' msg from peer %d (%s, %s) with %d bytes\n", $msg_type, $peer_id, $peer_type, $peer_addr, $msg_len);
@@ -19,7 +29,7 @@ usdt:./src/bitcoind:net:outbound_message
 {
   $peer_id = (int64) arg0;
   $peer_addr = str(arg1);
-  $peer_type = str(arg2);
+  $peer_type = CONNTYPE(arg2);
   $msg_type = str(arg3);
   $msg_len = arg4;

I tried with a bpf map but it was complaining about how the 64-byte(?) strings in the map were taking up too much stack size... I was able to reduce the stack size with BPFTRACE_STRLEN=32 but that conflicts with the docs for this file, since we might need it for some peer_addr logs?

Honestly bpftrace is looking like a poor tool for this particular job.

bpftrace doesn't have any functions as of writing this commit, so we have to do a ternary lookup hack that introduces a bit of code duplication. Alternatively you could try to use a bpf map, but this uses a lot of stack space in bpftrace which makes it harder to run this script effectively. Signed-off-by: William Casarin <jb55@jb55.com>

jb55 · 2021-12-18T20:50:00Z

see [1] for a inelegant patch that solves this

I counter your inelegant patch with my own, less readable version. with no support for basic abstractions, we might just need to hack it for now, and perhaps wait for bpftrace updates before we can clean this up. I really don't feel like adding a cpp build step for this simple example.

I updated docs + pushed this patch: git range-diff ca7a12479a...e049b7dae5

jb55 · 2022-01-04T17:20:32Z

doing some back of the envelope calculations, the amount of instructions this saves wouldn't even be noticable across the entire duration of IBD. going to just drop it to save review time.

jb55 changed the title ~~tracing: reduce instructions generated by net:inbound_message tracepoint~~ tracing: reduce instructions generated by net:message tracepoints Dec 18, 2021

jb55 force-pushed the conntype-enum-usdt branch 2 times, most recently from b559e63 to 50a6826 Compare December 18, 2021 02:08

jb55 mentioned this pull request Dec 18, 2021

build: add systemtap's sys/sdt.h as depends for GUIX builds with USDT tracepoints #23724

Merged

jb55 force-pushed the conntype-enum-usdt branch from 50a6826 to ca7a124 Compare December 18, 2021 02:13

DrahtBot added P2P Scripts and tools labels Dec 18, 2021

jb55 added 2 commits December 18, 2021 12:41

tracing: update docs to reflect ConnectionType change

99dddf5

jb55 force-pushed the conntype-enum-usdt branch from ca7a124 to e049b7d Compare December 18, 2021 20:43

jb55 closed this Jan 4, 2022

bitcoin locked and limited conversation to collaborators Jan 4, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tracing: reduce instructions generated by net:message tracepoints #23809

tracing: reduce instructions generated by net:message tracepoints #23809

jb55 commented Dec 18, 2021 •

edited

jb55 commented Dec 18, 2021 •

edited

fanquake commented Dec 18, 2021

0xB10C commented Dec 18, 2021

0xB10C commented Dec 18, 2021

jb55 commented Dec 18, 2021 via email

jb55 commented Dec 18, 2021 via email

jb55 commented Dec 18, 2021

jb55 commented Dec 18, 2021

jb55 commented Jan 4, 2022

tracing: reduce instructions generated by net:message tracepoints #23809

tracing: reduce instructions generated by net:message tracepoints #23809

Conversation

jb55 commented Dec 18, 2021 • edited

jb55 commented Dec 18, 2021 • edited

fanquake commented Dec 18, 2021

0xB10C commented Dec 18, 2021

0xB10C commented Dec 18, 2021

jb55 commented Dec 18, 2021 via email

jb55 commented Dec 18, 2021 via email

jb55 commented Dec 18, 2021

jb55 commented Dec 18, 2021

jb55 commented Jan 4, 2022

jb55 commented Dec 18, 2021 •

edited

jb55 commented Dec 18, 2021 •

edited