mempool: Add mempool tracepoints #26531

pull virtu wants to merge 1 commits into bitcoin:master from virtu:add_mempool_tracepoints changing 7 files +845 −0
  1. virtu commented at 2:33 pm on November 18, 2022: contributor

    This PR adds multiple mempool tracepoints.

    tracepoint description
    mempool:added Is called when a transaction enters the mempool
    mempool:removed … when a transaction is removed from the mempool
    mempool:replaced … when a transaction is replaced in the mempool
    mempool:rejected … when a transaction is rejected from entering the mempool

    The tracepoints are further documented in docs/tracing.md. Usage is demonstrated in the example script contrib/tracing/mempool_monitor.py. Interface tests are provided in test/functional/interface_usdt_mempool.py.

    The rationale for passing the removal reason as a string instead of numerically is that the benefits of not having to maintain a redundant enum-string mapping seem to outweigh the small cost of string generation. The reject reason is passed as string as well, although in this instance the string does not have to be generated but is readily available.

  2. DrahtBot commented at 2:34 pm on November 18, 2022: contributor

    The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

    Reviews

    See the guideline for information on the review process.

    Type Reviewers
    ACK 0xB10C, achow101
    Concept ACK jamesob, dergoegge
    Stale ACK glozow

    If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #25832 (tracing: network connection tracepoints by 0xB10C)
    • #25038 (policy: nVersion=3 and Package RBF by glozow)

    If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

  3. 0xB10C commented at 3:02 pm on November 18, 2022: contributor
    Concept ACK
  4. in doc/tracing.md:224 in c0395b5c1b outdated 
    219+about the transaction.
220+
221+Arguments passed:
222+1. Transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
223+2. Transaction virtual size as `uint64`
224+3. Transaction fee as `int64`
    jamesob commented at 3:10 pm on November 18, 2022:
    Would it make sense to convey information about the peer (even if just ID) as well? One of the things that I think is potentially valuable e.g. in bmon is tracking which peers fed you which transactions.
    virtu commented at 1:39 pm on November 21, 2022:

    I think it makes sense.

    However, peer information is no longer available in functions that handle low-level mempool operations, so I propose adding a separate mempool:accepted tracepoint for this in PeerManagerImpl::ProcessMessage here (which is right where the debug log entries for transactions accepted into the memory pool are created).

    The rationale for adding a separate mempool:accepted tracepoint instead of moving the existing mempool:added one from CTxMemPool::addUnchecked is to ensure consistency of added and removed transactions.

    Details: The tracepoint call in ProcessMessage would depend on the success of ProcessTransaction here. There’s an edge case where a transaction added to the mempool in MemPoolAccept::Finalize here is immediately removed again seven lines below during the call to LimitMempoolSize, in which case MemPoolAccept::Finalize will return state.Invalid(TxValidationResult::TX_MEMPOOL_POLICY, "mempool full"). As expected, in this case ProcessMessage will not call the tracepoint (or create a debug log entry). LimitMempoolSize, however, will at some point call CTxMemPool::removeUnchecked, which calls the mempool:removed tracepoint, resulting in tracepoint data containing a “transaction removed” event without a preceding “transaction added” event.

    Please note that this problem does not arise due to poor placement of the mempool:removed tracepoint here. The tracepoint is positioned right after GetMainSignals().TransactionRemovedFromMempool, which leads me to believe that the aforementioned consistency issue currently affects zeromq (cf. here) and the debug log.

    0xB10C commented at 1:54 pm on November 21, 2022:

    Note that adding transactions we receive over the network is only one option out of several to add something to our mempool. Can also add transactions via RPC, loadMempool(), wallet, etc..

    I agree that it could be useful to have information about peers that send us transactions we end up accepting. Could call a tracepoint something like net:tx_accepted. Not sure if that’s in-scope for this PR though.

    dergoegge commented at 10:01 pm on November 22, 2022:
    Couldn’t this be done by using both net:inbound_message and mempool:added at the same time? That is, correlate the txids from both tracepoints to deduce which peer sent the tx.
    0xB10C commented at 0:06 am on November 23, 2022:
    Yes, that works too. Needs transaction decoding in the tracing script though, but possible
  5. jamesob commented at 3:17 pm on November 18, 2022: member
    Cool! concept ACK
  6. maflcko renamed this:
    tracing: Add mempool tracepoints
    mempool: Add mempool tracepoints
    on Nov 18, 2022
  7. DrahtBot added the label Mempool on Nov 18, 2022
  8. in contrib/tracing/mempool_monitor.py:13 in c0395b5c1b outdated 
     8+
 9+import curses
10+import sys
11+from datetime import datetime, timezone
12+
13+from bcc import BPF, USDT
    glozow commented at 6:07 pm on November 18, 2022: 
    0test/functional/interface_usdt_mempool.py:14: error: Cannot find implementation or library stub for module named "bcc"  [import]
1test/functional/interface_usdt_mempool.py:14: note: See https://mypy.readthedocs.io/en/stable/running_mypy.html#missing-imports
2Found 1 error in 1 file (checked 256 source files)
3^---- failure generated from lint-python.py

    I think you may want to do this?

    0# Test will be skipped if we don't have bcc installed
1try:
2    from bcc import BPF, USDT # type: ignore[import]
3except ImportError:
4    pass
    0xB10C commented at 6:21 pm on November 18, 2022:
    yes, that’s the trick we’re using in the other tracepoint tests too
    virtu commented at 3:24 pm on November 19, 2022:
    Thanks.
  9. glozow commented at 6:08 pm on November 18, 2022: member
    Concept ACK, thanks for working on this!
  10. virtu force-pushed on Nov 20, 2022
  11. dergoegge commented at 10:02 pm on November 22, 2022: member
    Concept ACK
  12. 0xB10C referenced this in commit 0cdaef4406 on Nov 25, 2022
  13. 0xB10C referenced this in commit e2bc73c418 on Nov 25, 2022
  14. 0xB10C referenced this in commit 9945ebea52 on Nov 25, 2022
  15. 0xB10C referenced this in commit f3d78a37c8 on Nov 26, 2022
  16. 0xB10C referenced this in commit 91161d6859 on Nov 27, 2022
  17. virtu force-pushed on Nov 28, 2022
  18. 0xB10C referenced this in commit 27bd196214 on Nov 28, 2022
  19. 0xB10C referenced this in commit 94331ba3cc on Nov 28, 2022
  20. 0xB10C referenced this in commit be0a187021 on Nov 29, 2022
  21. 0xB10C referenced this in commit 61ca0f99db on Nov 29, 2022
  22. in doc/tracing.md:246 in 3b6d3f0294 outdated 
    241+
242+Arguments passed:
243+1. Replacement transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
244+2. Replacement transaction virtual size as `uint64`
245+3. Replacement transaction fee as `int64`
246+4. Replaced transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
    0xB10C commented at 10:02 am on December 1, 2022:
    nit: I’d find it more intuitive to first pass the replaced transaction and then the replacement.
  23. 0xB10C commented at 2:15 pm on December 1, 2022: contributor

    With #26593: tracing: Only prepare tracepoint arguments when actually tracing, we could also pass the serialized transactions as arguments for the mempool tracepoints. I think this makes these mempool tracepoints even more interesting as we otherwise only have the txids of removed/rejected/replaced transactions and wouldn’t need to pair them with e.g. ZMQ rawtx data in an extra step. As demonstration, see the last three commits of 2022-11-virtu-add_mempool_tracepoints-with-rawtx. I’d be interested in hearing from people that left a Concept ACK here and @virtu if this extension to this PR that makes sense (once we have more Concept ACKs for #26593).

    I’m currently working on monitoring for fullrbf replacements as seen by my node with the above branch (if the replaced transaction didn’t signal optin-RBF, it should be a fullrbf replacement). Edit: It’s live on https://fullrbf.mempool.observer.

    (also sorry for the “0xB10C added a commit to 0xB10C/bitcoin that referenced this pull request” spam. Forgot that this would appear here for every force push…)

  24. russeree commented at 2:42 pm on December 1, 2022: contributor

    Super cool stuff! One note should removal reason ‘BLOCK’ be logged? It’s the one exclusion from even ZMQ because of the resulting data dump. With eBPF it’s the most difficult to log because it will overflow the eBPF ring buffer every time. There is a clever solution to use the eBPF filesystem to store data that would otherwise overflow the ring buffer.

    ref. #24935

  25. virtu commented at 3:15 pm on December 1, 2022: contributor

    One note should removal reason ‘BLOCK’ be logged? It’s the one exclusion from even ZMQ because of the resulting data dump. With eBPF it’s the most difficult to log because it will overflow the eBPF ring buffer every time.

    Block removal was deliberately included because it makes data collection much easier (inferring removal times from block arrival time involves a certain degree of processing; also, timestamps could be wrong if there was a block reorg and the original block is lost) and the overhead of calling the tracepoint pales in comparison to the rest of the code. But that’s not set in stone.

    Check the mempool_monitor.py’s code for a possible take on avoiding overflowing the ring buffer.

  26. in contrib/tracing/README.md:331 in 3b6d3f0294 outdated 
    326+ │ 17:09:56Z event=replaced, replacement_txid=db3c91d7dfff65ea5b85ca58bc3e9a26556eb6506ccb04a573f920d297060218, replace│
327+ │ ment_vsize=110, replacement_fee=23343, replaced_txid=0356df4450c76d2474eab13fab15bfab843e31617edf9ce88d5d5bea5b19bf3│
328+ │ e, replaced_vsize=110, replaced_fee=16655                                                                           │
329+ │ 17:09:56Z event=replaced, replacement_txid=9b304b9357df5e2cfcbbbead7ffa67c0efc3c599aac9093362b398478d46a587, replace│
330+ │ ment_vsize=110, replacement_fee=4268, replaced_txid=653db4f9af156626a7359c18f9cb095009583497ef606d7a9d2f093c63d392da│
331+ │ , replaced_vsize=110, replaced_fee=4037                                                                             │
    0xB10C commented at 1:57 pm on December 5, 2022:

    Played around with this a bit. Super cool!

    nit: I think these could be a bit more human readable instead of just printing the raw values. Examples:

    • added 0356df4450c76d2474eab13fab15bfab843e31617edf9ce88d5d5bea5b19bf3e with 27.14 sat/vbyte (4968 sat in fees at 183 vbyte)
    • replaced 0356df4450c76d2474eab13fab15bfab843e31617edf9ce88d5d5bea5b19bf3 (110 vbyte, 16655 sat, 151.40 sat/vbyte) with db3c91d7dfff65ea5b85ca58bc3e9a26556eb6506ccb04a573f920d297060218 (110 vbyte, 23343 sat, 212.20 sat/vbyte)
    • rejected 1cd12698577446904e8654372421e1ab5b82bdb8faee3f11f34ed758c17ae85a from peer 2568 (158.69.116.169:8333): bad-txns-inputs-missingorspent
  27. in doc/tracing.md:237 in 3b6d3f0294 outdated 
    231+Arguments passed:
232+1. Transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
233+2. Removal reason as `pointer to C-style String` (max. length 9 characters)
234+3. Transaction virtual size as `uint64`
235+4. Transaction fee as `int64`
236+
    0xB10C commented at 10:05 am on December 12, 2022:
    probably makes sense to also pass the time the transaction was initially added to the mempool here. CTxMempoolEntry has a GetTime() method.
    achow101 commented at 10:22 pm on March 16, 2023:
    It would probably make sense to include the time for all of the tracepoints added in this PR?
    0xB10C commented at 7:58 am on March 17, 2023:
    Not necessarily. Might be redundant. When a transaction is added and you pass the tracepoint arguments directly to a tracing script (can’t think of a reason why you would want to store it in a BPF map first for a while), then the time is very close to now(). Similar for rejected transactions and for the replacement transaction during RBF (the time when the replaced transaction entered is passed).
    virtu commented at 1:05 pm on March 20, 2023:

    In reply to the original comment: oversight on my part; will push a fix.

    In reply to adding event timestamps for all tracepoints: in omitting the actual event timestamps as tracepoint parameters, I followed the precedent set by other tracepoints, where, as laid out by @0xB10C, event timestamps are generated inside tracing scripts.

  28. in doc/tracing.md:248 in 3b6d3f0294 outdated 
    243+1. Replacement transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
244+2. Replacement transaction virtual size as `uint64`
245+3. Replacement transaction fee as `int64`
246+4. Replaced transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
247+5. Replaced transaction virtual size as `uint64`
248+6. Replaced transaction fee as `int64`
    0xB10C commented at 10:05 am on December 12, 2022:
    probably makes sense to also pass the time the replaced transaction was initially added to the mempool here. CTxMempoolEntry has a GetTime() method. See also https://github.com/0xB10C/mempool-observer-fullrbf-ui/issues/1#issue-1488592350
  29. virtu force-pushed on Dec 12, 2022
  30. virtu commented at 1:28 pm on December 12, 2022: contributor
  31. in src/net_processing.cpp:4164 in 869a7492df outdated 
    4160@@ -4161,6 +4161,12 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
4161             LogPrint(BCLog::MEMPOOLREJ, "%s from peer=%d was not accepted: %s\n", tx.GetHash().ToString(),
4162                 pfrom.GetId(),
4163                 state.ToString());
4164+            TRACE4(mempool, rejected,
    glozow commented at 4:36 pm on December 12, 2022:
    No huge objection, but what is the reasoning behind only tracing rejected transactions received over p2p, excluding RPC/wallet? If the reason is so we get the peerid, same comment as https://github.com/bitcoin/bitcoin/pull/26531/files#r1029861158 - this can be done by correlating mempool events with p2p inbound messages?
    0xB10C commented at 12:52 pm on December 13, 2022:
    I initially suggested to @virtu to include the peer_id (and thus place it in net_processing.cpp). But based on the ‘mempool’ scope of this PR might be better to place this tracepoint somewhere transaction source (p2p/wallet/rpc,..) agnostic.
    virtu commented at 2:12 pm on December 19, 2022:

    My reasoning was to follow the precedent set by the debug log, which only records rejected transactions received by peers. I assumed this would be the most interesting case, especially since it allowed the collection of peer data (as suggested by @0xB10C). At the time this approach seemed pragmatic, but now it appears to clash with a clean design.

    Let me know what you think of the following change:

    1. Remove all networking-related information from the mempool:rejected tracepoint to narrow the scope of the mempool tracepoints to mempool data, making for a clean interface.
    2. Call the mempool:rejected tracepoint after this loop if test_accept is false.
    0xB10C commented at 2:54 pm on December 20, 2022:
    Sounds good. Might also make sense to call the tracepoint for the test_accept == false case. Maybe even pass test_accept as argument to allow filtering in e.g. BPF or downstream tools.
    virtu commented at 10:12 am on January 17, 2023:

    Implemented in 069af24.

    This also simplified the functional tests, since validation no longer requires determining node address and port.

    To test, for example, that transactions received via RPC are covered, one can try spending an already-spent tx via bitcoin-cli. Example (courtesy of stackoverflow):

    0bitcoin-cli sendrawtransaction 0100000001e34ac1e2baac09c366fce1c2245536bda8f7db0f6685862aecf53ebd69f9a89c000000006a47304402203e8a16522da80cef66bacfbc0c800c6d52c4a26d1d86a54e0a1b76d661f020c9022010397f00149f2a8fb2bc5bca52f2d7a7f87e3897a273ef54b277e4af52051a06012103c9700559f690c4a9182faa8bed88ad8a0c563777ac1d3f00fd44ea6c71dc5127ffffffff02a0252600000000001976a914d90d36e98f62968d2bc9bbd68107564a156a9bcf88ac50622500000000001976a91407bdb518fa2e6089fd810235cf1100c9c13d1fd288ac00000000
  32. in test/functional/interface_usdt_mempool.py:135 in 869a7492df outdated 
    130+class MempoolTracepointTest(BitcoinTestFramework):
131+    def set_test_params(self):
132+        self.num_nodes = 1
133+        self.extra_args = [
134+            [
135+                "-acceptnonstdtxn=1",
    glozow commented at 4:57 pm on December 12, 2022:
    Question: is there a purpose for setting acceptnonstdtxn=1? Deleting this and having rejected_test send a create_self_transfer(fee_rate=0) seems to be an equivalent test to me. It would be preferable to test the default mempool behavior if possible, unless I’m missing something?
    virtu commented at 12:36 pm on December 13, 2022:
    I guess I was too occupied with trying to understand the functional test framework to figure out this solution. d890e9a removes acceptnonstdtxn=1.
    0xB10C commented at 12:43 pm on December 13, 2022:
    (I think this is a leftover from when you used ToManySigOps to create an invalid transaction in an earlier version of this PR)
  33. glozow commented at 5:45 pm on December 12, 2022: member
    Tested the monitor - this is awesome! A few small questions
  34. virtu force-pushed on Dec 13, 2022
  35. virtu force-pushed on Dec 13, 2022
  36. 0xB10C referenced this in commit bf997bcfe7 on Dec 20, 2022
  37. 0xB10C referenced this in commit 65366a5ae6 on Dec 20, 2022
  38. bitcoin deleted a comment on Dec 20, 2022
  39. DrahtBot added the label Needs rebase on Jan 3, 2023
  40. 0xB10C referenced this in commit 13714fda62 on Jan 4, 2023
  41. virtu force-pushed on Jan 17, 2023
  42. virtu force-pushed on Jan 17, 2023
  43. virtu force-pushed on Jan 17, 2023
  44. virtu force-pushed on Jan 17, 2023
  45. DrahtBot removed the label Needs rebase on Jan 17, 2023
  46. virtu force-pushed on Jan 17, 2023
  47. in src/validation.cpp:1476 in d0c6da92c5 outdated 
    1469@@ -1461,6 +1470,10 @@ MempoolAcceptResult AcceptToMemoryPool(Chainstate& active_chainstate, const CTra
1470 
1471         for (const COutPoint& hashTx : coins_to_uncache)
1472             active_chainstate.CoinsTip().Uncache(hashTx);
1473+        TRACE2(mempool, rejected,
1474+                tx->GetHash().data(),
1475+                result.m_state.GetRejectReason().c_str()
1476+        );
    glozow commented at 10:12 am on February 28, 2023:
    I have a question about reusing an event name, i.e. for rejections in packages (in a future PR) could/should we add a TRACE2(mempool, rejected, txhash, reason) or TRACE3(mempool, rejected, txhash, pkghash, reason) in the package rejection code? Or should we use a different event?
    virtu commented at 12:22 pm on March 14, 2023:

    Last time I checked event names could not be reused, so the package rejection code would have to use a new event.

    On the bright side, having separate rejection events might help differentiating between them and avoid conflating regular vs. package-based rejections.

    glozow commented at 12:31 pm on March 14, 2023:
    Mm good to know, thanks!
  48. 0xB10C referenced this in commit f92bb595d9 on Mar 9, 2023
  49. glozow commented at 10:00 am on March 14, 2023: member
    utACK d0c6da92c5a4d2a972f884f29dd716da2040fdb2 don’t have much experience with bcc, so hoping to get another review from @0xB10C. Also pinging @jamesob @dergoegge for re-review?
  50. 0xB10C commented at 5:10 pm on March 16, 2023: contributor

    ACK d0c6da92c5a4d2a972f884f29dd716da2040fdb2

    Code reviewed the mempool tracepoint interface tests and the mempool_monitor.py example script including the BCC code for both. Tracepoint placement also looks good and the tracepoint arguments match whats added in the documentation.

    Two things to note:

    • the mempool_monitor.py demo script will, over time, use more and more system resources (RAM and CPU) as mempool events are added to the events list. The list is never cleared. The entries in the events list are used to calculate the statistics, so for a large list it takes longer to calculate. I noticed this after running the demo script for >24h. I don’t think it’s a problem for a demo script, though.
    • I still think it makes sense to also pass the time a transaction was added to the mempool in the transaction removed tracepoint as noted in #26531 (review). This allows calculating the time the transaction was in the mempool before being mined/evicted. (I think this is an oversight as you addressed this similar comment #26531 (review) right after it).

    I’ve also setup a quick-and-dirty dashboard using these tracepoints on https://bitcoind.observer/d/jRIa_aaVk/mempool (might turn this off at somepoint again).

  51. Add mempool tracepoints 
    Tracepoints for added, removed, replaced, and rejected transactions.

The removal reason is passed as string instead of a numeric value, since
the benefits of not having to maintain a redundant enum-string mapping
seem to outweigh the small cost of string generation.  The reject reason
is passed as string as well, although here the string does not have to
be generated but is readily available.

So far, tracepoint PRs typically included two demo scripts: a naive
bpftrace script to show raw tracepoint data and a bcc script for a more
refined view. However, as some of the ongoing changes to bpftrace
introduce a certain degree of unreliability (running some of the
existing bpftrace scripts was not possible with standard kernels and
bpftrace packages on latest stable Ubuntu, Debian, and NixOS), this PR
includes only a single bcc script that fuses the functionality of former
bpftrace and bcc scripts.
    4b7aec2951
  52. virtu force-pushed on Mar 20, 2023
  53. virtu commented at 3:18 pm on March 20, 2023: contributor
    • As requested here, themempool:removed tracepoint now includes the time the removed transaction originally entered the mempool so mempool residency times can be calculated: 4684aa3
    • Addressed feedback on demo script memory usage by introducing explicit counters for events older than ten minutes to enable discarding timestamps older than ten minutes: 129d70e
  54. 0xB10C commented at 4:05 pm on March 20, 2023: contributor

    ACK 4b7aec2951fe4595946cdc804b0dec1921d79d05

    Reviewed changes since my last ACK with git range-diff d0c6da92c...4b7aec2951:

    • This adds the entry time to the mempool:removed transactions. The docs and the tests are updated accordingly.
    • Code reviewed that the mempool_monitor.py demo now doesn’t store events forever and let the script run for >10min.
    • Ran the interface_usdt_mempool.py test

    The failing CI job looks unrelated.

  55. DrahtBot requested review from glozow on Mar 20, 2023
  56. achow101 commented at 4:34 pm on March 20, 2023: member
    ACK 4b7aec2951fe4595946cdc804b0dec1921d79d05
  57. achow101 merged this on Mar 20, 2023
  58. achow101 closed this on Mar 20, 2023
  59. sidhujag referenced this in commit db4bc8c6cc on Mar 20, 2023
  60. russeree commented at 7:09 pm on March 20, 2023: contributor

    https://nydig.com/bounties/add-bpf-tracepoints-for-the-mempool

    https://github.com/NYDIG/bitcoin-task-bounty/blob/main/bounties/add-bpf-tracepoints-for-the-mempool.md

    This might be of interest. For reference I am no longer and have not been working on my mempool tracepoints PR and I closed it months ago.

  61. bitcoin deleted a comment on Apr 3, 2023
  62. kouloumos referenced this in commit d42aa93d7b on Apr 8, 2023
  63. bitcoin locked this on Apr 2, 2024
  64. virtu deleted the branch on Apr 9, 2024


virtu DrahtBot 0xB10C jamesob dergoegge glozow russeree achow101


glozow

Labels
Mempool

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-12-22 09:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me