tracing: utxocache tracepoints #22902

pull arnabsen1729 wants to merge 2 commits into bitcoin:master from arnabsen1729:2021-09-utxocache-usdt changing 6 files +327 −0
  1. arnabsen1729 commented at 2:35 pm on September 6, 2021: contributor

    This PR adds some of the UTXO set cache tracepoints proposed in #20981 (comment). The first tracepoints were added in bitcoin#22006.

    tracepoint description
    utxocache:flush Is called after the caches and indexes are flushed
    utxocache:add when a new coin is added to the UTXO cache
    utxocache:spent when a coin is spent
    utxocache:uncache when coin is removed from the UTXO cache

    The tracepoints are further documented in docs/tracing.md and the usage is shown via the two newly added example scripts in contrib/tracing/.

  2. arnabsen1729 force-pushed on Sep 6, 2021
  3. laanwj added the label Utils/log/libs on Sep 6, 2021
  4. arnabsen1729 force-pushed on Sep 6, 2021
  5. 0xB10C commented at 3:25 pm on September 6, 2021: member

    Concept ACK. @arnabsen1729 is working on this as part of his summerofbitcoin.org project. I’ve mentored him along the way. Some earlier review is in https://github.com/0xB10C/bitcoin/pull/1.

    I suspect hooking into the add and spend tracepoints during IBD could have a noticeable performance impact. I’ll test this. If is is the case, then it should be documented. Not hooking into the tracepoints shouldn’t have any performance impact.

  6. in src/validation.cpp:2105 in 15b8ba500d outdated 
    2119@@ -2120,6 +2120,13 @@ bool CChainState::FlushStateToDisk(
2120             nLastFlush = nNow;
2121             full_flush_completed = true;
2122         }
2123+        TRACE6(utxocache, flush,
2124+               (int64_t)(GetTimeMicros() - nNow.count()), // in microseconds (µs)
    jb55 commented at 4:26 pm on September 6, 2021:
    what’s the purpose of this argument?
    arnabsen1729 commented at 9:40 am on September 10, 2021:

    The purpose was to get the duration of the flush, this value can be used for benchmarking purposes.

    The nNow was declared here: https://github.com/bitcoin/bitcoin/blob/384d07601185d0779c324392e798da234163ca72/src/validation.cpp#L1969

  7. in src/coins.cpp:100 in 15b8ba500d outdated 
     95@@ -95,6 +96,15 @@ void CCoinsViewCache::AddCoin(const COutPoint &outpoint, Coin&& coin, bool possi
 96     it->second.coin = std::move(coin);
 97     it->second.flags |= CCoinsCacheEntry::DIRTY | (fresh ? CCoinsCacheEntry::FRESH : 0);
 98     cachedCoinsUsage += it->second.coin.DynamicMemoryUsage();
 99+    TRACE8(utxocache, add,
100+           outpoint.hash.ToString().c_str(),
    jb55 commented at 4:36 pm on September 6, 2021:
    do we need the hash string here (and the ones below)? we should avoid doing non-negligible computations in traces.
    0xB10C commented at 5:01 pm on September 6, 2021:

    We need if we want to support the current versions of bpftrace as it can’t print binary data in hex (or at all really).

    related discussion #22006 (review)

    might be worth thinking about adding support for this in bpftrace rather than this work around here

    0xB10C commented at 5:03 pm on September 6, 2021:
    I agree that outpoint.hash.ToString().c_str() here is called a lot more than the hash.data().toString().c_str() in the connect_block tracepoint. This could hurt performance. Might need to drop this.
    martinus commented at 7:12 am on September 9, 2021:
    How about only using the first 64bit of the hash: outpoint.hash.GetUint64(0). This should be very fast and maybe unique enough, at least for the purpose of tracing
    0xB10C commented at 7:19 am on September 9, 2021:
    We already pass outpoint.hash.data() as the last argument, that’s not the issue. The issue here is the ToString() part which might be to expensive in such a frequently called function while being only a work around for bpftrace not supporting hex-formatting.
    0xB10C commented at 9:55 am on September 9, 2021:

    I just came across https://github.com/iovisor/bpftrace/issues/659#issuecomment-568624842. We don’t need to use the built-in hex-formatting as it’s quite simple just printf("%02x") each byte of the txid in an unroll () {...}. This even allows us to print the txids in big-endian (the block-explorer format).

    0  $p = $txid + 31;
1  unroll(32) {
2      $b = *(uint8*)$p;
3      printf("%02x", $b);
4      $p-=1;
5  }

    This means we can drop the outpoint.hash.ToString().c_str() from the tracepoints added here and use the outpoint.hash.data() as the first argument.

    jb55 commented at 10:55 pm on September 10, 2021:
    Nice, I was trying to use unroll like this for printing data in bpftrace but could never figure it out. I was never able to do it based on a length argument, probably because it wasn’t a literal. This case works fine though since we know the length of the hash.
    laanwj commented at 7:00 pm on November 10, 2021:

    We already pass outpoint.hash.data() as the last argument, that’s not the issue. The issue here is the ToString() part which might be to expensive in such a frequently called function while being only a work around for bpftrace not supporting hex-formatting.

    I agree here. Let’s remove this ToString argument. It’s too much overhead to allocate, construct, deallocate a string here every time even if the tracepoint is disabled.

  8. DrahtBot commented at 0:28 am on September 7, 2021: member

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

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #9384 (CCoinsViewCache code cleanup & deduplication by ryanofsky)

    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.

  9. practicalswift commented at 7:58 am on September 8, 2021: contributor
    Concept ACK
  10. theStack commented at 2:28 pm on September 8, 2021: member
    Concept ACK
  11. MarcoFalke referenced this in commit 5522408f30 on Sep 9, 2021
  12. MarcoFalke referenced this in commit 5417758166 on Sep 9, 2021
  13. 0xB10C commented at 9:32 am on September 10, 2021: member

    My benchmarks (4x reindex-chainstate till block 500000 for both the mergebase 92aad5303b9b96c46015156b5dc96b48e9e7bc76 and 15b8ba500d59c6c5de764cd13c22d0cb44d6bd14) show that this PR increases time spent in ConnectBlock by about 3.4%. This is without hooking into the tracepoints.

    image

    As discussed in #22902 (review) we can drop the first argument of the add, spent, and uncache tracepoints which should improve the performance. Will re-benchmark then.

  14. 0xB10C commented at 11:00 pm on September 11, 2021: member

    Did some more profiling on a node in IBD running with this PR (https://github.com/bitcoin/bitcoin/commit/15b8ba500d59c6c5de764cd13c22d0cb44d6bd14) to make sure the ToString() is really the issue here.

    In CCoinsViewCache::SpendCoin we spend more than half of the time in ToString().
    image

    In CCoinsViewCache::AddCoin we spend a lot less time in ToString() compared to CCoinsViewCache::SpendCoin, but still significant time. image

    (please ignore the bitcoind-22902-mergebase binary name shown here. It’s not the mergebase, the binary is build from https://github.com/bitcoin/bitcoin/commit/15b8ba500d59c6c5de764cd13c22d0cb44d6bd14)

  15. laanwj commented at 7:29 am on October 1, 2021: member
    I think in general good advice is to pass binary/raw data into the trace functions directly. Don’t spent effort formatting, you can do this on the other side (and only when necessary, just before presentation to the user).
  16. 0xB10C referenced this in commit bc771fd41b on Oct 18, 2021
  17. 0xB10C referenced this in commit 82ad1c4bdd on Oct 18, 2021
  18. 0xB10C referenced this in commit 11d4406f5d on Oct 18, 2021
  19. 0xB10C referenced this in commit 604ca386bb on Oct 18, 2021
  20. 0xB10C referenced this in commit 53c9fa9e62 on Oct 18, 2021
  21. fanquake referenced this in commit 4b24f6bbb5 on Oct 19, 2021
  22. sidhujag referenced this in commit 230bd8aef6 on Oct 19, 2021
  23. laanwj commented at 6:39 pm on November 10, 2021: member

    Concept and light code review ACK, thanks for adding tracepoints!

    Edit: see discussion please remove the ToString.

  24. janus referenced this in commit c22d9a590f on Nov 11, 2021
  25. [tracing] tracepoint for utxocache flushes 
    Signed-off-by: Arnab Sen <arnabsen1729@gmail.com>
    a26e8eef43
  26. arnabsen1729 force-pushed on Nov 28, 2021
  27. [tracing] tracepoints to utxocache add, spent and uncache 
    Signed-off-by: Arnab Sen <arnabsen1729@gmail.com>
    2bc51c5c32
  28. arnabsen1729 force-pushed on Nov 28, 2021
  29. laanwj commented at 12:31 pm on November 29, 2021: member
    Thanks for updating! Code and documentation review ACK 2bc51c5c3215398875c04456a3f3df1c07b830b5
  30. laanwj merged this on Nov 29, 2021
  31. laanwj closed this on Nov 29, 2021
  32. in src/validation.cpp:2104 in 2bc51c5c32 
    2100@@ -2101,6 +2101,13 @@ bool CChainState::FlushStateToDisk(
2101             nLastFlush = nNow;
2102             full_flush_completed = true;
2103         }
2104+        TRACE6(utxocache, flush,
    0xB10C commented at 3:48 pm on November 29, 2021:
    This tracepoint is being called each time FlushStateToDisk() is called, even when we don’t flush. We call FlushStateToDisk() with FlushStateMode::PERIODIC in AcceptToMemoryPoolWithTime() for each transaction accepted to mempool.
    jamesob commented at 6:03 pm on November 29, 2021:

    If this is specifically about flushing the UTXO set, it should probably be moved a few lines higher into the conditional where the associated LOG_TIME_MILLIS... call is: https://github.com/bitcoin/bitcoin/blob/master/src/validation.cpp#L2087-L2089

    However based on the included doc, it sounds like this tracepoint is attempting to include both UTXO cache flushes and block index flushes. I think this will be difficult to do with a single tracepoint, so probably the scope should be reduced to a tracepoint for writing the coins cache to disk.

  33. in contrib/tracing/README.md:250 in 2bc51c5c32 
    245+```
246+
247+```
248+Logging utxocache flushes. Ctrl-C to end...
249+Duration (µs)   Mode       Coins Count     Memory Usage    Prune    Full Flush
250+0               PERIODIC   28484           3929.87 kB      False    False
    0xB10C commented at 3:50 pm on November 29, 2021:
    We didn’t flush here. We should only trace and log on flushes and not each time FlushStateToDisk() is called. See #22902 (review).
  34. 0xB10C commented at 3:52 pm on November 29, 2021: member
    I don’t think this was ready for merge yet. Partly my fault as I didn’t post my comments publicly and primary communicated with @arnabsen1729 directly. I think this merge should be reverted.
  35. sidhujag referenced this in commit 17e5a1632d on Nov 30, 2021
  36. in contrib/tracing/log_utxocache_flush.py:36 in 2bc51c5c32 
    31+  bpf_usdt_readarg(1, ctx, &data.duration);
32+  bpf_usdt_readarg(2, ctx, &data.mode);
33+  bpf_usdt_readarg(3, ctx, &data.coins_count);
34+  bpf_usdt_readarg(4, ctx, &data.coins_mem_usage);
35+  bpf_usdt_readarg(5, ctx, &data.is_flush_prune);
36+  bpf_usdt_readarg(5, ctx, &data.is_full_flush);
    0xB10C commented at 12:10 pm on December 2, 2021:

    Both instances of bpf_usdt_readarg read from argument 5. The second one should read from argument 6.

    If we move the tracepoint the if (fIsFullFlush) {} scope then the 6th argument can be dropped completely.

  37. laanwj commented at 10:44 am on December 4, 2021: member
    I don’t think reverting is a good idea. We only do that in the case of emergencies: breaking the build or bugs which inconvenience current users of the master branch. All of this is sufficiently experimental that it doesn’t bother anyone when it’s not in a release. Let’s handle it in a follow-up PR.
  38. 0xB10C commented at 11:12 am on December 6, 2021: member
    Agree that a follow-up is better suited here.
  39. 0xB10C commented at 11:28 am on December 6, 2021: member

    I’ve just tested the log_utxos.bt on mainnet and it’s giving me this output:

     0Spent  0b9ab1dc44cf8ff9a3b9d4Lost 20 events
 194Lost 36 events
 2f6Lost 33 events
 3b241Lost 32 events
 4b2Lost 32 events
 5Spent  6ae7e6eb7cffLost 28 events
 6bcLost 43 events
 7faLost 46 events
 809Lost 24 events
 937Lost 19 events
102fLost 32 events
11Spent  1bfaf48e84d8b3dc2c3ebe282d8842Lost 34 events
12c0Lost 18 events
135e17Lost 17 events
148aLost 42 events
150dLost 39 events
167ee9Lost 31 events
17Spent  bbc2c4ccbd1c3d6583cacd4a8572b2Lost 44 events

    The tracepoints utxocache:add and utxocache:spent tracepoints are called very frequently during block connections causing events to be lost as the buffer fills before it read. Haven’t tested if attaching to the two tracepoints via a BCC Python script or Rust program behaves differently.

    I’m seeing events being lost during testnet and signet IBD too, however not as many as on mainnet (as the blocks contain fewer transactions and thus fewer changes to the UTXO set).

  40. 0xB10C commented at 12:01 pm on December 6, 2021: member

    Let’s handle it in a follow-up PR.

    fwiw: @arnabsen1729 is working on a follow-up

  41. jb55 commented at 6:29 pm on December 6, 2021: member

    On Mon, Dec 06, 2021 at 03:28:44AM -0800, 0xB10C wrote:

    I’ve just tested the log_utxos.bt on mainnet and it’s giving me this output:

    94Lost 36 events [..]

    The tracepoints utxocache:add and utxocache:spent tracepoints are called very frequently during block connections causing events to be lost as the buffer fills before it read. Haven’t tested if attaching to the two tracepoints via a BCC Python script or Rust program behaves differently.

    Interesting, it looks like this is a fundamental limitation of the ring buffer. If you’re generating events faster than the script can process them, it looks like events will be dropped.

    Looking at the script, calling printf 32 times might be pretty slow relative to the incoming events. Is it possible to call printf once with 32 %02x entries in the format string?

  42. 0xB10C commented at 7:12 pm on December 6, 2021: member

    Looking at the script, calling printf 32 times might be pretty slow relative to the incoming events. Is it possible to call printf once with 32 %02x entries in the format string?

    Maybe, yes.

    In BCC you can set the page count of the ring buffer. That worked for me in the past. You can control bpftrace’s ring buffer page count with BPFTRACE_PERF_RB_PAGES (needs to be set to a power of two).

    Running BPFTRACE_PERF_RB_PAGES=16384 bpftrace contrib/tracing/log_utxos.bt is the lowest page size that works for me here without dropping events. Default is 64.

  43. jb55 commented at 7:14 pm on December 6, 2021: member
    @0xB10C that seems to be a better solution, since I imagine people will have harder workloads than 32 printfs…
  44. 0xB10C commented at 7:18 pm on December 6, 2021: member
    yes, I guess mentioning this on either the docs or examples page would be good. Could be done in @arnabsen1729 follow-up.
  45. jb55 commented at 7:20 pm on December 6, 2021: member
    if the page size is 4096 (some quick googling, not sure if correct), then 16384 pages is ~67 MB. seems pretty high but not unreasonable…
  46. 0xB10C referenced this in commit 21fc279ba6 on Dec 13, 2021
  47. 0xB10C referenced this in commit f1d51b3e9b on Dec 13, 2021
  48. 0xB10C referenced this in commit 0407530d7d on Dec 13, 2021
  49. arnabsen1729 referenced this in commit 29685d0ae2 on Dec 17, 2021
  50. arnabsen1729 referenced this in commit 0dea281844 on Dec 22, 2021
  51. RandyMcMillan referenced this in commit e5d47bc614 on Dec 23, 2021
  52. arnabsen1729 referenced this in commit 235addd7e1 on Dec 25, 2021
  53. arnabsen1729 referenced this in commit 261db41e15 on Dec 30, 2021
  54. 0xB10C referenced this in commit bdbf5e36eb on Feb 15, 2022
  55. arnabsen1729 referenced this in commit 799968e8b3 on Feb 18, 2022
  56. 0xB10C referenced this in commit 3e5365827f on Feb 20, 2022
  57. fanquake referenced this in commit 2b0735d183 on Feb 20, 2022
  58. sidhujag referenced this in commit ce2594239b on Feb 20, 2022
  59. laanwj referenced this in commit 6c9460edae on Apr 6, 2022
  60. janus referenced this in commit 93f2af9c02 on Jul 24, 2022
  61. Fabcien referenced this in commit 8e9ae4ef68 on Nov 30, 2022
  62. Fabcien referenced this in commit e2cc0f927a on Dec 1, 2022
  63. DrahtBot locked this on Dec 6, 2022


arnabsen1729 0xB10C jb55 martinus laanwj DrahtBot practicalswift theStack jamesob

Labels
Utils/log/libs

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-07-03 10:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me