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

1. 
   jb55 commented at 1:30 am on December 18, 2021: member

   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

2. 
   jb55 commented at 1:35 am on December 18, 2021: member

   ~Looks like I need to still need to~:

   • update the outbound_message tracepoint
   • update docs
3. jb55 renamed this:
   tracing: reduce instructions generated by net:inbound_message tracepoint
   tracing: reduce instructions generated by net:message tracepoints
   on Dec 18, 2021
4. jb55 force-pushed on Dec 18, 2021
5. jb55 force-pushed on Dec 18, 2021
6. tracing: trace the peer ConnectionType enum directly

   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] https://github.com/bitcoin/bitcoin/pull/23724#issuecomment-996919963
   [2] https://github.com/bitcoin/bitcoin/pull/23724

   08efc0da99
7. jb55 force-pushed on Dec 18, 2021
8. 
   fanquake commented at 2:53 am on December 18, 2021: member

   cc @laanwj @0xB10C
9. DrahtBot added the label P2P on Dec 18, 2021
10. DrahtBot added the label Scripts and tools on Dec 18, 2021
11. 
    0xB10C commented at 1:24 pm on December 18, 2021: member

    Concept and tested ACK (modulo :x:). 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: :heavy_check_mark:
    • checked that the order of connection_types in contrib/tracing/net_common.py matches [0]: :heavy_check_mark:
    • checked that the order of connection_types in the tracepoint documentation doc/tracing.md matches [0]: :heavy_check_mark:
    • tested contrib/tracing/log_raw_p2p_msgs.py: :heavy_check_mark:
    • tested contrib/tracing/p2p_monitor.py: :heavy_check_mark:
    • tested contrib/tracing/log_p2p_traffic.bt: :x:
      • tries to read argument 2 as string $peer_type = str(arg2); (two occurrences)
      • see [1] for a inelegant patch that solves this

    [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..

     0diff --git a/contrib/tracing/log_p2p_traffic.bt b/contrib/tracing/log_p2p_traffic.bt
     1index f62956aa5..f038ae1b2 100755
     2--- a/contrib/tracing/log_p2p_traffic.bt
     3+++ b/contrib/tracing/log_p2p_traffic.bt
     4@@ -9,20 +9,51 @@ usdt:./src/bitcoind:net:inbound_message
     5 {
     6   $peer_id = (int64) arg0;
     7   $peer_addr = str(arg1);
     8-  $peer_type = str(arg2);
     9+  $peer_type = (int32) arg2;
    10   $msg_type = str(arg3);
    11   $msg_len = arg4;
    12-  printf("inbound '%s' msg from peer %d (%s, %s) with %d bytes\n", $msg_type, $peer_id, $peer_type, $peer_addr, $msg_len);
    13+
    14+  $peer_type_str = "unknown";
    15+  if ($peer_type == 0) {
    16+    $peer_type_str = "inbound";
    17+  } else if ($peer_type == 1) {
    18+    $peer_type_str = "outbound-full-relay";
    19+  } else if ($peer_type == 2) {
    20+    $peer_type_str = "manual";
    21+  } else if ($peer_type == 3) {
    22+    $peer_type_str = "feeler";
    23+  } else if ($peer_type == 4) {
    24+    $peer_type_str = "block-relay";
    25+  } else if ($peer_type == 5) {
    26+    $peer_type_str = "addr-fetch";
    27+  }
    28+
    29+  printf("inbound '%s' msg from peer %d (%s, %s) with %d bytes\n", $msg_type, $peer_id, $peer_type_str, $peer_addr, $msg_len);
    30 }
    31
    32 usdt:./src/bitcoind:net:outbound_message
    33 {
    34   $peer_id = (int64) arg0;
    35   $peer_addr = str(arg1);
    36-  $peer_type = str(arg2);
    37+  $peer_type = (int32) arg2;
    38   $msg_type = str(arg3);
    39   $msg_len = arg4;
    40
    41-  printf("outbound '%s' msg to peer %d (%s, %s) with %d bytes\n", $msg_type, $peer_id, $peer_type, $peer_addr, $msg_len);
    42+  $peer_type_str = "unknown";
    43+  if ($peer_type == 0) {
    44+    $peer_type_str = "inbound";
    45+  } else if ($peer_type == 1) {
    46+    $peer_type_str = "outbound-full-relay";
    47+  } else if ($peer_type == 2) {
    48+    $peer_type_str = "manual";
    49+  } else if ($peer_type == 3) {
    50+    $peer_type_str = "feeler";
    51+  } else if ($peer_type == 4) {
    52+    $peer_type_str = "block-relay";
    53+  } else if ($peer_type == 5) {
    54+    $peer_type_str = "addr-fetch";
    55+  }
    56+
    57+  printf("outbound '%s' msg to peer %d (%s, %s) with %d bytes\n", $msg_type, $peer_id, $peer_type_str, $peer_addr, $msg_len);
    58 }
    

12. 
    0xB10C commented at 2:32 pm on December 18, 2021: member

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

    https://github.com/bitcoin/bitcoin/blob/ca7a12479a9aae6ff20de355cc28dcd2f71a74cb/doc/tracing.md?plain=1#L193

13. 
    jb55 commented at 6:58 pm on December 18, 2021: member

    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

14. 
    jb55 commented at 7:10 pm on December 18, 2021: member

    [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.

15. 
    jb55 commented at 8:22 pm on December 18, 2021: member

    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:

     0diff --git a/contrib/tracing/log_p2p_traffic.bt b/contrib/tracing/log_p2p_traffic.bt
     1index f62956aa5e..9ed8a6aa10 100755
     2--- a/contrib/tracing/log_p2p_traffic.bt
     3+++ b/contrib/tracing/log_p2p_traffic.bt
     4@@ -1,15 +1,25 @@
     5 #!/usr/bin/env bpftrace
     6 
     7+#define CONNTYPE(ct) \
     8+  (ct == 0 ? "inbound":\
     9+  (ct == 1 ? "outbound-full-relay":\
    10+  (ct == 2 ? "manual":\
    11+  (ct == 3 ? "feeler":\
    12+  (ct == 4 ? "block-relay":\
    13+  (ct == 5 ? "addr-fetch":\
    14+   "unknown"\
    15+  ))))))
    16+
    17 BEGIN
    18 {
    19-  printf("Logging P2P traffic\n")
    20+  printf("Logging P2P traffic\n");
    21 }
    22 
    23 usdt:./src/bitcoind:net:inbound_message
    24 {
    25   $peer_id = (int64) arg0;
    26   $peer_addr = str(arg1);
    27-  $peer_type = str(arg2);
    28+  $peer_type = CONNTYPE(arg2);
    29   $msg_type = str(arg3);
    30   $msg_len = arg4;
    31   printf("inbound '%s' msg from peer %d (%s, %s) with %d bytes\n", $msg_type, $peer_id, $peer_type, $peer_addr, $msg_len);
    32@@ -19,7 +29,7 @@ usdt:./src/bitcoind:net:outbound_message
    33 {
    34   $peer_id = (int64) arg0;
    35   $peer_addr = str(arg1);
    36-  $peer_type = str(arg2);
    37+  $peer_type = CONNTYPE(arg2);
    38   $msg_type = str(arg3);
    39   $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.

16. tracing: update docs to reflect ConnectionType change 99dddf5ad0
17. tracing: update log_p2p_traffic.bt bpftrace script

    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>

    e049b7dae5
18. jb55 force-pushed on Dec 18, 2021
19. 
    jb55 commented at 8:50 pm on December 18, 2021: member

    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

20. 
    jb55 commented at 5:20 pm on January 4, 2022: member

    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.
21. jb55 closed this on Jan 4, 2022

    ---

22. DrahtBot locked this on Jan 4, 2023

Contributors
jb55 fanquake 0xB10C

Labels
P2P Scripts and tools