README.md
1 Example scripts for User-space, Statically Defined Tracing (USDT) 2 ================================================================= 3 4 This directory contains scripts showcasing User-space, Statically Defined 5 Tracing (USDT) support for Bitcoin Core on Linux using. For more information on 6 USDT support in Bitcoin Core see the [USDT documentation]. 7 8 [USDT documentation]: ../../doc/tracing.md 9 10 11 Examples for the two main eBPF front-ends, [bpftrace] and 12 [BPF Compiler Collection (BCC)], with support for USDT, are listed. BCC is used 13 for complex tools and daemons and `bpftrace` is preferred for one-liners and 14 shorter scripts. 15 16 [bpftrace]: https://github.com/iovisor/bpftrace 17 [BPF Compiler Collection (BCC)]: https://github.com/iovisor/bcc 18 19 20 To develop and run bpftrace and BCC scripts you need to install the 21 corresponding packages. See [installing bpftrace] and [installing BCC] for more 22 information. For development there exist a [bpftrace Reference Guide], a 23 [BCC Reference Guide], and a [bcc Python Developer Tutorial]. 24 25 [installing bpftrace]: https://github.com/bpftrace/bpftrace/blob/master/README.md#quick-start 26 [installing BCC]: https://github.com/iovisor/bcc/blob/master/INSTALL.md 27 [bpftrace Reference Guide]: https://github.com/iovisor/bpftrace/blob/master/docs/reference_guide.md 28 [BCC Reference Guide]: https://github.com/iovisor/bcc/blob/master/docs/reference_guide.md 29 [bcc Python Developer Tutorial]: https://github.com/iovisor/bcc/blob/master/docs/tutorial_bcc_python_developer.md 30 31 ## Examples 32 33 The bpftrace examples contain a relative path to the `bitcoind` binary. By 34 default, the scripts should be run from the repository-root and assume a 35 self-compiled `bitcoind` binary. The paths in the examples can be changed, for 36 example, to point to release builds if needed. See the 37 [Bitcoin Core USDT documentation] on how to list available tracepoints in your 38 `bitcoind` binary. 39 40 [Bitcoin Core USDT documentation]: ../../doc/tracing.md#listing-available-tracepoints 41 42 **WARNING: eBPF programs require root privileges to be loaded into a Linux 43 kernel VM. This means the bpftrace and BCC examples must be executed with root 44 privileges. Make sure to carefully review any scripts that you run with root 45 privileges first!** 46 47 ### log_p2p_traffic.bt 48 49 A bpftrace script logging information about inbound and outbound P2P network 50 messages. Based on the `net:inbound_message` and `net:outbound_message` 51 tracepoints. 52 53 By default, `bpftrace` limits strings to 64 bytes due to the limited stack size 54 in the eBPF VM. For example, Tor v3 addresses exceed the string size limit which 55 results in the port being cut off during logging. The string size limit can be 56 increased with the `BPFTRACE_STRLEN` environment variable (`BPFTRACE_STRLEN=70` 57 works fine). 58 59 ``` 60 $ bpftrace contrib/tracing/log_p2p_traffic.bt 61 ``` 62 63 Output 64 ``` 65 outbound 'ping' msg to peer 11 (outbound-full-relay, [2a02:b10c:f747:1:ef:fake:ipv6:addr]:8333) with 8 bytes 66 inbound 'pong' msg from peer 11 (outbound-full-relay, [2a02:b10c:f747:1:ef:fake:ipv6:addr]:8333) with 8 bytes 67 inbound 'inv' msg from peer 16 (outbound-full-relay, XX.XX.XXX.121:8333) with 37 bytes 68 outbound 'getdata' msg to peer 16 (outbound-full-relay, XX.XX.XXX.121:8333) with 37 bytes 69 inbound 'tx' msg from peer 16 (outbound-full-relay, XX.XX.XXX.121:8333) with 222 bytes 70 outbound 'inv' msg to peer 9 (outbound-full-relay, faketorv3addressa2ufa6odvoi3s77j4uegey0xb10csyfyve2t33curbyd.onion:8333) with 37 bytes 71 outbound 'inv' msg to peer 7 (outbound-full-relay, XX.XX.XXX.242:8333) with 37 bytes 72 … 73 ``` 74 75 ### p2p_monitor.py 76 77 A BCC Python script using curses for an interactive P2P message monitor. Based 78 on the `net:inbound_message` and `net:outbound_message` tracepoints. 79 80 Inbound and outbound traffic is listed for each peer together with information 81 about the connection. Peers can be selected individually to view recent P2P 82 messages. 83 84 ``` 85 $ python3 contrib/tracing/p2p_monitor.py $(pidof bitcoind) 86 ``` 87 88 Lists selectable peers and traffic and connection information. 89 ``` 90 P2P Message Monitor 91 Navigate with UP/DOWN or J/K and select a peer with ENTER or SPACE to see individual P2P messages 92 93 PEER OUTBOUND INBOUND TYPE ADDR 94 0 46 398 byte 61 1407590 byte block-relay-only XX.XX.XXX.196:8333 95 11 1156 253570 byte 3431 2394924 byte outbound-full-relay XXX.X.XX.179:8333 96 13 3425 1809620 byte 1236 305458 byte inbound XXX.X.X.X:60380 97 16 1046 241633 byte 1589 1199220 byte outbound-full-relay 4faketorv2pbfu7x.onion:8333 98 19 577 181679 byte 390 148951 byte outbound-full-relay kfake4vctorjv2o2.onion:8333 99 20 11 1248 byte 13 1283 byte block-relay-only [2600:fake:64d9:b10c:4436:aaaa:fe:bb]:8333 100 21 11 1248 byte 13 1299 byte block-relay-only XX.XXX.X.155:8333 101 22 5 103 byte 1 102 byte feeler XX.XX.XXX.173:8333 102 23 11 1248 byte 12 1255 byte block-relay-only XX.XXX.XXX.220:8333 103 24 3 103 byte 1 102 byte feeler XXX.XXX.XXX.64:8333 104 … 105 ``` 106 107 Showing recent P2P messages between our node and a selected peer. 108 109 ``` 110 ---------------------------------------------------------------------- 111 | PEER 16 (4faketorv2pbfu7x.onion:8333) | 112 | OUR NODE outbound-full-relay PEER | 113 | <--- sendcmpct (9 bytes) | 114 | inv (37 byte) ---> | 115 | <--- ping (8 bytes) | 116 | pong (8 byte) ---> | 117 | inv (37 byte) ---> | 118 | <--- addr (31 bytes) | 119 | inv (37 byte) ---> | 120 | <--- getheaders (1029 bytes) | 121 | headers (1 byte) ---> | 122 | <--- feefilter (8 bytes) | 123 | <--- pong (8 bytes) | 124 | <--- headers (82 bytes) | 125 | <--- addr (30003 bytes) | 126 | inv (1261 byte) ---> | 127 | … | 128 129 ``` 130 131 ### log_raw_p2p_msgs.py 132 133 A BCC Python script showcasing eBPF and USDT limitations when passing data 134 larger than about 32kb. Based on the `net:inbound_message` and 135 `net:outbound_message` tracepoints. 136 137 Bitcoin P2P messages can be larger than 32kb (e.g. `tx`, `block`, ...). The 138 eBPF VM's stack is limited to 512 bytes, and we can't allocate more than about 139 32kb for a P2P message in the eBPF VM. The **message data is cut off** when the 140 message is larger than MAX_MSG_DATA_LENGTH (see script). This can be detected 141 in user-space by comparing the data length to the message length variable. The 142 message is cut off when the data length is smaller than the message length. 143 A warning is included with the printed message data. 144 145 Data is submitted to user-space (i.e. to this script) via a ring buffer. The 146 throughput of the ring buffer is limited. Each p2p_message is about 32kb in 147 size. In- or outbound messages submitted to the ring buffer in rapid 148 succession fill the ring buffer faster than it can be read. Some messages are 149 lost. BCC prints: `Possibly lost 2 samples` on lost messages. 150 151 152 ``` 153 $ python3 contrib/tracing/log_raw_p2p_msgs.py $(pidof bitcoind) 154 ``` 155 156 ``` 157 Logging raw P2P messages. 158 Messages larger than about 32kb will be cut off! 159 Some messages might be lost! 160 outbound msg 'inv' from peer 4 (outbound-full-relay, XX.XXX.XX.4:8333) with 253 bytes: 0705000000be2245c8f844c9f763748e1a7… 161 … 162 Warning: incomplete message (only 32568 out of 53552 bytes)! inbound msg 'tx' from peer 32 (outbound-full-relay, XX.XXX.XXX.43:8333) with 53552 bytes: 020000000001fd3c01939c85ad6756ed9fc… 163 … 164 Possibly lost 2 samples 165 ``` 166 167 ### connectblock_benchmark.bt 168 169 A `bpftrace` script to benchmark the `ConnectBlock()` function during, for 170 example, a blockchain re-index. Based on the `validation:block_connected` USDT 171 tracepoint. 172 173 The script takes three positional arguments. The first two arguments, the start, 174 and end height indicate between which blocks the benchmark should be run. The 175 third acts as a duration threshold in milliseconds. When the `ConnectBlock()` 176 function takes longer than the threshold, information about the block, is 177 printed. For more details, see the header comment in the script. 178 179 The following command can be used to benchmark, for example, `ConnectBlock()` 180 between height 20000 and 38000 on SigNet while logging all blocks that take 181 longer than 25ms to connect. 182 183 ``` 184 $ bpftrace contrib/tracing/connectblock_benchmark.bt 20000 38000 25 185 ``` 186 187 In a different terminal, starting Bitcoin Core in SigNet mode and with 188 re-indexing enabled. 189 190 ``` 191 $ ./build/bin/bitcoind -signet -reindex 192 ``` 193 194 This produces the following output. 195 ``` 196 Attaching 5 probes... 197 ConnectBlock Benchmark between height 20000 and 38000 inclusive 198 Logging blocks taking longer than 25 ms to connect. 199 Starting Connect Block Benchmark between height 20000 and 38000. 200 BENCH 39 blk/s 59 tx/s 59 inputs/s 20 sigops/s (height 20038) 201 Block 20492 (000000f555653bb05e2f3c6e79925e01a20dd57033f4dc7c354b46e34735d32b) 20 tx 2319 ins 2318 sigops took 38 ms 202 BENCH 1840 blk/s 2117 tx/s 4478 inputs/s 2471 sigops/s (height 21879) 203 BENCH 1816 blk/s 4972 tx/s 4982 inputs/s 125 sigops/s (height 23695) 204 BENCH 2095 blk/s 2890 tx/s 2910 inputs/s 152 sigops/s (height 25790) 205 BENCH 1684 blk/s 3979 tx/s 4053 inputs/s 288 sigops/s (height 27474) 206 BENCH 1155 blk/s 3216 tx/s 3252 inputs/s 115 sigops/s (height 28629) 207 BENCH 1797 blk/s 2488 tx/s 2503 inputs/s 111 sigops/s (height 30426) 208 BENCH 1849 blk/s 6318 tx/s 6569 inputs/s 12189 sigops/s (height 32275) 209 BENCH 946 blk/s 20209 tx/s 20775 inputs/s 83809 sigops/s (height 33221) 210 Block 33406 (0000002adfe4a15cfcd53bd890a89bbae836e5bb7f38bac566f61ad4548c87f6) 25 tx 2045 ins 2090 sigops took 29 ms 211 Block 33687 (00000073231307a9828e5607ceb8156b402efe56747271a4442e75eb5b77cd36) 52 tx 1797 ins 1826 sigops took 26 ms 212 BENCH 582 blk/s 21581 tx/s 27673 inputs/s 60345 sigops/s (height 33803) 213 BENCH 1035 blk/s 19735 tx/s 19776 inputs/s 51355 sigops/s (height 34838) 214 Block 35625 (0000006b00b347390c4768ea9df2655e9ff4b120f29d78594a2a702f8a02c997) 20 tx 3374 ins 3371 sigops took 49 ms 215 BENCH 887 blk/s 17857 tx/s 22191 inputs/s 24404 sigops/s (height 35725) 216 Block 35937 (000000d816d13d6e39b471cd4368db60463a764ba1f29168606b04a22b81ea57) 75 tx 3943 ins 3940 sigops took 61 ms 217 BENCH 823 blk/s 16298 tx/s 21031 inputs/s 18440 sigops/s (height 36548) 218 Block 36583 (000000c3e260556dbf42968aae3f904dba8b8c1ff96a6f6e3aa5365d2e3ad317) 24 tx 2198 ins 2194 sigops took 34 ms 219 Block 36700 (000000b3b173de9e65a3cfa738d976af6347aaf83fa17ab3f2a4d2ede3ddfac4) 73 tx 1615 ins 1611 sigops took 31 ms 220 Block 36832 (0000007859578c02c1ac37dabd1b9ec19b98f350b56935f5dd3a41e9f79f836e) 34 tx 1440 ins 1436 sigops took 26 ms 221 BENCH 613 blk/s 16718 tx/s 25074 inputs/s 23022 sigops/s (height 37161) 222 Block 37870 (000000f5c1086291ba2d943fb0c3bc82e71c5ee341ee117681d1456fbf6c6c38) 25 tx 1517 ins 1514 sigops took 29 ms 223 BENCH 811 blk/s 16031 tx/s 20921 inputs/s 18696 sigops/s (height 37972) 224 225 Took 14055 ms to connect the blocks between height 20000 and 38000. 226 227 Histogram of block connection times in milliseconds (ms). 228 @durations: 229 [0] 16838 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| 230 [1] 882 |@@ | 231 [2, 4) 236 | | 232 [4, 8) 23 | | 233 [8, 16) 9 | | 234 [16, 32) 9 | | 235 [32, 64) 4 | | 236 ``` 237 238 ### log_utxocache_flush.py 239 240 A BCC Python script to log the UTXO cache flushes. Based on the 241 `utxocache:flush` tracepoint. 242 243 ```bash 244 $ python3 contrib/tracing/log_utxocache_flush.py $(pidof bitcoind) 245 ``` 246 247 ``` 248 Logging utxocache flushes. Ctrl-C to end... 249 Duration (µs) Mode Coins Count Memory Usage Flush for Prune 250 2556340 IF_NEEDED 2899141 394844.34 kB False 251 2005788 FORCE_FLUSH 2238117 310189.68 kB False 252 2685 FORCE_FLUSH 0 262.24 kB False 253 ``` 254 255 ### log_utxos.bt 256 257 A `bpftrace` script to log information about the coins that are added, spent, or 258 uncached from the UTXO set. Based on the `utxocache:add`, `utxocache:spend` and 259 `utxocache:uncache` tracepoints. 260 261 ```bash 262 $ bpftrace contrib/tracing/log_utxos.bt 263 ``` 264 265 This should produce an output similar to the following. If you see bpftrace 266 warnings like `Lost 24 events`, the eBPF perf ring-buffer is filled faster 267 than it is being read. You can increase the ring-buffer size by setting the 268 ENV variable `BPFTRACE_PERF_RB_PAGES` (default 64) at a cost of higher 269 memory usage. See the [bpftrace reference guide] for more information. 270 271 [bpftrace reference guide]: https://github.com/iovisor/bpftrace/blob/master/docs/reference_guide.md#98-bpftrace_perf_rb_pages 272 273 ```bash 274 Attaching 4 probes... 275 OP Outpoint Value Height Coinbase 276 Added 6ba9ad857e1ef2eb2a2c94f06813c414c7ab273e3d6bd7ad64e000315a887e7c:1 10000 2094512 No 277 Spent fa7dc4db56637a151f6649d8f26732956d1c5424c82aae400a83d02b2cc2c87b:0 182264897 2094512 No 278 Added eeb2f099b1af6a2a12e6ddd2eeb16fc5968582241d7f08ba202d28b60ac264c7:0 10000 2094512 No 279 Added eeb2f099b1af6a2a12e6ddd2eeb16fc5968582241d7f08ba202d28b60ac264c7:1 182254756 2094512 No 280 Added a0c7f4ec9cccef2d89672a624a4e6c8237a17572efdd4679eea9e9ee70d2db04:0 10072679 2094513 Yes 281 Spent 25e0df5cc1aeb1b78e6056bf403e5e8b7e41f138060ca0a50a50134df0549a5e:2 540 2094508 No 282 Spent 42f383c04e09c26a2378272ec33aa0c1bf4883ca5ab739e8b7e06be5a5787d61:1 3848399 2007724 No 283 Added f85e3b4b89270863a389395cc9a4123e417ab19384cef96533c6649abd6b0561:0 3788399 2094513 No 284 Added f85e3b4b89270863a389395cc9a4123e417ab19384cef96533c6649abd6b0561:2 540 2094513 No 285 Spent a05880b8c77971ed0b9f73062c7c4cdb0ff3856ab14cbf8bc481ed571cd34b83:1 5591281046 2094511 No 286 Added eb689865f7d957938978d6207918748f74e6aa074f47874724327089445b0960:0 5589696005 2094513 No 287 Added eb689865f7d957938978d6207918748f74e6aa074f47874724327089445b0960:1 1565556 2094513 No 288 ``` 289 290 ### mempool_monitor.py 291 292 A BCC Python script producing mempool statistics and an event log. Based on the 293 `mempool:added`, `mempool:removed`, `mempool:replaced`, and `mempool:rejected` 294 tracepoints. 295 296 Statistics include incidence and rate for each event type since the script was 297 started (`total`) as well as during the last minute (`1 min`) and ten minutes 298 (`10 min`). The event log shows mempool events in real time, each entry 299 comprising a timestamp along with all event data available via the event's 300 tracepoint. 301 302 ```console 303 $ python3 contrib/tracing/mempool_monitor.py $(pidof bitcoind) 304 ``` 305 306 ``` 307 Mempool Monitor 308 Press CTRL-C to stop. 309 310 ┌─Event count───────────────────────┐ ┌─Event rate──────────────────────────┐ 311 │ Event total 1 min 10 min │ │ Event total 1 min 10 min │ 312 │ added 1425tx 201tx 1425tx │ │ added 4.7tx/s 3.4tx/s 4.7tx/s │ 313 │ removed 35tx 4tx 35tx │ │ removed 0.1tx/s 0.1tx/s 0.1tx/s │ 314 │ replaced 35tx 4tx 35tx │ │ replaced 0.1tx/s 0.1tx/s 0.1tx/s │ 315 │ rejected 0tx 0tx 0tx │ │ rejected 0.0tx/s 0.0tx/s 0.0tx/s │ 316 └───────────────────────────────────┘ └─────────────────────────────────────┘ 317 318 ┌─Event log────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐ 319 │ 13:10:30Z added f9064ca5bfc87cdd191faa42bf697217cd920b2b94838c1f1192e4f06c4fd217 with feerate 8.92 sat/vB (981 sat, 110 vbytes) │ 320 │ 13:10:30Z added 53ffa3afbe57b1bfe423e1755ca2b52c5b6cb4aa91b8b7ee9cb694953f47f234 with feerate 5.00 sat/vB (550 sat, 110 vbytes) │ 321 │ 13:10:30Z added 4177df5e19465eb5e53c3f8b6830a293f57474921bc6c2ae89375e0986e1f0f9 with feerate 2.98 sat/vB (429 sat, 144 vbytes) │ 322 │ 13:10:30Z added 931a10d83f0a268768da75dc4b9e199f2f055f12979ae5491cc304ee10f890ea with feerate 3.55 sat/vB (500 sat, 141 vbytes) │ 323 │ 13:10:30Z added 4cf32b295723cc4ab73f2a2e51d4bb276c0042760a4c00a3eb9595b8ebb24721 with feerate 89.21 sat/vB (12668 sat, 142 vbytes) │ 324 │ 13:10:31Z replaced d1eecf9d662121322f4f31f0c2267a752d14bb3956e6016ba96e87f47890e1db with feerate 27.12 sat/vB received 23.3 seconds ago (7213 sat, 266 vbytes) with c412db908│ 325 │ 9b7ed53f3e5e36d2819dd291278b59ccaabaeb17fd37c3d87fdcd57 with feerate 28.12 sat/vB (8351 sat, 297 vbytes) │ 326 │ 13:10:31Z added c412db9089b7ed53f3e5e36d2819dd291278b59ccaabaeb17fd37c3d87fdcd57 with feerate 28.12 sat/vB (8351 sat, 297 vbytes) │ 327 │ 13:10:31Z added b8388a5bdc421b11460bdf477d5a85a1a39c2784e7dd7bffabe688740424ea57 with feerate 25.21 sat/vB (3554 sat, 141 vbytes) │ 328 │ 13:10:31Z added 4ddb88bc90a122cd9eae8a664e73bdf5bebe75f3ef901241b4a251245854a98e with feerate 24.15 sat/vB (5072 sat, 210 vbytes) │ 329 │ 13:10:31Z added 19101e4161bca5271ad5d03e7747f2faec7793b274dc2f3c4cf516b7cef1aac3 with feerate 7.06 sat/vB (1080 sat, 153 vbytes) │ 330 │ 13:10:31Z removed d1eecf9d662121322f4f31f0c2267a752d14bb3956e6016ba96e87f47890e1db with feerate 27.12 sat/vB (7213 sat, 266 vbytes): replaced │ 331 │ 13:10:31Z added 6c511c60d9b95b9eff81df6ecba5c86780f513fe62ce3ad6be2c5340d957025a with feerate 4.00 sat/vB (440 sat, 110 vbytes) │ 332 │ 13:10:31Z added 44d66f7f004bd52c46be4dff3067cab700e51c7866a84282bd8aab560a5bfb79 with feerate 3.15 sat/vB (448 sat, 142 vbytes) │ 333 │ 13:10:31Z added b17b7c9ec5acfbbf12f0eeef8e29826fad3105bb95eef7a47d2f1f22b4784643 with feerate 4.10 sat/vB (1348 sat, 329 vbytes) │ 334 │ 13:10:31Z added b7a4ad93554e57454e8a8049bfc0bd803fa962bd3f0a08926aa72e7cb23e2276 with feerate 1.01 sat/vB (205 sat, 202 vbytes) │ 335 │ 13:10:32Z added c78e87be86c828137a6e7e00a177c03b52202ce4c39029b99904c2a094b9da87 with feerate 11.00 sat/vB (1562 sat, 142 vbytes) │ 336 │ │ 337 └──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘ 338 339 ### log_p2p_connections.bt 340 341 A `bpftrace` script to log information about opened, closed, misbehaving, and 342 evicted P2P connections. Uses the `net:*_connection` tracepoints. 343 344 ```bash 345 $ bpftrace contrib/tracing/log_p2p_connections.bt 346 ``` 347 348 This should produce an output similar to the following. 349 350 ```bash 351 Attaching 6 probes... 352 Logging opened, closed, misbehaving, and evicted P2P connections 353 OUTBOUND conn to 127.0.0.1:15287: id=0, type=block-relay-only, network=0, total_out=1 354 INBOUND conn from 127.0.0.1:45324: id=1, type=inbound, network=0, total_in=1 355 MISBEHAVING conn id=1, score_before=0, score_increase=20, message='getdata message size = 50001', threshold_exceeded=false 356 CLOSED conn to 127.0.0.1:15287: id=0, type=block-relay-only, network=0, established=1231006505 357 EVICTED conn to 127.0.0.1:45324: id=1, type=inbound, network=0, established=1612312312 358 ... 359 ```