tracing: correctly scope utxocache:flush tracepoint

Previously, the `utxocache:flush` tracepoint was in the wrong scope and reached every time `CChainState::FlushStateToDisk` was called, even when there was no flushing of the cache. The tracepoint is now properly scoped and will be reached during a full flush. Inside the scope, the `fDoFullFlush` value will always be `true`, so it doesn't need to be logged separately. Hence, it's dropped from the tracepoint arguments.
philiplee15 · Dec 30, 2021 · 36a6584 · 36a6584
1 parent 5d91133
commit 36a6584
Show file tree

Hide file tree

Showing 4 changed files with 16 additions and 35 deletions.
diff --git a/contrib/tracing/README.md b/contrib/tracing/README.md
@@ -237,7 +237,7 @@ Histogram of block connection times in milliseconds (ms).
 
 ### log_utxocache_flush.py
 
-A BCC Python script to log the cache and index flushes. Based on the
+A BCC Python script to log the UTXO cache flushes. Based on the
 `utxocache:flush` tracepoint.
 
 ```bash
@@ -246,23 +246,10 @@ $ python3 contrib/tracing/log_utxocache_flush.py ./src/bitcoind
 
 ```
 Logging utxocache flushes. Ctrl-C to end...
-Duration (µs)   Mode       Coins Count     Memory Usage    Prune    Full Flush
-0               PERIODIC   28484           3929.87 kB      False    False
-1               PERIODIC   28485           3930.00 kB      False    False
-0               PERIODIC   28489           3930.51 kB      False    False
-1               PERIODIC   28490           3930.64 kB      False    False
-0               PERIODIC   28491           3930.77 kB      False    False
-0               PERIODIC   28491           3930.77 kB      False    False
-0               PERIODIC   28496           3931.41 kB      False    False
-1               PERIODIC   28496           3931.41 kB      False    False
-0               PERIODIC   28497           3931.54 kB      False    False
-1               PERIODIC   28497           3931.54 kB      False    False
-1               PERIODIC   28499           3931.79 kB      False    False
-.
-.
-.
-53788           ALWAYS     30076           4136.27 kB      False    False
-7463            ALWAYS     0               245.84 kB       False    False
+Duration (µs)   Mode       Coins Count     Memory Usage    Prune
+730451          IF_NEEDED  22990           3323.54 kB      True
+637657          ALWAYS     122320          17124.80 kB     False
+81349           ALWAYS     0               1383.49 kB      False
 ```
 
 ### log_utxos.bt

diff --git a/contrib/tracing/log_utxocache_flush.py b/contrib/tracing/log_utxocache_flush.py
@@ -20,7 +20,6 @@
   u64 coins_count;
   u64 coins_mem_usage;
   bool is_flush_prune;
-  bool is_full_flush;
 };
 
 // BPF perf buffer to push the data to user space.
@@ -33,7 +32,6 @@
   bpf_usdt_readarg(3, ctx, &data.coins_count);
   bpf_usdt_readarg(4, ctx, &data.coins_mem_usage);
   bpf_usdt_readarg(5, ctx, &data.is_flush_prune);
-  bpf_usdt_readarg(5, ctx, &data.is_full_flush);
   flush.perf_submit(ctx, &data, sizeof(data));
   return 0;
 }
@@ -55,18 +53,16 @@ class Data(ctypes.Structure):
         ("coins_count", ctypes.c_uint64),
         ("coins_mem_usage", ctypes.c_uint64),
         ("is_flush_prune", ctypes.c_bool),
-        ("is_full_flush", ctypes.c_bool)
     ]
 
 
 def print_event(event):
-    print("%-15d %-10s %-15d %-15s %-8s %-8s" % (
+    print("%-15d %-10s %-15d %-15s %-8s" % (
         event.duration,
         FLUSH_MODES[event.mode],
         event.coins_count,
         "%.2f kB" % (event.coins_mem_usage/1000),
         event.is_flush_prune,
-        event.is_full_flush
     ))
 
 
@@ -87,9 +83,9 @@ def handle_flush(_, data, size):
 
     b["flush"].open_perf_buffer(handle_flush)
     print("Logging utxocache flushes. Ctrl-C to end...")
-    print("%-15s %-10s %-15s %-15s %-8s %-8s" % ("Duration (µs)", "Mode",
-                                                 "Coins Count", "Memory Usage",
-                                                 "Prune", "Full Flush"))
+    print("%-15s %-10s %-15s %-15s %-8s" % ("Duration (µs)", "Mode",
+                                            "Coins Count", "Memory Usage",
+                                            "Prune"))
 
     while True:
         try:

diff --git a/doc/tracing.md b/doc/tracing.md
@@ -112,7 +112,7 @@ Arguments passed:
 
 #### Tracepoint `utxocache:flush`
 
-Is called *after* the caches and indexes are flushed depending on the mode
+Is called *after* the caches are flushed depending on the mode
 `CChainState::FlushStateToDisk` is called with.
 
 Arguments passed:
@@ -122,7 +122,6 @@ Arguments passed:
 3. Number of coins flushed as `uint64`
 4. Memory usage in bytes as `uint64`
 5. If the flush was pruned as `bool`
-6. If it was full flush as `bool`
 
 #### Tracepoint `utxocache:add`
 

diff --git a/src/validation.cpp b/src/validation.cpp
@@ -2324,14 +2324,13 @@ bool CChainState::FlushStateToDisk(
                 return AbortNode(state, "Failed to write to coin database");
             nLastFlush = nNow;
             full_flush_completed = true;
+            TRACE5(utxocache, flush,
+                   (int64_t)(GetTimeMicros() - nNow.count()), // in microseconds (µs)
+                   (u_int32_t)mode,
+                   (u_int64_t)coins_count,
+                   (u_int64_t)coins_mem_usage,
+                   (bool)fFlushForPrune);
         }
-        TRACE6(utxocache, flush,
-               (int64_t)(GetTimeMicros() - nNow.count()), // in microseconds (µs)
-               (u_int32_t)mode,
-               (u_int64_t)coins_count,
-               (u_int64_t)coins_mem_usage,
-               (bool)fFlushForPrune,
-               (bool)fDoFullFlush);
     }
     if (full_flush_completed) {
         // Update best block in wallet (so we can detect restored wallets).