From 411c6cfc6c2e488e407f057b646730e63806ed8a Mon Sep 17 00:00:00 2001 From: 0xb10c Date: Thu, 23 Nov 2023 16:51:36 +0100 Subject: [PATCH] tracing: only prepare tracepoint args if attached Before this commit, we would always prepare tracepoint arguments regardless of the tracepoint being used or not. While we already made sure not to include expensive arguments in our tracepoints, this commit introduces gating to make sure the arguments are only prepared if the tracepoints are actually used. This is a win-win improvement to our tracing framework. For users not interested in tracing, the overhead is reduced to a cheap 'greater than 0' compare. As the semaphore-gating technique used here is available in bpftrace, bcc, and libbpf, users interested in tracing don't have to change their tracing scripts while profiting from potential future tracepoints passing slightly more expensive arguments. An example are mempool tracepoints that pass serialized transactions. We've avoided the serialization in the past as it was too expensive. Under the hood, the semaphore-gating works by placing a 2-byte semaphore in the '.probes' ELF section. The address of the semaphore is contained in the ELF note providing the tracepoint information (`readelf -n ./src/bitcoind | grep NT_STAPSDT`). Tracing toolkits like bpftrace, bcc, and libbpf increase the semaphore at the address upon attaching to the tracepoint. We only prepare the arguments and reach the tracepoint if the semaphore is greater than zero. The semaphore is decreased when detaching from the tracepoint. This also extends the "Adding a new tracepoint" documentation to include information about the semaphores and updated step-by-step instructions on how to add a new tracepoint. --- doc/tracing.md | 66 +++++++++++++++++++++++------------ src/coins.cpp | 4 +++ src/net.cpp | 2 ++ src/net_processing.cpp | 2 ++ src/test/util_trace_tests.cpp | 37 +++++++++++++++++++- src/txmempool.cpp | 3 ++ src/util/trace.h | 34 +++++++++++++++--- src/validation.cpp | 5 +++ src/wallet/spend.cpp | 5 +++ 9 files changed, 130 insertions(+), 28 deletions(-) diff --git a/doc/tracing.md b/doc/tracing.md index ee0d81d7dd479..5b9369f0b91c0 100644 --- a/doc/tracing.md +++ b/doc/tracing.md @@ -270,21 +270,47 @@ Use the `TRACEPOINT` macro to add a new tracepoint. If not yet included, include Each tracepoint needs a `context` and an `event`. Please use `snake_case` and try to make sure that the tracepoint names make sense even without detailed knowledge of the implementation details. You can pass zero to twelve arguments -to the tracepoint. Do not forget to update the tracepoint list in this -document. +to the tracepoint. Each tracepoint also needs a global semaphore. The semaphore +gates the tracepoint arguments from being processed if we are not attached to +the tracepoint. Add a `TRACEPOINT_SEMAPHORE(context, event)` with the `context` +and `event` of your tracepoint in the top-level namespace at the beginning of +the file. Do not forget to update the tracepoint list in this document. -For example, a tracepoint in the `net` context for the event `inbound_message` -and six arguments: +For example, the `net:outbound_message` tracepoint in `src/net.cpp` with six +arguments. ```C++ -TRACEPOINT(net, inbound_message, - pnode->GetId(), - pnode->m_addr_name.c_str(), - pnode->ConnectionTypeAsString().c_str(), - sanitizedType.c_str(), - msg.data.size(), - msg.data.data() -); +// src/net.cpp +TRACEPOINT_SEMAPHORE(net, outbound_message); +… +void CConnman::PushMessage(…) { + … + TRACEPOINT(net, outbound_message, + pnode->GetId(), + pnode->m_addr_name.c_str(), + pnode->ConnectionTypeAsString().c_str(), + sanitizedType.c_str(), + msg.data.size(), + msg.data.data() + ); + … +} +``` +If needed, an extra `if (TRACEPOINT_ACTIVE(context, event)) {...}` check can be +used to prepare somewhat expensive arguments right before the tracepoint. While +the tracepoint arguments are only prepared when we attach something to the +tracepoint, an argument preparation should never hang the process. Hashing and +serialization of data structures is probably fine, a `sleep(10s)` not. + +```C++ +// An example tracepoint with an expensive argument. + +TRACEPOINT_SEMAPHORE(example, gated_expensive_argument); +… +if (TRACEPOINT_ACTIVE(example, gated_expensive_argument)) { + expensive_argument = expensive_calulation(); + TRACEPOINT(example, gated_expensive_argument, expensive_argument); +} ``` ### Guidelines and best practices @@ -302,12 +328,6 @@ the tracepoint. See existing examples in [contrib/tracing/]. [contrib/tracing/]: ../contrib/tracing/ -#### No expensive computations for tracepoints -Data passed to the tracepoint should be inexpensive to compute. Although the -tracepoint itself only has overhead when enabled, the code to compute arguments -is always run - even if the tracepoint is not used. For example, avoid -serialization and parsing. - #### Semi-stable API Tracepoints should have a semi-stable API. Users should be able to rely on the tracepoints for scripting. This means tracepoints need to be documented, and the @@ -354,9 +374,9 @@ $ gdb ./build/src/bitcoind … (gdb) info probes Type Provider Name Where Semaphore Object -stap net inbound_message 0x000000000014419e /build/src/bitcoind -stap net outbound_message 0x0000000000107c05 /build/src/bitcoind -stap validation block_connected 0x00000000002fb10c /build/src/bitcoind +stap net inbound_message 0x000000000014419e 0x0000000000d29bd2 /build/src/bitcoind +stap net outbound_message 0x0000000000107c05 0x0000000000d29bd0 /build/src/bitcoind +stap validation block_connected 0x00000000002fb10c 0x0000000000d29bd8 /build/src/bitcoind … ``` @@ -372,7 +392,7 @@ Displaying notes found in: .note.stapsdt stapsdt 0x0000005d NT_STAPSDT (SystemTap probe descriptors) Provider: net Name: outbound_message - Location: 0x0000000000107c05, Base: 0x0000000000579c90, Semaphore: 0x0000000000000000 + Location: 0x0000000000107c05, Base: 0x0000000000579c90, Semaphore: 0x0000000000d29bd0 Arguments: -8@%r12 8@%rbx 8@%rdi 8@192(%rsp) 8@%rax 8@%rdx … ``` @@ -391,7 +411,7 @@ between distributions. For example, on ``` $ tplist -l ./build/src/bitcoind -v -b'net':b'outbound_message' [sema 0x0] +b'net':b'outbound_message' [sema 0xd29bd0] 1 location(s) 6 argument(s) … diff --git a/src/coins.cpp b/src/coins.cpp index 4fcb48ebb1206..75d11b4f267b1 100644 --- a/src/coins.cpp +++ b/src/coins.cpp @@ -9,6 +9,10 @@ #include #include +TRACEPOINT_SEMAPHORE(utxocache, add); +TRACEPOINT_SEMAPHORE(utxocache, spent); +TRACEPOINT_SEMAPHORE(utxocache, uncache); + std::optional CCoinsView::GetCoin(const COutPoint& outpoint) const { return std::nullopt; } uint256 CCoinsView::GetBestBlock() const { return uint256(); } std::vector CCoinsView::GetHeadBlocks() const { return std::vector(); } diff --git a/src/net.cpp b/src/net.cpp index 15cf1fe80ce1a..0a643c48c599c 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -53,6 +53,8 @@ #include #include +TRACEPOINT_SEMAPHORE(net, outbound_message); + /** Maximum number of block-relay-only anchor connections */ static constexpr size_t MAX_BLOCK_RELAY_ONLY_ANCHORS = 2; static_assert (MAX_BLOCK_RELAY_ONLY_ANCHORS <= static_cast(MAX_BLOCK_RELAY_ONLY_CONNECTIONS), "MAX_BLOCK_RELAY_ONLY_ANCHORS must not exceed MAX_BLOCK_RELAY_ONLY_CONNECTIONS."); diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 8777af3657b9d..2d78a4c96a630 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -56,6 +56,8 @@ using namespace util::hex_literals; +TRACEPOINT_SEMAPHORE(net, inbound_message); + /** Headers download timeout. * Timeout = base + per_header * (expected number of headers) */ static constexpr auto HEADERS_DOWNLOAD_TIMEOUT_BASE = 15min; diff --git a/src/test/util_trace_tests.cpp b/src/test/util_trace_tests.cpp index 8d7eb9ae2e856..06fbcf3b15b7f 100644 --- a/src/test/util_trace_tests.cpp +++ b/src/test/util_trace_tests.cpp @@ -8,6 +8,13 @@ #include +TRACEPOINT_SEMAPHORE(test, zero_args); +TRACEPOINT_SEMAPHORE(test, one_arg); +TRACEPOINT_SEMAPHORE(test, six_args); +TRACEPOINT_SEMAPHORE(test, twelve_args); +TRACEPOINT_SEMAPHORE(test, check_if_attached); +TRACEPOINT_SEMAPHORE(test, expensive_section); + BOOST_FIXTURE_TEST_SUITE(util_trace_tests, BasicTestingSetup) // Tests the TRACEPOINT macro and that we can compile tracepoints with 0 to 12 args. @@ -20,4 +27,32 @@ BOOST_AUTO_TEST_CASE(test_tracepoints) BOOST_CHECK(true); } -BOOST_AUTO_TEST_SUITE_END() \ No newline at end of file +int fail_test_if_executed() +{ + BOOST_CHECK(false); + return 0; +} + +BOOST_AUTO_TEST_CASE(test_tracepoint_check_if_attached) +{ + // TRACEPOINT should check if we are attaching to the tracepoint and only then + // process arguments. This means, only if we are attached to the + // `test:check_if_attached` tracepoint, fail_test_if_executed() is executed. + // Since we don't attach to the tracepoint when running the test, it succeeds. + TRACEPOINT(test, check_if_attached, fail_test_if_executed()); + BOOST_CHECK(true); +} + +BOOST_AUTO_TEST_CASE(test_tracepoint_manual_tracepoint_active_check) +{ + // We should be able to use the TRACEPOINT_ACTIVE() macro to only + // execute an 'expensive' code section if we are attached to the + // tracepoint. + if (TRACEPOINT_ACTIVE(test, expensive_section)) { + BOOST_CHECK(false); // expensive_function() + TRACEPOINT(test, expensive_section); + } + BOOST_CHECK(true); +} + +BOOST_AUTO_TEST_SUITE_END() diff --git a/src/txmempool.cpp b/src/txmempool.cpp index 847c62c980b73..8b6f993843124 100644 --- a/src/txmempool.cpp +++ b/src/txmempool.cpp @@ -34,6 +34,9 @@ #include #include +TRACEPOINT_SEMAPHORE(mempool, added); +TRACEPOINT_SEMAPHORE(mempool, removed); + bool TestLockPointValidity(CChain& active_chain, const LockPoints& lp) { AssertLockHeld(cs_main); diff --git a/src/util/trace.h b/src/util/trace.h index 8165d602726fc..3deefeade370d 100644 --- a/src/util/trace.h +++ b/src/util/trace.h @@ -13,16 +13,42 @@ // the optional variadic macros to define tracepoints. #define SDT_USE_VARIADIC 1 +// Setting _SDT_HAS_SEMAPHORES let's systemtap (sys/sdt.h) know that we want to +// use the optional semaphore feature for our tracepoints. This feature allows +// us to check if something is attached to a tracepoint. We only want to prepare +// some potentially expensive tracepoint arguments, if the tracepoint is being +// used. Here, an expensive argument preparation could, for example, be +// calculating a hash or serialization of a data structure. +#define _SDT_HAS_SEMAPHORES 1 + +// Used to define a counting semaphore for a tracepoint. This semaphore is +// automatically incremented by tracing frameworks (bpftrace, bcc, libbpf, ...) +// upon attaching to the tracepoint and decremented when detaching. This needs +// to be a global variable. It's placed in the '.probes' ELF section. +#define TRACEPOINT_SEMAPHORE(context, event) \ + unsigned short context##_##event##_semaphore __attribute__((section(".probes"))) + #include -// A USDT tracepoint with zero to twelve arguments. -#define TRACEPOINT(context, ...) \ - STAP_PROBEV(context, __VA_ARGS__); +// Returns true if something is attached to the tracepoint. +#define TRACEPOINT_ACTIVE(context, event) (context##_##event##_semaphore > 0) + +// A USDT tracepoint with one to twelve arguments. It's checked that the +// tracepoint is active before preparing its arguments. +#define TRACEPOINT(context, event, ...) \ + do { \ + if (TRACEPOINT_ACTIVE(context, event)) { \ + STAP_PROBEV(context, event __VA_OPT__(, ) __VA_ARGS__); \ + } \ + } while(0) + #else +#define TRACEPOINT_SEMAPHORE(context, event) +#define TRACEPOINT_ACTIVE(context, event) false #define TRACEPOINT(context, ...) -#endif +#endif // ENABLE_TRACING #endif // BITCOIN_UTIL_TRACE_H diff --git a/src/validation.cpp b/src/validation.cpp index 71c2b381ddfbf..5b9b99e4aa397 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -108,6 +108,11 @@ const std::vector CHECKLEVEL_DOC { * */ static constexpr int PRUNE_LOCK_BUFFER{10}; +TRACEPOINT_SEMAPHORE(validation, block_connected); +TRACEPOINT_SEMAPHORE(utxocache, flush); +TRACEPOINT_SEMAPHORE(mempool, replaced); +TRACEPOINT_SEMAPHORE(mempool, rejected); + const CBlockIndex* Chainstate::FindForkInGlobalIndex(const CBlockLocator& locator) const { AssertLockHeld(cs_main); diff --git a/src/wallet/spend.cpp b/src/wallet/spend.cpp index 9f1e3ef376696..f45db1c16f303 100644 --- a/src/wallet/spend.cpp +++ b/src/wallet/spend.cpp @@ -35,6 +35,11 @@ using common::TransactionErrorString; using interfaces::FoundBlock; using node::TransactionError; +TRACEPOINT_SEMAPHORE(coin_selection, selected_coins); +TRACEPOINT_SEMAPHORE(coin_selection, normal_create_tx_internal); +TRACEPOINT_SEMAPHORE(coin_selection, attempting_aps_create_tx); +TRACEPOINT_SEMAPHORE(coin_selection, aps_create_tx_internal); + namespace wallet { static constexpr size_t OUTPUT_GROUP_MAX_ENTRIES{100};