From d524c1ec06643208c189089089e84f6e1cd0abad Mon Sep 17 00:00:00 2001 From: 0xb10c Date: Thu, 23 Nov 2023 11:06:17 +0100 Subject: [PATCH 1/3] tracing: dedup TRACE macros & rename to TRACEPOINT This deduplicates the TRACEx macros by using systemtaps STAP_PROBEV[0] variadic macro instead of the DTrace compability DTRACE_PROBE[1] macros. Bitcoin Core never had DTrace tracepoints, so we don't need to use the drop-in replacement for it. As noted in pr25541[2], these macros aren't compatibile with DTrace on macOS anyway. This also renames the TRACEx macro to TRACEPOINT to clarify what the macro does: inserting a tracepoint vs tracing (logging) something. [0]: https://sourceware.org/git/?p=systemtap.git;a=blob;f=includes/sys/sdt.h;h=24d5e01c37805e55c36f7202e5d4e821b85167a1;hb=ecab2afea46099b4e7dfd551462689224afdbe3a#l407 [1]: https://sourceware.org/git/?p=systemtap.git;a=blob;f=includes/sys/sdt.h;h=24d5e01c37805e55c36f7202e5d4e821b85167a1;hb=ecab2afea46099b4e7dfd551462689224afdbe3a#l490 [2]: https://github.com/bitcoin/bitcoin/pull/25541/files#diff-553886c5f808e01e3452c7b21e879cc355da388ef7680bf310f6acb926d43266R30-R31 Co-authored-by: Martin Leitner-Ankerl --- cmake/module/FindUSDT.cmake | 7 +++++-- doc/tracing.md | 36 ++++++++++------------------------- src/coins.cpp | 6 +++--- src/net.cpp | 2 +- src/net_processing.cpp | 2 +- src/test/CMakeLists.txt | 1 + src/test/util_trace_tests.cpp | 23 ++++++++++++++++++++++ src/txmempool.cpp | 4 ++-- src/util/trace.h | 35 ++++++++-------------------------- src/validation.cpp | 8 ++++---- src/wallet/spend.cpp | 8 ++++---- 11 files changed, 62 insertions(+), 70 deletions(-) create mode 100644 src/test/util_trace_tests.cpp diff --git a/cmake/module/FindUSDT.cmake b/cmake/module/FindUSDT.cmake index 0ba9a58fc10..0be7c28ff58 100644 --- a/cmake/module/FindUSDT.cmake +++ b/cmake/module/FindUSDT.cmake @@ -36,13 +36,16 @@ if(USDT_INCLUDE_DIR) include(CheckCXXSourceCompiles) set(CMAKE_REQUIRED_INCLUDES ${USDT_INCLUDE_DIR}) check_cxx_source_compiles(" + // Setting SDT_USE_VARIADIC lets systemtap (sys/sdt.h) know that we want to use + // the optional variadic macros to define tracepoints. + #define SDT_USE_VARIADIC 1 #include int main() { - DTRACE_PROBE(context, event); + STAP_PROBEV(context, event); int a, b, c, d, e, f, g; - DTRACE_PROBE7(context, event, a, b, c, d, e, f, g); + STAP_PROBEV(context, event, a, b, c, d, e, f, g); } " HAVE_USDT_H ) diff --git a/doc/tracing.md b/doc/tracing.md index c12af122db5..ee0d81d7dd4 100644 --- a/doc/tracing.md +++ b/doc/tracing.md @@ -265,35 +265,19 @@ Arguments passed: ## Adding tracepoints to Bitcoin Core -To add a new tracepoint, `#include ` in the compilation unit where -the tracepoint is inserted. Use one of the `TRACEx` macros listed below -depending on the number of arguments passed to the tracepoint. Up to 12 -arguments can be provided. The `context` and `event` specify the names by which -the tracepoint is referred to. Please use `snake_case` and try to make sure that -the tracepoint names make sense even without detailed knowledge of the -implementation details. Do not forget to update the tracepoint list in this +Use the `TRACEPOINT` macro to add a new tracepoint. If not yet included, include +`util/trace.h` (defines the tracepoint macros) with `#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. -```c -#define TRACE(context, event) -#define TRACE1(context, event, a) -#define TRACE2(context, event, a, b) -#define TRACE3(context, event, a, b, c) -#define TRACE4(context, event, a, b, c, d) -#define TRACE5(context, event, a, b, c, d, e) -#define TRACE6(context, event, a, b, c, d, e, f) -#define TRACE7(context, event, a, b, c, d, e, f, g) -#define TRACE8(context, event, a, b, c, d, e, f, g, h) -#define TRACE9(context, event, a, b, c, d, e, f, g, h, i) -#define TRACE10(context, event, a, b, c, d, e, f, g, h, i, j) -#define TRACE11(context, event, a, b, c, d, e, f, g, h, i, j, k) -#define TRACE12(context, event, a, b, c, d, e, f, g, h, i, j, k, l) -``` - -For example: +For example, a tracepoint in the `net` context for the event `inbound_message` +and six arguments: ```C++ -TRACE6(net, inbound_message, +TRACEPOINT(net, inbound_message, pnode->GetId(), pnode->m_addr_name.c_str(), pnode->ConnectionTypeAsString().c_str(), @@ -347,7 +331,7 @@ first six argument fields. Binary data can be placed in later arguments. The BCC supports reading from all 12 arguments. #### Strings as C-style String -Generally, strings should be passed into the `TRACEx` macros as pointers to +Generally, strings should be passed into the `TRACEPOINT` macros as pointers to C-style strings (a null-terminated sequence of characters). For C++ `std::strings`, [`c_str()`] can be used. It's recommended to document the maximum expected string size if known. diff --git a/src/coins.cpp b/src/coins.cpp index cb09aa2e7aa..4fcb48ebb12 100644 --- a/src/coins.cpp +++ b/src/coins.cpp @@ -97,7 +97,7 @@ void CCoinsViewCache::AddCoin(const COutPoint &outpoint, Coin&& coin, bool possi it->second.coin = std::move(coin); it->second.AddFlags(CCoinsCacheEntry::DIRTY | (fresh ? CCoinsCacheEntry::FRESH : 0), *it, m_sentinel); cachedCoinsUsage += it->second.coin.DynamicMemoryUsage(); - TRACE5(utxocache, add, + TRACEPOINT(utxocache, add, outpoint.hash.data(), (uint32_t)outpoint.n, (uint32_t)it->second.coin.nHeight, @@ -131,7 +131,7 @@ bool CCoinsViewCache::SpendCoin(const COutPoint &outpoint, Coin* moveout) { CCoinsMap::iterator it = FetchCoin(outpoint); if (it == cacheCoins.end()) return false; cachedCoinsUsage -= it->second.coin.DynamicMemoryUsage(); - TRACE5(utxocache, spent, + TRACEPOINT(utxocache, spent, outpoint.hash.data(), (uint32_t)outpoint.n, (uint32_t)it->second.coin.nHeight, @@ -278,7 +278,7 @@ void CCoinsViewCache::Uncache(const COutPoint& hash) CCoinsMap::iterator it = cacheCoins.find(hash); if (it != cacheCoins.end() && !it->second.IsDirty() && !it->second.IsFresh()) { cachedCoinsUsage -= it->second.coin.DynamicMemoryUsage(); - TRACE5(utxocache, uncache, + TRACEPOINT(utxocache, uncache, hash.hash.data(), (uint32_t)hash.n, (uint32_t)it->second.coin.nHeight, diff --git a/src/net.cpp b/src/net.cpp index 477240cdf2d..15cf1fe80ce 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -3809,7 +3809,7 @@ void CConnman::PushMessage(CNode* pnode, CSerializedNetMsg&& msg) CaptureMessage(pnode->addr, msg.m_type, msg.data, /*is_incoming=*/false); } - TRACE6(net, outbound_message, + TRACEPOINT(net, outbound_message, pnode->GetId(), pnode->m_addr_name.c_str(), pnode->ConnectionTypeAsString().c_str(), diff --git a/src/net_processing.cpp b/src/net_processing.cpp index be16884011e..8777af3657b 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -5421,7 +5421,7 @@ bool PeerManagerImpl::ProcessMessages(CNode* pfrom, std::atomic& interrupt CNetMessage& msg{poll_result->first}; bool fMoreWork = poll_result->second; - TRACE6(net, inbound_message, + TRACEPOINT(net, inbound_message, pfrom->GetId(), pfrom->m_addr_name.c_str(), pfrom->ConnectionTypeAsString().c_str(), diff --git a/src/test/CMakeLists.txt b/src/test/CMakeLists.txt index c23fbae92fe..fb099d06ea9 100644 --- a/src/test/CMakeLists.txt +++ b/src/test/CMakeLists.txt @@ -135,6 +135,7 @@ add_executable(test_bitcoin util_string_tests.cpp util_tests.cpp util_threadnames_tests.cpp + util_trace_tests.cpp validation_block_tests.cpp validation_chainstate_tests.cpp validation_chainstatemanager_tests.cpp diff --git a/src/test/util_trace_tests.cpp b/src/test/util_trace_tests.cpp new file mode 100644 index 00000000000..8d7eb9ae2e8 --- /dev/null +++ b/src/test/util_trace_tests.cpp @@ -0,0 +1,23 @@ +// Copyright (c) 2023 The Bitcoin Core developers +// Distributed under the MIT software license, see the accompanying +// file COPYING or http://www.opensource.org/licenses/mit-license.php. + +#include + +#include + +#include + +BOOST_FIXTURE_TEST_SUITE(util_trace_tests, BasicTestingSetup) + +// Tests the TRACEPOINT macro and that we can compile tracepoints with 0 to 12 args. +BOOST_AUTO_TEST_CASE(test_tracepoints) +{ + TRACEPOINT(test, zero_args); + TRACEPOINT(test, one_arg, 1); + TRACEPOINT(test, six_args, 1, 2, 3, 4, 5, 6); + TRACEPOINT(test, twelve_args, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12); + BOOST_CHECK(true); +} + +BOOST_AUTO_TEST_SUITE_END() \ No newline at end of file diff --git a/src/txmempool.cpp b/src/txmempool.cpp index 4756c202096..847c62c980b 100644 --- a/src/txmempool.cpp +++ b/src/txmempool.cpp @@ -477,7 +477,7 @@ void CTxMemPool::addUnchecked(const CTxMemPoolEntry &entry, setEntries &setAnces txns_randomized.emplace_back(newit->GetSharedTx()); newit->idx_randomized = txns_randomized.size() - 1; - TRACE3(mempool, added, + TRACEPOINT(mempool, added, entry.GetTx().GetHash().data(), entry.GetTxSize(), entry.GetFee() @@ -497,7 +497,7 @@ void CTxMemPool::removeUnchecked(txiter it, MemPoolRemovalReason reason) // notification. m_opts.signals->TransactionRemovedFromMempool(it->GetSharedTx(), reason, mempool_sequence); } - TRACE5(mempool, removed, + TRACEPOINT(mempool, removed, it->GetTx().GetHash().data(), RemovalReasonToString(reason).c_str(), it->GetTxSize(), diff --git a/src/util/trace.h b/src/util/trace.h index 72a486d562c..8165d602726 100644 --- a/src/util/trace.h +++ b/src/util/trace.h @@ -9,37 +9,18 @@ #ifdef ENABLE_TRACING +// Setting SDT_USE_VARIADIC lets systemtap (sys/sdt.h) know that we want to use +// the optional variadic macros to define tracepoints. +#define SDT_USE_VARIADIC 1 + #include -#define TRACE(context, event) DTRACE_PROBE(context, event) -#define TRACE1(context, event, a) DTRACE_PROBE1(context, event, a) -#define TRACE2(context, event, a, b) DTRACE_PROBE2(context, event, a, b) -#define TRACE3(context, event, a, b, c) DTRACE_PROBE3(context, event, a, b, c) -#define TRACE4(context, event, a, b, c, d) DTRACE_PROBE4(context, event, a, b, c, d) -#define TRACE5(context, event, a, b, c, d, e) DTRACE_PROBE5(context, event, a, b, c, d, e) -#define TRACE6(context, event, a, b, c, d, e, f) DTRACE_PROBE6(context, event, a, b, c, d, e, f) -#define TRACE7(context, event, a, b, c, d, e, f, g) DTRACE_PROBE7(context, event, a, b, c, d, e, f, g) -#define TRACE8(context, event, a, b, c, d, e, f, g, h) DTRACE_PROBE8(context, event, a, b, c, d, e, f, g, h) -#define TRACE9(context, event, a, b, c, d, e, f, g, h, i) DTRACE_PROBE9(context, event, a, b, c, d, e, f, g, h, i) -#define TRACE10(context, event, a, b, c, d, e, f, g, h, i, j) DTRACE_PROBE10(context, event, a, b, c, d, e, f, g, h, i, j) -#define TRACE11(context, event, a, b, c, d, e, f, g, h, i, j, k) DTRACE_PROBE11(context, event, a, b, c, d, e, f, g, h, i, j, k) -#define TRACE12(context, event, a, b, c, d, e, f, g, h, i, j, k, l) DTRACE_PROBE12(context, event, a, b, c, d, e, f, g, h, i, j, k, l) - +// A USDT tracepoint with zero to twelve arguments. +#define TRACEPOINT(context, ...) \ + STAP_PROBEV(context, __VA_ARGS__); #else -#define TRACE(context, event) -#define TRACE1(context, event, a) -#define TRACE2(context, event, a, b) -#define TRACE3(context, event, a, b, c) -#define TRACE4(context, event, a, b, c, d) -#define TRACE5(context, event, a, b, c, d, e) -#define TRACE6(context, event, a, b, c, d, e, f) -#define TRACE7(context, event, a, b, c, d, e, f, g) -#define TRACE8(context, event, a, b, c, d, e, f, g, h) -#define TRACE9(context, event, a, b, c, d, e, f, g, h, i) -#define TRACE10(context, event, a, b, c, d, e, f, g, h, i, j) -#define TRACE11(context, event, a, b, c, d, e, f, g, h, i, j, k) -#define TRACE12(context, event, a, b, c, d, e, f, g, h, i, j, k, l) +#define TRACEPOINT(context, ...) #endif diff --git a/src/validation.cpp b/src/validation.cpp index 0dd5aeffc28..71c2b381ddf 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -1304,7 +1304,7 @@ bool MemPoolAccept::Finalize(const ATMPArgs& args, Workspace& ws) tx.GetWitnessHash().ToString(), entry->GetFee(), entry->GetTxSize()); - TRACE7(mempool, replaced, + TRACEPOINT(mempool, replaced, it->GetTx().GetHash().data(), it->GetTxSize(), it->GetFee(), @@ -1866,7 +1866,7 @@ MempoolAcceptResult AcceptToMemoryPool(Chainstate& active_chainstate, const CTra for (const COutPoint& hashTx : coins_to_uncache) active_chainstate.CoinsTip().Uncache(hashTx); - TRACE2(mempool, rejected, + TRACEPOINT(mempool, rejected, tx->GetHash().data(), result.m_state.GetRejectReason().c_str() ); @@ -2736,7 +2736,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, Ticks(m_chainman.time_index), Ticks(m_chainman.time_index) / m_chainman.num_blocks_total); - TRACE6(validation, block_connected, + TRACEPOINT(validation, block_connected, block_hash.data(), pindex->nHeight, block.vtx.size(), @@ -2912,7 +2912,7 @@ bool Chainstate::FlushStateToDisk( } m_last_flush = nNow; full_flush_completed = true; - TRACE5(utxocache, flush, + TRACEPOINT(utxocache, flush, int64_t{Ticks(SteadyClock::now() - nNow)}, (uint32_t)mode, (uint64_t)coins_count, diff --git a/src/wallet/spend.cpp b/src/wallet/spend.cpp index aceed24a86c..9f1e3ef3766 100644 --- a/src/wallet/spend.cpp +++ b/src/wallet/spend.cpp @@ -1159,7 +1159,7 @@ static util::Result CreateTransactionInternal( return util::Error{err.empty() ?_("Insufficient funds") : err}; } const SelectionResult& result = *select_coins_res; - TRACE5(coin_selection, selected_coins, + TRACEPOINT(coin_selection, selected_coins, wallet.GetName().c_str(), GetAlgorithmName(result.GetAlgo()).c_str(), result.GetTarget(), @@ -1380,7 +1380,7 @@ util::Result CreateTransaction( LOCK(wallet.cs_wallet); auto res = CreateTransactionInternal(wallet, vecSend, change_pos, coin_control, sign); - TRACE4(coin_selection, normal_create_tx_internal, + TRACEPOINT(coin_selection, normal_create_tx_internal, wallet.GetName().c_str(), bool(res), res ? res->fee : 0, @@ -1389,7 +1389,7 @@ util::Result CreateTransaction( const auto& txr_ungrouped = *res; // try with avoidpartialspends unless it's enabled already if (txr_ungrouped.fee > 0 /* 0 means non-functional fee rate estimation */ && wallet.m_max_aps_fee > -1 && !coin_control.m_avoid_partial_spends) { - TRACE1(coin_selection, attempting_aps_create_tx, wallet.GetName().c_str()); + TRACEPOINT(coin_selection, attempting_aps_create_tx, wallet.GetName().c_str()); CCoinControl tmp_cc = coin_control; tmp_cc.m_avoid_partial_spends = true; @@ -1401,7 +1401,7 @@ util::Result CreateTransaction( auto txr_grouped = CreateTransactionInternal(wallet, vecSend, change_pos, tmp_cc, sign); // if fee of this alternative one is within the range of the max fee, we use this one const bool use_aps{txr_grouped.has_value() ? (txr_grouped->fee <= txr_ungrouped.fee + wallet.m_max_aps_fee) : false}; - TRACE5(coin_selection, aps_create_tx_internal, + TRACEPOINT(coin_selection, aps_create_tx_internal, wallet.GetName().c_str(), use_aps, txr_grouped.has_value(), From 411c6cfc6c2e488e407f057b646730e63806ed8a Mon Sep 17 00:00:00 2001 From: 0xb10c Date: Thu, 23 Nov 2023 16:51:36 +0100 Subject: [PATCH 2/3] 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 ee0d81d7dd4..5b9369f0b91 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 4fcb48ebb12..75d11b4f267 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 15cf1fe80ce..0a643c48c59 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 8777af3657b..2d78a4c96a6 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 8d7eb9ae2e8..06fbcf3b15b 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 847c62c980b..8b6f9938431 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 8165d602726..3deefeade37 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 71c2b381ddf..5b9b99e4aa3 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 9f1e3ef3766..f45db1c16f3 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}; From 0de3e96e333090548a43e5e870c4cb8941d6baf1 Mon Sep 17 00:00:00 2001 From: 0xb10c Date: Tue, 20 Dec 2022 12:51:13 +0100 Subject: [PATCH 3/3] tracing: use bitcoind pid in bcc tracing examples BCC needs the PID of a bitcoind process to attach to the tracepoints (instead of the binary path used before) when the tracepoints have a semaphore. For reference, we already use the PID in our tracepoint interface tests. See 220a5a2841172a07d6d7849596316f0e0933e272. --- contrib/tracing/README.md | 8 ++++---- contrib/tracing/log_raw_p2p_msgs.py | 13 +++++++------ contrib/tracing/log_utxocache_flush.py | 13 +++++++------ contrib/tracing/mempool_monitor.py | 11 ++++++----- contrib/tracing/p2p_monitor.py | 22 ++++++++++++++-------- 5 files changed, 38 insertions(+), 29 deletions(-) diff --git a/contrib/tracing/README.md b/contrib/tracing/README.md index c471770a7d7..cf59d7e2bbd 100644 --- a/contrib/tracing/README.md +++ b/contrib/tracing/README.md @@ -82,7 +82,7 @@ about the connection. Peers can be selected individually to view recent P2P messages. ``` -$ python3 contrib/tracing/p2p_monitor.py ./build/src/bitcoind +$ python3 contrib/tracing/p2p_monitor.py $(pidof bitcoind) ``` Lists selectable peers and traffic and connection information. @@ -150,7 +150,7 @@ lost. BCC prints: `Possibly lost 2 samples` on lost messages. ``` -$ python3 contrib/tracing/log_raw_p2p_msgs.py ./build/src/bitcoind +$ python3 contrib/tracing/log_raw_p2p_msgs.py $(pidof bitcoind) ``` ``` @@ -241,7 +241,7 @@ A BCC Python script to log the UTXO cache flushes. Based on the `utxocache:flush` tracepoint. ```bash -$ python3 contrib/tracing/log_utxocache_flush.py ./build/src/bitcoind +$ python3 contrib/tracing/log_utxocache_flush.py $(pidof bitcoind) ``` ``` @@ -300,7 +300,7 @@ comprising a timestamp along with all event data available via the event's tracepoint. ```console -$ python3 contrib/tracing/mempool_monitor.py ./build/src/bitcoind +$ python3 contrib/tracing/mempool_monitor.py $(pidof bitcoind) ``` ``` diff --git a/contrib/tracing/log_raw_p2p_msgs.py b/contrib/tracing/log_raw_p2p_msgs.py index c0ab7041062..bd51c2eb7d9 100755 --- a/contrib/tracing/log_raw_p2p_msgs.py +++ b/contrib/tracing/log_raw_p2p_msgs.py @@ -132,8 +132,9 @@ def print_message(event, inbound): ) -def main(bitcoind_path): - bitcoind_with_usdts = USDT(path=str(bitcoind_path)) +def main(pid): + print(f"Hooking into bitcoind with pid {pid}") + bitcoind_with_usdts = USDT(pid=int(pid)) # attaching the trace functions defined in the BPF program to the tracepoints bitcoind_with_usdts.enable_probe( @@ -176,8 +177,8 @@ def main(bitcoind_path): if __name__ == "__main__": - if len(sys.argv) < 2: - print("USAGE:", sys.argv[0], "path/to/bitcoind") + if len(sys.argv) != 2: + print("USAGE:", sys.argv[0], "") exit() - path = sys.argv[1] - main(path) + pid = sys.argv[1] + main(pid) diff --git a/contrib/tracing/log_utxocache_flush.py b/contrib/tracing/log_utxocache_flush.py index 6c568998e99..8ff9cd5e03a 100755 --- a/contrib/tracing/log_utxocache_flush.py +++ b/contrib/tracing/log_utxocache_flush.py @@ -70,8 +70,9 @@ def print_event(event): )) -def main(bitcoind_path): - bitcoind_with_usdts = USDT(path=str(bitcoind_path)) +def main(pid): + print(f"Hooking into bitcoind with pid {pid}") + bitcoind_with_usdts = USDT(pid=int(pid)) # attaching the trace functions defined in the BPF program # to the tracepoints @@ -99,9 +100,9 @@ def main(bitcoind_path): if __name__ == "__main__": - if len(sys.argv) < 2: - print("USAGE: ", sys.argv[0], "path/to/bitcoind") + if len(sys.argv) != 2: + print("USAGE: ", sys.argv[0], "") exit(1) - path = sys.argv[1] - main(path) + pid = sys.argv[1] + main(pid) diff --git a/contrib/tracing/mempool_monitor.py b/contrib/tracing/mempool_monitor.py index afb5e603722..4492cb75708 100755 --- a/contrib/tracing/mempool_monitor.py +++ b/contrib/tracing/mempool_monitor.py @@ -114,8 +114,9 @@ int trace_replaced(struct pt_regs *ctx) { """ -def main(bitcoind_path): - bitcoind_with_usdts = USDT(path=str(bitcoind_path)) +def main(pid): + print(f"Hooking into bitcoind with pid {pid}") + bitcoind_with_usdts = USDT(pid=int(pid)) # attaching the trace functions defined in the BPF program # to the tracepoints @@ -365,8 +366,8 @@ class Dashboard: if __name__ == "__main__": if len(sys.argv) < 2: - print("USAGE: ", sys.argv[0], "path/to/bitcoind") + print("USAGE: ", sys.argv[0], "") exit(1) - path = sys.argv[1] - main(path) + pid = sys.argv[1] + main(pid) diff --git a/contrib/tracing/p2p_monitor.py b/contrib/tracing/p2p_monitor.py index 4ff701cac3c..63a27fc17da 100755 --- a/contrib/tracing/p2p_monitor.py +++ b/contrib/tracing/p2p_monitor.py @@ -14,8 +14,9 @@ # outbound P2P messages. The eBPF program submits the P2P messages to # this script via a BPF ring buffer. -import sys import curses +import os +import sys from curses import wrapper, panel from bcc import BPF, USDT @@ -115,10 +116,10 @@ class Peer: self.total_outbound_msgs += 1 -def main(bitcoind_path): +def main(pid): peers = dict() - - bitcoind_with_usdts = USDT(path=str(bitcoind_path)) + print(f"Hooking into bitcoind with pid {pid}") + bitcoind_with_usdts = USDT(pid=int(pid)) # attaching the trace functions defined in the BPF program to the tracepoints bitcoind_with_usdts.enable_probe( @@ -245,9 +246,14 @@ def render(screen, peers, cur_list_pos, scroll, ROWS_AVALIABLE_FOR_LIST, info_pa (msg.msg_type, msg.size), curses.A_NORMAL) +def running_as_root(): + return os.getuid() == 0 + if __name__ == "__main__": - if len(sys.argv) < 2: - print("USAGE:", sys.argv[0], "path/to/bitcoind") + if len(sys.argv) != 2: + print("USAGE:", sys.argv[0], "") exit() - path = sys.argv[1] - main(path) + if not running_as_root(): + print("You might not have the privileges required to hook into the tracepoints!") + pid = sys.argv[1] + main(pid)