Skip to content

workloads+smite-scenarios: patch CLN to sync with new blocks faster - #156

Merged
morehouse merged 1 commit into
lnfuzz:masterfrom
NishantBansal2003:cln-syncwallet-rpc
Jul 22, 2026
Merged

workloads+smite-scenarios: patch CLN to sync with new blocks faster#156
morehouse merged 1 commit into
lnfuzz:masterfrom
NishantBansal2003:cln-syncwallet-rpc

Conversation

@NishantBansal2003

@NishantBansal2003 NishantBansal2003 commented Jul 17, 2026

Copy link
Copy Markdown
Contributor

ref: #143

I tried two approaches for CLN:

  • Patch the polling interval from 30s (currently 2s) to 50ms
  • Add a new syncblocks RPC that triggers an immediate chain sync, and tie it to bitcoind’s -blocknotify hook

In both cases, I ran campaign for 2 days and didn’t observe any target-side issues, so both approaches appear to be stable. To determine which approach performs better, I compared their coverage using the smite evaluation script. I ran five 1h trials for each approach, then replayed the generated corpus from each trial in local mode while measuring the CPU overhead for both CLN and bitcoind. Here are the resulting plots for reference (Let me know if running longer campaign trials would provide a better comparison?):

Target: cln

Median Coverage Over Time

cln Time Series

Distribution Comparisons

Final Edge Coverage Area Under Curve (Speed)
cln Boxplot cln AUC

CPU Overhead (median)

cln CPU Overhead

With the 50ms polling interval approach:

INFO  [smite_scenarios::targets::bitcoind] Starting bitcoind...
INFO  [smite_scenarios::targets::bitcoind] Waiting for bitcoind to be ready...
INFO  [smite_scenarios::targets::bitcoind] bitcoind is ready
INFO  [smite_scenarios::targets::cln] Starting lightningd...
INFO  [smite_scenarios::targets::cln] Waiting for lightningd to be ready and synced...
INFO  [smite_scenarios::targets::cln] CLN identity pubkey: 021821158262e148a50c40b8e4eed6ad2f3a8a5dae475ba5c8269e8881a664fff6, blockheight: 101
INFO  [smite_scenarios::targets::cln] lightningd synced (blockheight=101)
INFO  [smite_scenarios::targets::cln] Both daemons are running, ready to fuzz
DEBUG [smite_scenarios::scenarios] Handshake complete, received target init
INFO  [smite::scenarios] Scenario initialized! Executing input...
INFO  [smite::runners] Reading input from "/input.bin"
DEBUG [smite_scenarios::scenarios::ir] [9.559µs] Executing IR program (28 instructions, 204 input bytes)
DEBUG [smite_scenarios::executor] [59.887µs] SendOpenChannel: 349 bytes
DEBUG [smite_scenarios::executor] [73.212µs] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [17.164578ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [23.921416ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [23.93913ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [41.149847ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [41.309537ms] BroadcastTransaction: txid=a982a06080d7d843d62b56a265ea1201d7f7ac47c7fd32cea854b4e1304906a8
DEBUG [smite_scenarios::executor] [73.766602ms] MineBlocks: mined 8 block(s)
DEBUG [smite_scenarios::executor] [73.781275ms] SendChannelReady: 77 bytes
DEBUG [smite_scenarios::executor] [84.409964ms] RecvChannelReady: waiting
DEBUG [smite_scenarios::executor] skipping gossip message type 258
DEBUG [smite_scenarios::executor] [166.947336ms] RecvChannelReady: received
DEBUG [smite_scenarios::scenarios::ir] [166.954511ms] Program executed successfully
DEBUG [smite_scenarios::scenarios::ir] [167.001796ms] Target responded with pong
INFO  [smite::scenarios] Test case ran successfully!
DEBUG [smite_scenarios::targets::cln] lightningd: requesting graceful shutdown via lightning-cli stop
DEBUG [smite_scenarios::targets::cln] lightningd: waiting for process to exit
DEBUG [smite::process] bitcoind: dropping running process, attempting shutdown
DEBUG [smite::process] bitcoind: sending SIGTERM to process group 7
DEBUG [smite::process] bitcoind: exited with exit status: 0

With the -blocknotify hook approach:

INFO  [smite_scenarios::targets::bitcoind] Starting bitcoind...
INFO  [smite_scenarios::targets::bitcoind] Waiting for bitcoind to be ready...
INFO  [smite_scenarios::targets::bitcoind] bitcoind is ready
INFO  [smite_scenarios::targets::cln] Starting lightningd...
INFO  [smite_scenarios::targets::cln] Waiting for lightningd to be ready and synced...
INFO  [smite_scenarios::targets::cln] CLN identity pubkey: 031b4bda84b978bcc29a6dc8c5a0fdbf66e6bbe4d4a29cda105c99d42510291bcc, blockheight: 101
INFO  [smite_scenarios::targets::cln] lightningd synced (blockheight=101)
INFO  [smite_scenarios::targets::cln] Both daemons are running, ready to fuzz
DEBUG [smite_scenarios::scenarios] Handshake complete, received target init
INFO  [smite::scenarios] Scenario initialized! Executing input...
INFO  [smite::runners] Reading input from "/input.bin"
DEBUG [smite_scenarios::scenarios::ir] [7.524µs] Executing IR program (28 instructions, 204 input bytes)
DEBUG [smite_scenarios::executor] [61.873µs] SendOpenChannel: 349 bytes
DEBUG [smite_scenarios::executor] [72.363µs] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [17.631703ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [23.81154ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [23.828741ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [42.806291ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [43.058768ms] BroadcastTransaction: txid=5f1961dff6b10103072fdd66d72c71a7a2ef0f4f7a0acef1c95871c6ea136cb0
DEBUG [smite_scenarios::executor] [72.396396ms] MineBlocks: mined 8 block(s)
DEBUG [smite_scenarios::executor] [72.413794ms] SendChannelReady: 77 bytes
DEBUG [smite_scenarios::executor] [81.454544ms] RecvChannelReady: waiting
DEBUG [smite_scenarios::executor] skipping gossip message type 258
DEBUG [smite_scenarios::executor] [119.480716ms] RecvChannelReady: received
DEBUG [smite_scenarios::scenarios::ir] [119.486254ms] Program executed successfully
DEBUG [smite_scenarios::scenarios::ir] [119.546017ms] Target responded with pong
INFO  [smite::scenarios] Test case ran successfully!
DEBUG [smite_scenarios::targets::cln] lightningd: requesting graceful shutdown via lightning-cli stop
DEBUG [smite_scenarios::targets::cln] lightningd: waiting for process to exit
DEBUG [smite::process] bitcoind: dropping running process, attempting shutdown
DEBUG [smite::process] bitcoind: sending SIGTERM to process group 6
DEBUG [smite::process] bitcoind: exited with exit status: 0

@Chand-ra

Copy link
Copy Markdown

ref: #143

I tried two approaches for CLN:

  • Patch the polling interval from 30s (currently 2s) to 50ms
  • Add a new syncblocks RPC that triggers an immediate chain sync, and tie it to bitcoind’s -blocknotify hook

In both cases, I ran campaign for 2 days and didn’t observe any target-side issues, so both approaches appear to be stable. To determine which approach performs better, I compared their coverage using the smite evaluation script. I ran five 1h trials for each approach, then replayed the generated corpus from each trial in local mode while measuring the CPU overhead for both CLN and bitcoind. Here are the resulting plots for reference (Let me know if running longer campaign trials would provide a better comparison?)

That is difficult to answer with just the plots. While the plots provide a qualitative way of comparing the efficacy of two approaches, the statistical tests performed in the evaluation script are supposed to be the ground-truth oracles to determine answers to questions of this nature.

Could you provide the summary statistics from the evaluation report? It should be a markdown table similar to this:

Target Duration (h) n (Baseline) n (Exp.) Median Cov. (Baseline) Median Cov. (Exp.) Adj. p-value (Cov.) Â12 (Cov.) Median AUC (Baseline) Median AUC (Exp.) Adj. p-value (AUC) Â12 (AUC) Union Cov. (Baseline) Union Cov. (Exp.) Execs/s (Baseline) Execs/s (Exp.)
ldk 14.6636 13 13 13190 14199 0.00766076 0.810651 190769 200973 0.0402395 0.739645 13544 15269 363.63 157.57

@NishantBansal2003

Copy link
Copy Markdown
Contributor Author
Target Duration (h) n (Baseline) n (Exp.) Median Cov. (Baseline) Median Cov. (Exp.) Adj. p-value (Cov.) Â12 (Cov.) Median AUC (Baseline) Median AUC (Exp.) Adj. p-value (AUC) Â12 (AUC) Union Cov. (Baseline) Union Cov. (Exp.) Execs/s (Baseline) Execs/s (Exp.)
cln 1 5 5 13063 13428 0.00793651 1 13003.3 13370.2 0.00793651 1 13302 13684 59.39 64.08

@Chand-ra

Copy link
Copy Markdown

Target Duration (h) n (Baseline) n (Exp.) Median Cov. (Baseline) Median Cov. (Exp.) Adj. p-value (Cov.) Â12 (Cov.) Median AUC (Baseline) Median AUC (Exp.) Adj. p-value (AUC) Â12 (AUC) Union Cov. (Baseline) Union Cov. (Exp.) Execs/s (Baseline) Execs/s (Exp.)
cln 1 5 5 13063 13428 0.00793651 1 13003.3 13370.2 0.00793651 1 13302 13684 59.39 64.08

The experiment is definitely statistically under-powered (needs longer and more trials). But solely from the results here, the experimental configuration (which I assume is the blocknotify approach) is better than the baseline (assumably the polling approach) 100% of the time, with very little chances (~0.8%) of any of the trials being a false positive. True for both final coverage and AUC values.

Bottom line, this is the strongest possible result we can observe using our framework!

The execs/sec also seem to gain a significant improvement, and the CPU overhead is significantly lower. Given all of this, I think it's reasonable to assume that the blocknotify approach will be atleast as performant as the polling approach.

@Chand-ra

Copy link
Copy Markdown

The code looks fine to me, but I think it would be better to store patches in a separate directory like fuzzamoto does instead of alongside Docker files. Maybe in a workloads/<target>/patches/ directory?

@morehouse morehouse left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I do agree with @Chand-ra that it would be good to move the patch to a subdir.

Otherwise LGTM

@morehouse

Copy link
Copy Markdown
Collaborator

BTW, can we now remove the previous CLN 30s -> 2s patch?

@ekzyis ekzyis left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ACK 6da3fb7

I like the -blocknotify approach!

Comment thread smite-scenarios/src/targets/cln.rs Outdated
rpc_port: self.bitcoind_rpc_port,
p2p_port: self.bitcoind_p2p_port,
extra_args: vec![format!(
"-blocknotify=lightning-cli --lightning-dir={} --network=regtest syncblocks",

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit:

Suggested change
"-blocknotify=lightning-cli --lightning-dir={} --network=regtest syncblocks",
"-blocknotify=lightning-cli --lightning-dir='{}' --network=regtest syncblocks",

If the path contains spaces, I think -blocknotify would break. Wrapping the path in single quotes isn't foolproof (it would still break if the path itself contains a '), but it's probably good enough to avoid an unlikely edge case.

@erickcestari erickcestari left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think coverage is the most meaningful metric for evaluating this change. Since the goal of this PR is to maintain the same coverage while improving execution throughput, I think the benchmark from #160 is more appropriate, as it repeatedly executes the same input directly with NYX.

I ran the benchmark 6 times, and in each run I executed the following input 100 times:

v0 = LoadPrivateKey(0x00…01)
v1 = DerivePoint(v0)
v2 = LoadPrivateKey(0x00…02)
v3 = DerivePoint(v2)
v4 = LoadPrivateKey(0x00…03)
v5 = DerivePoint(v4)
v6 = LoadPrivateKey(0x00…04)
v7 = DerivePoint(v6)
v8 = LoadPrivateKey(0x00…05)
v9 = DerivePoint(v8)
v10 = LoadPrivateKey(0x00…06)
v11 = DerivePoint(v10)
v12 = LoadChannelId(0x1111…11)
v13 = LoadChainHashFromContext()
v14 = LoadAmount(100000)
v15 = LoadAmount(0)
v16 = LoadAmount(546)
v17 = LoadAmount(10000000)
v18 = LoadAmount(1000)
v19 = LoadAmount(1)
v20 = LoadFeeratePerKw(2500)
v21 = LoadU16(144)
v22 = LoadU16(483)
v23 = LoadU8(1)
v24 = LoadShutdownScript(Empty)
v25 = LoadChannelType(Anchors)
v26 = BuildOpenChannel(v13, v12, v14, v15, v16, v17, v18, v19, v20, v21, v22, v1, v3, v5, v7, v9, v11, v23, v24, v25)
v27 = SendOpenChannel(v26)
v28 = RecvAcceptChannel(v27)
v29 = ExtractFundingPubkey(v28)
v30 = CreateFundingTransaction(v1, v29, v14, v20)
v31 = SendFundingCreated(v30, v0, v12)
v32 = RecvFundingSigned(v31)
BroadcastTransaction(v30)
MineBlocks(8)
v35 = LoadPrivateKey(0x00…07)
v36 = DerivePoint(v35)
v37 = LoadShortChannelId(1x1x0)
SendChannelReady{include_alias=false}(v32, v36, v37)
RecvChannelReady()

For the CLN JSON-RPC implementation, I got:

Smite Nyx benchmark
  target:      cln/ir
  sharedir:    /tmp/smite-nyx
  input size:  410 bytes
  iterations:  100
  repeats:     6

  run 1/6:
  snapshot creation (first exec): 338.79 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.4
    wall time: 22.631 s
    latency:   min 215.34 ms  mean 226.31 ms  median 221.34 ms  p99 273.81 ms  max 290.26 ms
    input execution: mean 203.76 ms  median 199.32 ms   (guest runtime)
    nyx overhead:    mean 22.55 ms  median 21.85 ms   (restore + reset + ipc; 58686 dirty pages/exec)
    non-normal results: 0 / 100

  run 2/6:
  snapshot creation (first exec): 285.37 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.5
    wall time: 22.453 s
    latency:   min 214.58 ms  mean 224.53 ms  median 224.42 ms  p99 234.49 ms  max 238.29 ms
    input execution: mean 202.42 ms  median 202.32 ms   (guest runtime)
    nyx overhead:    mean 22.11 ms  median 21.92 ms   (restore + reset + ipc; 58224 dirty pages/exec)
    non-normal results: 0 / 100

  run 3/6:
  snapshot creation (first exec): 321.92 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.4
    wall time: 22.698 s
    latency:   min 215.03 ms  mean 226.98 ms  median 220.90 ms  p99 265.48 ms  max 276.45 ms
    input execution: mean 204.73 ms  median 199.26 ms   (guest runtime)
    nyx overhead:    mean 22.25 ms  median 21.64 ms   (restore + reset + ipc; 58087 dirty pages/exec)
    non-normal results: 0 / 100

  run 4/6:
  snapshot creation (first exec): 315.64 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.4
    wall time: 22.657 s
    latency:   min 215.28 ms  mean 226.57 ms  median 224.91 ms  p99 252.71 ms  max 268.01 ms
    input execution: mean 204.30 ms  median 202.43 ms   (guest runtime)
    nyx overhead:    mean 22.27 ms  median 22.06 ms   (restore + reset + ipc; 58112 dirty pages/exec)
    non-normal results: 0 / 100

  run 5/6:
  snapshot creation (first exec): 284.72 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.2
    wall time: 23.837 s
    latency:   min 220.04 ms  mean 238.37 ms  median 232.66 ms  p99 287.95 ms  max 294.65 ms
    input execution: mean 214.49 ms  median 209.38 ms   (guest runtime)
    nyx overhead:    mean 23.88 ms  median 22.94 ms   (restore + reset + ipc; 59717 dirty pages/exec)
    non-normal results: 0 / 100

  run 6/6:
  snapshot creation (first exec): 312.56 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.0
    wall time: 24.873 s
    latency:   min 217.83 ms  mean 248.73 ms  median 245.15 ms  p99 292.91 ms  max 304.05 ms
    input execution: mean 224.14 ms  median 220.37 ms   (guest runtime)
    nyx overhead:    mean 24.59 ms  median 24.71 ms   (restore + reset + ipc; 58166 dirty pages/exec)
    non-normal results: 0 / 100

  aggregate over 6 runs:
    execs/sec: mean 4.3  stddev 0.2  min 4.0  max 4.5
    snapshot:  mean 309.83 ms
    latency (mean across runs):
      min 216.35 ms  mean 231.91 ms  median 228.23 ms  p99 267.89 ms  max 278.62 ms
    input execution (mean across runs): mean 208.97 ms  median 205.51 ms
    nyx overhead (mean across runs):     mean 22.94 ms  median 22.52 ms
    non-normal results: 0 / 600

With the CLN polling implementation using a 50 ms interval, the results were:

Smite Nyx benchmark
  target:      cln/ir
  sharedir:    /tmp/smite-nyx
  input size:  410 bytes
  iterations:  100
  repeats:     6

  run 1/6:
  snapshot creation (first exec): 164.29 ms
  steady-state (snapshot restore + target run):
    execs/sec: 6.2
    wall time: 16.231 s
    latency:   min 148.71 ms  mean 162.31 ms  median 159.20 ms  p99 200.43 ms  max 254.28 ms
    input execution: mean 152.66 ms  median 150.25 ms   (guest runtime)
    nyx overhead:    mean 9.65 ms  median 9.53 ms   (restore + reset + ipc; 21166 dirty pages/exec)
    non-normal results: 0 / 100

  run 2/6:
  snapshot creation (first exec): 141.56 ms
  steady-state (snapshot restore + target run):
    execs/sec: 7.5
    wall time: 13.368 s
    latency:   min 129.52 ms  mean 133.68 ms  median 133.42 ms  p99 138.12 ms  max 145.71 ms
    input execution: mean 124.27 ms  median 124.09 ms   (guest runtime)
    nyx overhead:    mean 9.41 ms  median 9.42 ms   (restore + reset + ipc; 21929 dirty pages/exec)
    non-normal results: 0 / 100

  run 3/6:
  snapshot creation (first exec): 134.82 ms
  steady-state (snapshot restore + target run):
    execs/sec: 7.5
    wall time: 13.370 s
    latency:   min 111.58 ms  mean 133.70 ms  median 133.85 ms  p99 145.51 ms  max 160.73 ms
    input execution: mean 124.18 ms  median 124.25 ms   (guest runtime)
    nyx overhead:    mean 9.52 ms  median 9.52 ms   (restore + reset + ipc; 22083 dirty pages/exec)
    non-normal results: 0 / 100

  run 4/6:
  snapshot creation (first exec): 136.57 ms
  steady-state (snapshot restore + target run):
    execs/sec: 7.5
    wall time: 13.325 s
    latency:   min 127.18 ms  mean 133.25 ms  median 132.65 ms  p99 143.67 ms  max 165.25 ms
    input execution: mean 123.89 ms  median 123.55 ms   (guest runtime)
    nyx overhead:    mean 9.36 ms  median 9.29 ms   (restore + reset + ipc; 21880 dirty pages/exec)
    non-normal results: 0 / 100

  run 5/6:
  snapshot creation (first exec): 120.91 ms
  steady-state (snapshot restore + target run):
    execs/sec: 6.1
    wall time: 16.383 s
    latency:   min 156.31 ms  mean 163.82 ms  median 162.39 ms  p99 181.66 ms  max 189.13 ms
    input execution: mean 154.25 ms  median 152.75 ms   (guest runtime)
    nyx overhead:    mean 9.57 ms  median 9.53 ms   (restore + reset + ipc; 21705 dirty pages/exec)
    non-normal results: 0 / 100

  run 6/6:
  snapshot creation (first exec): 142.95 ms
  steady-state (snapshot restore + target run):
    execs/sec: 7.7
    wall time: 12.946 s
    latency:   min 112.60 ms  mean 129.46 ms  median 129.22 ms  p99 141.65 ms  max 168.44 ms
    input execution: mean 120.29 ms  median 120.22 ms   (guest runtime)
    nyx overhead:    mean 9.17 ms  median 9.11 ms   (restore + reset + ipc; 21266 dirty pages/exec)
    non-normal results: 0 / 100

  aggregate over 6 runs:
    execs/sec: mean 7.1  stddev 0.7  min 6.1  max 7.7
    snapshot:  mean 140.18 ms
    latency (mean across runs):
      min 130.98 ms  mean 142.70 ms  median 141.79 ms  p99 158.51 ms  max 180.59 ms
    input execution (mean across runs): mean 133.26 ms  median 132.52 ms
    nyx overhead (mean across runs):     mean 9.45 ms  median 9.40 ms
    non-normal results: 0 / 600

Compared to the JSON-RPC implementation, the 50 ms polling interval increased execution throughput by roughly 81% (4.3 -> 7.8 execs/sec) while reducing average end-to-end latency from 230 ms to 129 ms.

I think it's worth considering using the 50 ms polling interval. This difference is only noticeable when running with NYX.

My guess is that spawning processes dirty a lot of memory (page tables, loaded binaries, and RPC buffers). NYX must restore every dirty page on the next snapshot reset, so an exec with many spawns makes every subsequent reset more expensive.

Edit: I've updated the benchmark code to calculate the NYX snapshot overhead. My guess wasn't entirely correct. The polling accounts for half of the nyx JSON-RPC overhead. However, this doesn't explain why the raw input execution was faster than the clean JSON-RPC. I'll try running it on a different computer.

@morehouse

Copy link
Copy Markdown
Collaborator

The fuzzing results show significantly higher coverage for the notification variant, which also implies more execs/sec. But the benchmark shows more execs/sec for the polling variant.

Some possible explanations:

  • The benchmark runs against a single input, whose timing may happen to align well with one of CLN's 50ms polls, hiding the typical wait time of the polling mechanism.
  • When a program does actually execute RecvChannelReady, perhaps frequent polling is faster than doing the notification. But for programs that don't execute RecvChannelReady, frequent polling is just more CPU overhead for no benefit. The benchmark was done only against a program that executes RecvChannelReady, while the fuzzing run was done across the whole spectrum of inputs that could be generated, most of which never actually execute RecvChannelReady.

I haven't reviewed #160 yet, so there could be other explanations. Just wanted to share some initial thoughts.

@erickcestari

Copy link
Copy Markdown
Contributor

The fuzzing results show significantly higher coverage for the notification variant, which also implies more execs/sec.

One possible explanation for the higher level of coverage is that it uses JSON-RPC and Lightning-CLI, which access code that the polling variant cannot/will access.

@morehouse

Copy link
Copy Markdown
Collaborator

We should be able to test these hypotheses empirically.

* The benchmark runs against a single input, whose timing may happen to align well with one of CLN's 50ms polls, hiding the typical wait time of the polling mechanism.

Insert various sleeps before snapshot creation to offset the block-sync intervals, rebenchmark and compare results. At most can explain 50ms of the ~90ms difference.

* When a program does actually execute `RecvChannelReady`, perhaps frequent polling is faster than doing the notification.  But for programs that don't execute `RecvChannelReady`, frequent polling is just more CPU overhead for no benefit.  The benchmark was done only against a program that executes `RecvChannelReady`, while the fuzzing run was done across the whole spectrum of inputs that could be generated, most of which never actually execute `RecvChannelReady`.

Benchmark the exact same program without the RecvChannelReady and compare results.

One possible explanation for the higher level of coverage is that it uses JSON-RPC and Lightning-CLI, which access code that the polling variant cannot/will access.

Run the benchmark input through both variants and subtract the coverage difference. Adjust the coverage numbers from the fuzzing result accordingly.

@erickcestari

Copy link
Copy Markdown
Contributor
  • When a program does actually execute RecvChannelReady, perhaps frequent polling is faster than doing the notification. But for programs that don't execute RecvChannelReady, frequent polling is just more CPU overhead for no benefit. The benchmark was done only against a program that executes RecvChannelReady, while the fuzzing run was done across the whole spectrum of inputs that could be generated, most of which never actually execute RecvChannelReady.

I've tested with an input that never calls RecvChannelReady and does a lot of I/O operations

Input
MineBlocks(8)
v1 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000002)
v2 = DerivePoint(v1)
v3 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000003)
v4 = DerivePoint(v3)
v5 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000004)
v6 = DerivePoint(v5)
v7 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000005)
v8 = DerivePoint(v7)
v9 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000006)
v10 = DerivePoint(v9)
v11 = LoadChainHashFromContext()
v12 = LoadAmount(100000)
v13 = LoadAmount(0)
v14 = LoadAmount(546)
v15 = LoadAmount(10000000)
v16 = LoadAmount(1000)
v17 = LoadAmount(1)
v18 = LoadFeeratePerKw(2500)
v19 = LoadU16(144)
v20 = LoadU16(483)
v21 = LoadU8(1)
v22 = LoadShutdownScript(Empty)
v23 = LoadChannelType(Anchors)
v24 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000010)
v25 = DerivePoint(v24)
v26 = LoadChannelId(0xc0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c000)
v27 = BuildOpenChannel(v11, v26, v12, v13, v14, v15, v16, v17, v18, v19, v20, v25, v2, v4, v6, v8, v10, v21, v22, v23)
v28 = SendOpenChannel(v27)
v29 = RecvAcceptChannel(v28)
v30 = ExtractFundingPubkey(v29)
v31 = CreateFundingTransaction(v25, v30, v12, v18)
v32 = SendFundingCreated(v31, v24, v26)
v33 = RecvFundingSigned(v32)
v34 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000011)
v35 = DerivePoint(v34)
v36 = LoadChannelId(0xc0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c001)
v37 = BuildOpenChannel(v11, v36, v12, v13, v14, v15, v16, v17, v18, v19, v20, v35, v2, v4, v6, v8, v10, v21, v22, v23)
v38 = SendOpenChannel(v37)
v39 = RecvAcceptChannel(v38)
v40 = ExtractFundingPubkey(v39)
v41 = CreateFundingTransaction(v35, v40, v12, v18)
v42 = SendFundingCreated(v41, v34, v36)
v43 = RecvFundingSigned(v42)
v44 = LoadPrivateKey(0x000000000000000000000000000000000000000000000000000
v45 = DerivePoint(v44)
v46 = LoadChannelId(0xc0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c002)
v47 = BuildOpenChannel(v11, v46, v12, v13, v14, v15, v16, v17, v18, v19, v20, v45, v2, v4, v6, v8, v10, v21, v22, v23)
v48 = SendOpenChannel(v47)
v49 = RecvAcceptChannel(v48)
v50 = ExtractFundingPubkey(v49)
v51 = CreateFundingTransaction(v45, v50, v12, v18)
v52 = SendFundingCreated(v51, v44, v46)
v53 = RecvFundingSigned(v52)
v54 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000013)
v55 = DerivePoint(v54)
v56 = LoadChannelId(0xc0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c003)
v57 = BuildOpenChannel(v11, v56, v12, v13, v14, v15, v16, v17, v18, v19, v20, v55, v2, v4, v6, v8, v10, v21, v22, v23)
v58 = SendOpenChannel(v57)
v59 = RecvAcceptChannel(v58)
v60 = ExtractFundingPubkey(v59)
v61 = CreateFundingTransaction(v55, v60, v12, v18)
v62 = SendFundingCreated(v61, v54, v56)
v63 = RecvFundingSigned(v62)
v64 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000014)
v65 = DerivePoint(v64)
v66 = LoadChannelId(0xc0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c004)
v67 = BuildOpenChannel(v11, v66, v12, v13, v14, v15, v16, v17, v18, v19, v v21, v22, v23)
v68 = SendOpenChannel(v67)
v69 = RecvAcceptChannel(v68)
v70 = ExtractFundingPubkey(v69)
v71 = CreateFundingTransaction(v65, v70, v12, v18)
v72 = SendFundingCreated(v71, v64, v66)
v73 = RecvFundingSigned(v72)
v74 = LoadPrivateKey(0x000000000000000000000000000000000000000000000000000
v75 = DerivePoint(v74)
v76 = LoadChannelId(0xc0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0
v77 = BuildOpenChannel(v11, v76, v12, v13, v14, v15, v16, v17, v18, v19, v20, v75, v2, v4, v6, v8, v10, v21, v22, v23)
v78 = SendOpenChannel(v77)
v79 = RecvAcceptChannel(v78)
v80 = ExtractFundingPubkey(v79)
v81 = CreateFundingTransaction(v75, v80, v12, v18)
v82 = SendFundingCreated(v81, v74, v76)
v83 = RecvFundingSigned(v82)
v84 = LoadPrivateKey(0x000000000000000000000000000000000000000000000000000
v85 = DerivePoint(v84)
v86 = LoadChannelId(0xc0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c006)
v87 = BuildOpenChannel(v11, v86, v12, v13, v14, v15, v16, v17, v18, v19, v20, v85, v2, v4, v6, v8, v10, v21, v22, v23)
v88 = SendOpenChannel(v87)
v89 = RecvAcceptChannel(v88)
v90 = ExtractFundingPubkey(v89)
v91 = CreateFundingTransaction(v85, v90, v12, v18)
v92 = SendFundingCreated(v91, v84, v86)
v93 = RecvFundingSigned(v92)
v94 = LoadPrivateKey(0x000000000000000000000000000000000000000000000000000
v95 = DerivePoint(v94)
v96 = LoadChannelId(0xc0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c0c007)
v97 = BuildOpenChannel(v11, v96, v12, v13, v14, v15, v16, v17, v18, v19, v v21, v22, v23)
v98 = SendOpenChannel(v97)
v99 = RecvAcceptChannel(v98)
v100 = ExtractFundingPubkey(v99)
v101 = CreateFundingTransaction(v95, v100, v12, v18)
v102 = SendFundingCreated(v101, v94, v96)
v103 = RecvFundingSigned(v102)

Results:

json-rpc notification
Smite Nyx benchmark
  target:      cln/ir
  sharedir:    /tmp/smite-nyx
  input size:  1173 bytes
  iterations:  100
  repeats:     6

  run 1/6:
  snapshot creation (first exec): 389.03 ms
  steady-state (snapshot restore + target run):
    execs/sec: 2.6
    wall time: 39.123 s
    latency:   min 382.67 ms  mean 391.23 ms  median 389.84 ms  p99 412.34 ms  max 413.95 ms
    input execution: mean 368.07 ms  median 366.80 ms   (guest runtime)
    nyx overhead:    mean 23.16 ms  median 23.06 ms   (restore + reset + ipc; 59112 dirty pages/exec)
    non-normal results: 0 / 100

  run 2/6:
  snapshot creation (first exec): 511.60 ms
  steady-state (snapshot restore + target run):
    execs/sec: 2.5
    wall time: 39.567 s
    latency:   min 385.01 ms  mean 395.67 ms  median 393.08 ms  p99 424.69 ms  max 460.15 ms
    input execution: mean 371.98 ms  median 369.36 ms   (guest runtime)
    nyx overhead:    mean 23.69 ms  median 23.31 ms   (restore + reset + ipc; 59262 dirty pages/exec)
    non-normal results: 0 / 100

  run 3/6:
  snapshot creation (first exec): 512.84 ms
  steady-state (snapshot restore + target run):
    execs/sec: 2.6
    wall time: 38.244 s
    latency:   min 368.16 ms  mean 382.44 ms  median 379.69 ms  p99 432.39 ms  max 442.94 ms
    input execution: mean 360.18 ms  median 357.50 ms   (guest runtime)
    nyx overhead:    mean 22.25 ms  median 21.99 ms   (restore + reset + ipc; 58946 dirty pages/exec)
    non-normal results: 0 / 100

  run 4/6:
  snapshot creation (first exec): 579.92 ms
  steady-state (snapshot restore + target run):
    execs/sec: 2.6
    wall time: 38.270 s
    latency:   min 369.99 ms  mean 382.70 ms  median 379.23 ms  p99 421.73 ms  max 483.56 ms
    input execution: mean 360.11 ms  median 356.84 ms   (guest runtime)
    nyx overhead:    mean 22.59 ms  median 22.29 ms   (restore + reset + ipc; 59595 dirty pages/exec)
    non-normal results: 0 / 100

  run 5/6:
  snapshot creation (first exec): 526.41 ms
  steady-state (snapshot restore + target run):
    execs/sec: 2.6
    wall time: 38.437 s
    latency:   min 373.77 ms  mean 384.37 ms  median 380.96 ms  p99 407.94 ms  max 417.56 ms
    input execution: mean 362.05 ms  median 358.94 ms   (guest runtime)
    nyx overhead:    mean 22.32 ms  median 22.05 ms   (restore + reset + ipc; 59171 dirty pages/exec)
    non-normal results: 0 / 100

  run 6/6:
  snapshot creation (first exec): 584.00 ms
  steady-state (snapshot restore + target run):
    execs/sec: 2.6
    wall time: 38.850 s
    latency:   min 370.27 ms  mean 388.50 ms  median 380.75 ms  p99 487.21 ms  max 495.70 ms
    input execution: mean 365.86 ms  median 358.37 ms   (guest runtime)
    nyx overhead:    mean 22.63 ms  median 22.27 ms   (restore + reset + ipc; 59514 dirty pages/exec)
    non-normal results: 0 / 100

  aggregate over 6 runs:
    execs/sec: mean 2.6  stddev 0.0  min 2.5  max 2.6
    snapshot:  mean 517.30 ms
    latency (mean across runs):
      min 374.98 ms  mean 387.48 ms  median 383.93 ms  p99 431.05 ms  max 452.31 ms
    input execution (mean across runs): mean 364.71 ms  median 361.30 ms
    nyx overhead (mean across runs):     mean 22.77 ms  median 22.49 ms
    non-normal results: 0 / 600

one log:

docker run --rm \
          -v $PWD/input.bin:/input.bin \
          -e SMITE_INPUT=/input.bin \
          -e RUST_LOG=debug \
          smite-cln-ir /cln-scenario
INFO  [smite_scenarios::targets::bitcoind] Starting bitcoind...
INFO  [smite_scenarios::targets::bitcoind] Waiting for bitcoind to be ready...
INFO  [smite_scenarios::targets::bitcoind] bitcoind is ready
INFO  [smite_scenarios::targets::cln] Starting lightningd...
INFO  [smite_scenarios::targets::cln] Waiting for lightningd to be ready and synced...
INFO  [smite_scenarios::targets::cln] CLN identity pubkey: 0370c595a8da7c878bb9f72496fdf8d54609c8208e1133fe2194c05938ada36fbb, blockheight: 88
DEBUG [smite_scenarios::targets::cln] lightningd not yet synced (blockheight=88)
INFO  [smite_scenarios::targets::cln] CLN identity pubkey: 0370c595a8da7c878bb9f72496fdf8d54609c8208e1133fe2194c05938ada36fbb, blockheight: 101
INFO  [smite_scenarios::targets::cln] lightningd synced (blockheight=101)
INFO  [smite_scenarios::targets::cln] Both daemons are running, ready to fuzz
DEBUG [smite_scenarios::scenarios] Handshake complete, received target init
INFO  [smite::scenarios] Scenario initialized! Executing input...
INFO  [smite::runners] Reading input from "/input.bin"
DEBUG [smite_scenarios::scenarios::ir] [32.253µs] Executing IR program (104 instructions, 1173 input bytes)
DEBUG [smite_scenarios::executor] [203.169313ms] MineBlocks: mined 8 block(s)
DEBUG [smite_scenarios::executor] [203.730298ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [203.809627ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [226.398215ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [346.824386ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [346.905685ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [384.14885ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [384.726338ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [384.784481ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [403.176266ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [431.30529ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [431.346818ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [462.045238ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [462.424681ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [462.450447ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [479.673476ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [509.38699ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [509.437168ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [535.148588ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [535.563808ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [535.596234ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [553.327027ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [584.330199ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [584.403426ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [614.509038ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [614.708147ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [614.727846ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [628.994253ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [656.04321ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [656.087674ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [678.952887ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [679.336648ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [679.36902ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [695.577046ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [724.963875ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [725.012954ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [756.946905ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [757.219442ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [757.246594ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [780.480375ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [813.980385ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [814.048717ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [842.251858ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [842.653283ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [842.678511ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [858.50074ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [886.477658ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [886.52915ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [909.339377ms] RecvFundingSigned: received
DEBUG [smite_scenarios::scenarios::ir] [909.70453ms] Program executed successfully
DEBUG [smite_scenarios::scenarios::ir] [909.853963ms] Target responded with pong
INFO  [smite::scenarios] Test case ran successfully!
DEBUG [smite_scenarios::targets::cln] lightningd: requesting graceful shutdown via lightning-cli stop
DEBUG [smite_scenarios::targets::cln] lightningd: waiting for process to exit
DEBUG [smite::process] bitcoind: dropping running process, attempting shutdown
DEBUG [smite::process] bitcoind: sending SIGTERM to process group 6
DEBUG [smite::process] bitcoind: exited with exit status: 0
50ms polling
Smite Nyx benchmark
  target:      cln/ir
  sharedir:    /tmp/smite-nyx
  input size:  1173 bytes
  iterations:  100
  repeats:     6

  run 1/6:
  snapshot creation (first exec): 397.89 ms
  steady-state (snapshot restore + target run):
    execs/sec: 3.2
    wall time: 31.371 s
    latency:   min 304.55 ms  mean 313.71 ms  median 311.05 ms  p99 334.73 ms  max 363.04 ms
    input execution: mean 293.00 ms  median 290.26 ms   (guest runtime)
    nyx overhead:    mean 20.71 ms  median 20.58 ms   (restore + reset + ipc; 55331 dirty pages/exec)
    non-normal results: 0 / 100

  run 2/6:
  snapshot creation (first exec): 692.11 ms
  steady-state (snapshot restore + target run):
    execs/sec: 3.1
    wall time: 32.252 s
    latency:   min 306.21 ms  mean 322.52 ms  median 320.03 ms  p99 356.34 ms  max 382.26 ms
    input execution: mean 301.29 ms  median 299.08 ms   (guest runtime)
    nyx overhead:    mean 21.23 ms  median 20.87 ms   (restore + reset + ipc; 55530 dirty pages/exec)
    non-normal results: 0 / 100

  run 3/6:
  snapshot creation (first exec): 552.95 ms
  steady-state (snapshot restore + target run):
    execs/sec: 3.0
    wall time: 33.120 s
    latency:   min 308.39 ms  mean 331.20 ms  median 322.86 ms  p99 397.35 ms  max 424.00 ms
    input execution: mean 309.44 ms  median 301.07 ms   (guest runtime)
    nyx overhead:    mean 21.76 ms  median 21.26 ms   (restore + reset + ipc; 55553 dirty pages/exec)
    non-normal results: 0 / 100

  run 4/6:
  snapshot creation (first exec): 446.72 ms
  steady-state (snapshot restore + target run):
    execs/sec: 3.1
    wall time: 32.607 s
    latency:   min 304.87 ms  mean 326.07 ms  median 322.00 ms  p99 386.46 ms  max 388.13 ms
    input execution: mean 304.44 ms  median 300.77 ms   (guest runtime)
    nyx overhead:    mean 21.62 ms  median 21.15 ms   (restore + reset + ipc; 56080 dirty pages/exec)
    non-normal results: 0 / 100

  run 5/6:
  snapshot creation (first exec): 452.54 ms
  steady-state (snapshot restore + target run):
    execs/sec: 3.0
    wall time: 33.078 s
    latency:   min 304.95 ms  mean 330.78 ms  median 326.84 ms  p99 385.27 ms  max 388.92 ms
    input execution: mean 308.80 ms  median 304.88 ms   (guest runtime)
    nyx overhead:    mean 21.98 ms  median 21.56 ms   (restore + reset + ipc; 55773 dirty pages/exec)
    non-normal results: 0 / 100

  run 6/6:
  snapshot creation (first exec): 467.49 ms
  steady-state (snapshot restore + target run):
    execs/sec: 3.1
    wall time: 32.410 s
    latency:   min 303.63 ms  mean 324.10 ms  median 319.63 ms  p99 378.77 ms  max 379.88 ms
    input execution: mean 302.34 ms  median 298.85 ms   (guest runtime)
    nyx overhead:    mean 21.76 ms  median 21.11 ms   (restore + reset + ipc; 55997 dirty pages/exec)
    non-normal results: 0 / 100

  aggregate over 6 runs:
    execs/sec: mean 3.1  stddev 0.1  min 3.0  max 3.2
    snapshot:  mean 501.62 ms
    latency (mean across runs):
      min 305.43 ms  mean 324.73 ms  median 320.40 ms  p99 373.15 ms  max 387.71 ms
    input execution (mean across runs): mean 303.22 ms  median 299.15 ms
    nyx overhead (mean across runs):     mean 21.51 ms  median 21.09 ms
    non-normal results: 0 / 600


one log:

smite on  bench-exec-s [$!?] is 📦 v0.0.0 via 🐍 v3.14.5 (.venv) via 🦀 v1.95.0-nightly
❯ docker run --rm \
          -v $PWD/input.bin:/input.bin \
          -e SMITE_INPUT=/input.bin \
          -e RUST_LOG=debug \
          smite-cln-ir /cln-scenario
INFO  [smite_scenarios::targets::bitcoind] Starting bitcoind...
INFO  [smite_scenarios::targets::bitcoind] Waiting for bitcoind to be ready...
INFO  [smite_scenarios::targets::bitcoind] bitcoind is ready
INFO  [smite_scenarios::targets::cln] Starting lightningd...
INFO  [smite_scenarios::targets::cln] Waiting for lightningd to be ready and synced...
INFO  [smite_scenarios::targets::cln] CLN identity pubkey: 03f69adb8fb85a777b68cce352b688c9a29851f699740a1afbeb90567ec1f49275, blockheight: 92
DEBUG [smite_scenarios::targets::cln] lightningd not yet synced (blockheight=92)
INFO  [smite_scenarios::targets::cln] CLN identity pubkey: 03f69adb8fb85a777b68cce352b688c9a29851f699740a1afbeb90567ec1f49275, blockheight: 101
INFO  [smite_scenarios::targets::cln] lightningd synced (blockheight=101)
INFO  [smite_scenarios::targets::cln] Both daemons are running, ready to fuzz
DEBUG [smite_scenarios::scenarios] Handshake complete, received target init
INFO  [smite::scenarios] Scenario initialized! Executing input...
INFO  [smite::runners] Reading input from "/input.bin"
DEBUG [smite_scenarios::scenarios::ir] [39.687µs] Executing IR program (104 instructions, 1173 input bytes)
DEBUG [smite_scenarios::executor] [211.690174ms] MineBlocks: mined 8 block(s)
DEBUG [smite_scenarios::executor] [212.415965ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [212.488401ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [233.108358ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [341.513982ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [341.559421ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [372.123801ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [372.366855ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [372.3926ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [385.800113ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [414.364828ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [414.403199ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [434.942316ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [435.343094ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [435.373543ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [448.952162ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [478.324767ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [478.369374ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [510.323923ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [510.791047ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [510.854209ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [529.211033ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [559.568392ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [559.614349ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [586.047309ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [586.443111ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [586.473142ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [603.924023ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [631.256023ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [631.290115ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [657.551943ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [657.951863ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [657.988818ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [672.85552ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [701.408809ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [701.441891ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [725.582194ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [725.733504ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [725.753194ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [739.079942ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [767.683195ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [767.745953ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [791.750316ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [791.924725ms] SendOpenChannel: 328 bytes
DEBUG [smite_scenarios::executor] [791.950724ms] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [807.070382ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [834.910534ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [834.955198ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [863.047084ms] RecvFundingSigned: received
DEBUG [smite_scenarios::scenarios::ir] [863.388083ms] Program executed successfully
DEBUG [smite_scenarios::scenarios::ir] [863.500691ms] Target responded with pong
INFO  [smite::scenarios] Test case ran successfully!
DEBUG [smite_scenarios::targets::cln] lightningd: requesting graceful shutdown via lightning-cli stop
DEBUG [smite_scenarios::targets::cln] lightningd: waiting for process to exit
DEBUG [smite::process] bitcoind: dropping running process, attempting shutdown
DEBUG [smite::process] bitcoind: sending SIGTERM to process group 7
DEBUG [smite::process] bitcoind: exited with exit status: 0

Claude reason why that polling was faster based on the results:

polling is faster because the blocknotify hook turns one MineBlocks into 8 async lightning-cli spawns that then steal the vCPU from your IO handshakes; the in-process poll does the same block-sync work for almost nothing.

So the hook's cost doesn't land on MineBlocks; it's smeared across the following rounds as CPU contention. That's exactly the shape in the log:

  • Round 1 is hit hardest (+21 ms) — it runs right after the mine, when all 8 syncblocks processes are freshly spawned and fighting for the vCPU.
  • Rounds 2–8 taper to ~+7 ms as that backlog drains.

@erickcestari

erickcestari commented Jul 21, 2026

Copy link
Copy Markdown
Contributor

This is true for MineBlock.

* When a program does actually execute `RecvChannelReady`, perhaps frequent polling is faster than doing the notification.  But for programs that don't execute `RecvChannelReady`, frequent polling is just more CPU overhead for no benefit.  The benchmark was done only against a program that executes `RecvChannelReady`, while the fuzzing run was done across the whole spectrum of inputs that could be generated, most of which never actually execute `RecvChannelReady`.

For an input that never calls MineBLock, the json-rpc notification is faster:

input
v0 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000001)
v1 = DerivePoint(v0)
v2 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000002)
v3 = DerivePoint(v2)
v4 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000003)
v5 = DerivePoint(v4)
v6 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000004)
v7 = DerivePoint(v6)
v8 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000005)
v9 = DerivePoint(v8)
v10 = LoadPrivateKey(0x0000000000000000000000000000000000000000000000000000000000000006)
v11 = DerivePoint(v10)
v12 = LoadChainHashFromContext()
v13 = LoadAmount(100000)
v14 = LoadAmount(0)
v15 = LoadAmount(546)
v16 = LoadAmount(10000000)
v17 = LoadAmount(1000)
v18 = LoadAmount(1)
v19 = LoadFeeratePerKw(2500)
v20 = LoadU16(144)
v21 = LoadU16(483)
v22 = LoadU8(1)
v23 = LoadShutdownScript(Empty)
v24 = LoadChannelType(Anchors)
v25 = LoadChannelId(0x1111111111111111111111111111111111111111111111111111
v26 = BuildOpenChannel(v12, v25, v13, v14, v15, v16, v17, v18, v19, v20, v21, v1, v3, v5, v7, v9, v11, v22, v23, v24)
v27 = SendOpenChannel(v26)
v28 = RecvAcceptChannel(v27)
v29 = ExtractFundingPubkey(v28)
v30 = CreateFundingTransaction(v1, v29, v13, v19)
v31 = SendFundingCreated(v30, v0, v25)
v32 = RecvFundingSigned(v31)
v33 = LoadPrivateKey(0x000000000000000000000000000000000000000000000000000
v34 = LoadFeatures()
v35 = LoadBytes()
v36 = LoadU8(1)
v37 = LoadU8(0)
v38 = LoadU16(144)
v39 = LoadForwardingFee(1000)
v40 = LoadForwardingFee(100)
v41 = LoadAmount(99000000)
v42 = LoadTimestamp(1700000000)
v43 = LoadShortChannelId(1x1x0)
v44 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d6974650000000000000000000000000}(v33, v34, v42, v35)
SendMessage(v44)
v46 = BuildChannelUpdate(v33, v12, v43, v42, v36, v37, v38, v18, v39, v40,
SendMessage(v46)
v48 = LoadTimestamp(1700000001)
v49 = LoadShortChannelId(2x1x0)
v50 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v48, v35)
SendMessage(v50)
v52 = BuildChannelUpdate(v33, v12, v49, v48, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v52)
v54 = LoadTimestamp(1700000002)
v55 = LoadShortChannelId(3x1x0)
v56 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d6974650000000000000000000000000}(v33, v34, v54, v35)
SendMessage(v56)
v58 = BuildChannelUpdate(v33, v12, v55, v54, v36, v37, v38, v18, v39, v40,
SendMessage(v58)
v60 = LoadTimestamp(1700000003)
v61 = LoadShortChannelId(4x1x0)
v62 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v60, v35)
SendMessage(v62)
SendMessage(v62)
v64 = BuildChannelUpdate(v33, v12, v61, v60, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v64)
v66 = LoadTimestamp(1700000004)
v67 = LoadShortChannelId(5x1x0)
v68 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d6974650000000000000000000000000}(v33, v34, v66, v35)
SendMessage(v68)
v70 = BuildChannelUpdate(v33, v12, v67, v66, v36, v37, v38, v18, v39, v40,
SendMessage(v70)
v72 = LoadTimestamp(1700000005)
v73 = LoadShortChannelId(6x1x0)
v74 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v72, v35)
SendMessage(v74)
v76 = BuildChannelUpdate(v33, v12, v73, v72, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v76)
v78 = LoadTimestamp(1700000006)
v79 = LoadShortChannelId(7x1x0)
v80 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d6974650000000000000000000000000}(v33, v34, v78, v35)
SendMessage(v80)
v82 = BuildChannelUpdate(v33, v12, v79, v78, v36, v37, v38, v18, v39, v40,
SendMessage(v82)
v84 = LoadTimestamp(1700000007)
v85 = LoadShortChannelId(8x1x0)
v86 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v84, v35)
SendMessage(v86)
v88 = BuildChannelUpdate(v33, v12, v85, v84, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v88)
v90 = LoadTimestamp(1700000008)
v91 = LoadShortChannelId(9x1x0)
v92 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v90, v35)
SendMessage(v92)
v94 = BuildChannelUpdate(v33, v12, v91, v90, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v94)
v96 = LoadTimestamp(1700000009)
v97 = LoadShortChannelId(10x1x0)
v98 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v96, v35)
SendMessage(v98)
v100 = BuildChannelUpdate(v33, v12, v97, v96, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v100)
v102 = LoadTimestamp(1700000010)
v103 = LoadShortChannelId(11x1x0)
v104 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v102, v35)
SendMessage(v104)
v106 = BuildChannelUpdate(v33, v12, v103, v102, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v106)
v108 = LoadTimestamp(1700000011)
v109 = LoadShortChannelId(12x1x0)
v110 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v108, v35)
SendMessage(v110)
v112 = BuildChannelUpdate(v33, v12, v109, v108, v36, v37, v38, v18, v39, v
SendMessage(v112)
v114 = LoadTimestamp(1700000012)
v115 = LoadShortChannelId(13x1x0)
v116 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v114, v35)
SendMessage(v116)
v118 = BuildChannelUpdate(v33, v12, v115, v114, v36, v37, v38, v18, v39, v
SendMessage(v118)
v120 = LoadTimestamp(1700000013)
v121 = LoadShortChannelId(14x1x0)
v122 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v120, v35)
SendMessage(v122)
v124 = BuildChannelUpdate(v33, v12, v121, v120, v36, v37, v38, v18, v39, v
SendMessage(v124)
v126 = LoadTimestamp(1700000014)
v127 = LoadShortChannelId(15x1x0)
v128 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d6974650000000000000000000000000}(v33, v34, v126, v35)
SendMessage(v128)
v130 = BuildChannelUpdate(v33, v12, v127, v126, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v130)
v132 = LoadTimestamp(1700000015)
v133 = LoadShortChannelId(16x1x0)
v134 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d6974650000000000000000000000000}(v33, v34, v132, v35)
SendMessage(v134)
v136 = BuildChannelUpdate(v33, v12, v133, v132, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v136)
v138 = LoadTimestamp(1700000016)
v139 = LoadShortChannelId(17x1x0)
v140 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v138, v35)
SendMessage(v140)
v142 = BuildChannelUpdate(v33, v12, v139, v138, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v142)
v144 = LoadTimestamp(1700000017)
v145 = LoadShortChannelId(18x1x0)
v146 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d6974650000000000000000000000000}(v33, v34, v144, v35)
SendMessage(v146)
v148 = BuildChannelUpdate(v33, v12, v145, v144, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v148)
v150 = LoadTimestamp(1700000018)
v151 = LoadShortChannelId(19x1x0)
v152 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d6974650000000000000000000000000}(v33, v34, v150, v35)
SendMessage(v152)
v154 = BuildChannelUpdate(v33, v12, v151, v150, v36, v37, v38, v18, v39, v
SendMessage(v154)
v156 = LoadTimestamp(1700000019)
v157 = LoadShortChannelId(20x1x0)
v158 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v156, v35)
SendMessage(v158)
v160 = BuildChannelUpdate(v33, v12, v157, v156, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v160)
v162 = LoadTimestamp(1700000020)
v163 = LoadShortChannelId(21x1x0)
v164 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v162, v35)
SendMessage(v164)
v166 = BuildChannelUpdate(v33, v12, v163, v162, v36, v37, v38, v18, v39, v
SendMessage(v166)
v168 = LoadTimestamp(1700000021)
v169 = LoadShortChannelId(22x1x0)
v170 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d6974650000000000000000000000000}(v33, v34, v168, v35)
SendMessage(v170)
v172 = BuildChannelUpdate(v33, v12, v169, v168, v36, v37, v38, v18, v39, v
SendMessage(v172)
v174 = LoadTimestamp(1700000022)
v175 = LoadShortChannelId(23x1x0)
v176 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v174, v35)
SendMessage(v176)
v178 = BuildChannelUpdate(v33, v12, v175, v174, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v178)
v180 = LoadTimestamp(1700000023)
v181 = LoadShortChannelId(24x1x0)
v182 = BuildNodeAnnouncement{rgb=0x112233, alias=0x736d697465000000000000000000000000000000000000000000000000000000}(v33, v34, v180, v35)
SendMessage(v182)
v184 = BuildChannelUpdate(v33, v12, v181, v180, v36, v37, v38, v18, v39, v40, v41)
SendMessage(v184)
json rpc notification:
Smite Nyx benchmark
  target:      cln/ir
  sharedir:    /tmp/smite-nyx
  input size:  2283 bytes
  iterations:  100
  repeats:     6

  run 1/6:
  snapshot creation (first exec): 48.14 ms
  steady-state (snapshot restore + target run):
    execs/sec: 21.0
    wall time: 4.771 s
    latency:   min 46.48 ms  mean 47.71 ms  median 47.59 ms  p99 49.93 ms  max 50.26 ms
    input execution: mean 41.58 ms  median 41.47 ms   (guest runtime)
    nyx overhead:    mean 6.12 ms  median 6.08 ms   (restore + reset + ipc; 15848 dirty pages/exec)
    non-normal results: 0 / 100

  run 2/6:
  snapshot creation (first exec): 50.40 ms
  steady-state (snapshot restore + target run):
    execs/sec: 19.4
    wall time: 5.156 s
    latency:   min 46.87 ms  mean 51.56 ms  median 51.01 ms  p99 67.78 ms  max 73.24 ms
    input execution: mean 44.92 ms  median 44.33 ms   (guest runtime)
    nyx overhead:    mean 6.65 ms  median 6.50 ms   (restore + reset + ipc; 15854 dirty pages/exec)
    non-normal results: 0 / 100

  run 3/6:
  snapshot creation (first exec): 51.85 ms
  steady-state (snapshot restore + target run):
    execs/sec: 20.3
    wall time: 4.933 s
    latency:   min 46.23 ms  mean 49.33 ms  median 48.08 ms  p99 68.09 ms  max 68.77 ms
    input execution: mean 42.94 ms  median 41.87 ms   (guest runtime)
    nyx overhead:    mean 6.39 ms  median 6.21 ms   (restore + reset + ipc; 15909 dirty pages/exec)
    non-normal results: 0 / 100

  run 4/6:
  snapshot creation (first exec): 47.92 ms
  steady-state (snapshot restore + target run):
    execs/sec: 21.2
    wall time: 4.722 s
    latency:   min 46.10 ms  mean 47.22 ms  median 47.11 ms  p99 49.29 ms  max 49.77 ms
    input execution: mean 41.08 ms  median 40.96 ms   (guest runtime)
    nyx overhead:    mean 6.14 ms  median 6.11 ms   (restore + reset + ipc; 15965 dirty pages/exec)
    non-normal results: 0 / 100

  run 5/6:
  snapshot creation (first exec): 49.78 ms
  steady-state (snapshot restore + target run):
    execs/sec: 21.0
    wall time: 4.765 s
    latency:   min 46.61 ms  mean 47.65 ms  median 47.52 ms  p99 50.30 ms  max 50.34 ms
    input execution: mean 41.48 ms  median 41.34 ms   (guest runtime)
    nyx overhead:    mean 6.16 ms  median 6.16 ms   (restore + reset + ipc; 15442 dirty pages/exec)
    non-normal results: 0 / 100

  run 6/6:
  snapshot creation (first exec): 47.11 ms
  steady-state (snapshot restore + target run):
    execs/sec: 21.3
    wall time: 4.704 s
    latency:   min 46.03 ms  mean 47.04 ms  median 46.77 ms  p99 52.21 ms  max 52.73 ms
    input execution: mean 40.94 ms  median 40.71 ms   (guest runtime)
    nyx overhead:    mean 6.10 ms  median 6.04 ms   (restore + reset + ipc; 15748 dirty pages/exec)
    non-normal results: 0 / 100

  aggregate over 6 runs:
    execs/sec: mean 20.7  stddev 0.7  min 19.4  max 21.3
    snapshot:  mean 49.20 ms
    latency (mean across runs):
      min 46.39 ms  mean 48.42 ms  median 48.01 ms  p99 56.27 ms  max 57.52 ms
    input execution (mean across runs): mean 42.16 ms  median 41.78 ms
    nyx overhead (mean across runs):     mean 6.26 ms  median 6.18 ms
    non-normal results: 0 / 600
50ms polling:
Smite Nyx benchmark
  target:      cln/ir
  sharedir:    /tmp/smite-nyx
  input size:  2283 bytes
  iterations:  100
  repeats:     6

  run 1/6:
  snapshot creation (first exec): 65.22 ms
  steady-state (snapshot restore + target run):
    execs/sec: 19.1
    wall time: 5.247 s
    latency:   min 50.99 ms  mean 52.47 ms  median 52.20 ms  p99 58.85 ms  max 60.49 ms
    input execution: mean 45.51 ms  median 45.23 ms   (guest runtime)
    nyx overhead:    mean 6.96 ms  median 6.90 ms   (restore + reset + ipc; 17870 dirty pages/exec)
    non-normal results: 0 / 100

  run 2/6:
  snapshot creation (first exec): 57.46 ms
  steady-state (snapshot restore + target run):
    execs/sec: 17.9
    wall time: 5.578 s
    latency:   min 47.12 ms  mean 55.78 ms  median 55.33 ms  p99 71.24 ms  max 74.63 ms
    input execution: mean 48.25 ms  median 47.86 ms   (guest runtime)
    nyx overhead:    mean 7.53 ms  median 7.32 ms   (restore + reset + ipc; 18261 dirty pages/exec)
    non-normal results: 0 / 100

  run 3/6:
  snapshot creation (first exec): 53.03 ms
  steady-state (snapshot restore + target run):
    execs/sec: 18.5
    wall time: 5.393 s
    latency:   min 52.65 ms  mean 53.93 ms  median 53.49 ms  p99 57.38 ms  max 58.46 ms
    input execution: mean 46.89 ms  median 46.70 ms   (guest runtime)
    nyx overhead:    mean 7.03 ms  median 6.89 ms   (restore + reset + ipc; 17224 dirty pages/exec)
    non-normal results: 0 / 100

  run 4/6:
  snapshot creation (first exec): 57.19 ms
  steady-state (snapshot restore + target run):
    execs/sec: 17.6
    wall time: 5.697 s
    latency:   min 52.55 ms  mean 56.97 ms  median 56.50 ms  p99 71.23 ms  max 104.90 ms
    input execution: mean 49.53 ms  median 49.09 ms   (guest runtime)
    nyx overhead:    mean 7.43 ms  median 7.16 ms   (restore + reset + ipc; 16772 dirty pages/exec)
    non-normal results: 0 / 100

  run 5/6:
  snapshot creation (first exec): 60.60 ms
  steady-state (snapshot restore + target run):
    execs/sec: 18.1
    wall time: 5.533 s
    latency:   min 48.80 ms  mean 55.33 ms  median 55.08 ms  p99 67.03 ms  max 67.14 ms
    input execution: mean 47.91 ms  median 47.60 ms   (guest runtime)
    nyx overhead:    mean 7.42 ms  median 7.30 ms   (restore + reset + ipc; 17962 dirty pages/exec)
    non-normal results: 0 / 100

  run 6/6:
  snapshot creation (first exec): 55.13 ms
  steady-state (snapshot restore + target run):
    execs/sec: 17.7
    wall time: 5.652 s
    latency:   min 54.76 ms  mean 56.52 ms  median 56.55 ms  p99 59.47 ms  max 59.52 ms
    input execution: mean 49.02 ms  median 49.05 ms   (guest runtime)
    nyx overhead:    mean 7.50 ms  median 7.36 ms   (restore + reset + ipc; 18412 dirty pages/exec)
    non-normal results: 0 / 100

  aggregate over 6 runs:
    execs/sec: mean 18.1  stddev 0.6  min 17.6  max 19.1
    snapshot:  mean 58.11 ms
    latency (mean across runs):
      min 51.15 ms  mean 55.16 ms  median 54.86 ms  p99 64.20 ms  max 70.86 ms
    input execution (mean across runs): mean 47.85 ms  median 47.59 ms
    nyx overhead (mean across runs):     mean 7.31 ms  median 7.16 ms
    non-normal results: 0 / 600

@erickcestari

erickcestari commented Jul 21, 2026

Copy link
Copy Markdown
Contributor

Run the benchmark input through both variants and subtract the coverage difference. Adjust the coverage numbers from the fuzzing result accordingly.

The difference is negible, only +10 lines.

I think it would be valuable to run smite-evaluation.py starting from an empty seed with 10+ trials. That would give us more confidence that the JSON-RPC approach consistently improves overall fuzzing performance, rather than the 2-day fuzzing campaign simply benefiting from a particularly lucky seed. While the higher execution rate is promising, repeating the experiment from scratch would help validate that the improvement is reproducible.

I don't want this to block the PR. Since it has already been approved and is clearly an improvement over the previous 20-second polling interval, I think it's worth merging as-is so we can keep moving forward. We can always follow up with a more thorough evaluation afterward to validate the overall fuzzing performance.

@erickcestari erickcestari left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ACK 6da3fb7

CLN's only polls for new blocks periodically, so scenarios still wait up
to the poll interval after mining a block. Add a `syncblocks` RPC that
forces CLN to poll immediately, and wire it to bitcoind's `-blocknotify`
so CLN syncs as soon as a block is mined.

The RPC complements periodic polling rather than replacing it: concurrent
requests are coalesced, and polling still catches any blocks missed while
CLN is processing a previous chain update.

Signed-off-by: Nishant Bansal <nishant.bansal.282003@gmail.com>
@NishantBansal2003

Copy link
Copy Markdown
Contributor Author

I used the script from #160 on my machine with the same input shared in #156 (review). Here are the results I got:

For the -blocknotify implementation
Smite Nyx benchmark
  target:      cln/ir
  sharedir:    /tmp/smite-bench/smite-nyx
  input size:  410 bytes
  iterations:  100
  repeats:     6

  run 1/6:
  snapshot creation (first exec): 203.15 ms
  steady-state (snapshot restore + target run):
    execs/sec: 5.0
    wall time: 20.122 s
    latency:   min 196.07 ms  mean 201.21 ms  median 201.01 ms  p99 206.01 ms  max 206.82 ms
    input execution: mean 178.81 ms  median 178.55 ms   (guest runtime)
    nyx overhead:    mean 22.40 ms  median 22.31 ms   (restore + reset + ipc; 59514 dirty pages/exec)
    non-normal results: 0 / 100

  run 2/6:
  snapshot creation (first exec): 204.20 ms
  steady-state (snapshot restore + target run):
    execs/sec: 5.0
    wall time: 20.151 s
    latency:   min 193.18 ms  mean 201.51 ms  median 201.51 ms  p99 205.64 ms  max 205.70 ms
    input execution: mean 179.10 ms  median 179.07 ms   (guest runtime)
    nyx overhead:    mean 22.41 ms  median 22.30 ms   (restore + reset + ipc; 59136 dirty pages/exec)
    non-normal results: 0 / 100

  run 3/6:
  snapshot creation (first exec): 200.16 ms
  steady-state (snapshot restore + target run):
    execs/sec: 5.0
    wall time: 20.125 s
    latency:   min 195.55 ms  mean 201.25 ms  median 201.25 ms  p99 207.29 ms  max 207.43 ms
    input execution: mean 178.61 ms  median 178.91 ms   (guest runtime)
    nyx overhead:    mean 22.64 ms  median 22.53 ms   (restore + reset + ipc; 59537 dirty pages/exec)
    non-normal results: 0 / 100

  run 4/6:
  snapshot creation (first exec): 199.51 ms
  steady-state (snapshot restore + target run):
    execs/sec: 5.0
    wall time: 20.154 s
    latency:   min 197.27 ms  mean 201.54 ms  median 201.32 ms  p99 206.25 ms  max 208.03 ms
    input execution: mean 178.96 ms  median 178.75 ms   (guest runtime)
    nyx overhead:    mean 22.58 ms  median 22.48 ms   (restore + reset + ipc; 59526 dirty pages/exec)
    non-normal results: 0 / 100

  run 5/6:
  snapshot creation (first exec): 202.06 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.9
    wall time: 20.224 s
    latency:   min 196.74 ms  mean 202.24 ms  median 202.38 ms  p99 206.93 ms  max 213.29 ms
    input execution: mean 179.63 ms  median 179.82 ms   (guest runtime)
    nyx overhead:    mean 22.61 ms  median 22.43 ms   (restore + reset + ipc; 59530 dirty pages/exec)
    non-normal results: 0 / 100

  run 6/6:
  snapshot creation (first exec): 207.36 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.8
    wall time: 20.723 s
    latency:   min 198.75 ms  mean 207.23 ms  median 207.08 ms  p99 219.41 ms  max 221.95 ms
    input execution: mean 183.48 ms  median 183.76 ms   (guest runtime)
    nyx overhead:    mean 23.75 ms  median 23.23 ms   (restore + reset + ipc; 59952 dirty pages/exec)
    non-normal results: 0 / 100

  aggregate over 6 runs:
    execs/sec: mean 4.9  stddev 0.1  min 4.8  max 5.0
    snapshot:  mean 202.74 ms
    latency (mean across runs):
      min 196.26 ms  mean 202.50 ms  median 202.43 ms  p99 208.59 ms  max 210.54 ms
    input execution (mean across runs): mean 179.77 ms  median 179.81 ms
    nyx overhead (mean across runs):     mean 22.73 ms  median 22.55 ms
    non-normal results: 0 / 600
For the 50ms polling implementation
Smite Nyx benchmark
  target:      cln/ir
  sharedir:    /tmp/smite-bench/smite-nyx
  input size:  410 bytes
  iterations:  100
  repeats:     6

  run 1/6:
  snapshot creation (first exec): 228.55 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.4
    wall time: 22.658 s
    latency:   min 218.73 ms  mean 226.58 ms  median 226.32 ms  p99 235.59 ms  max 237.50 ms
    input execution: mean 203.01 ms  median 202.72 ms   (guest runtime)
    nyx overhead:    mean 23.57 ms  median 23.36 ms   (restore + reset + ipc; 60910 dirty pages/exec)
    non-normal results: 0 / 100

  run 2/6:
  snapshot creation (first exec): 228.03 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.4
    wall time: 22.588 s
    latency:   min 218.39 ms  mean 225.88 ms  median 226.06 ms  p99 234.36 ms  max 234.45 ms
    input execution: mean 202.46 ms  median 202.29 ms   (guest runtime)
    nyx overhead:    mean 23.42 ms  median 23.08 ms   (restore + reset + ipc; 61069 dirty pages/exec)
    non-normal results: 0 / 100

  run 3/6:
  snapshot creation (first exec): 231.48 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.4
    wall time: 22.574 s
    latency:   min 218.92 ms  mean 225.74 ms  median 225.52 ms  p99 232.39 ms  max 233.04 ms
    input execution: mean 202.24 ms  median 202.17 ms   (guest runtime)
    nyx overhead:    mean 23.50 ms  median 23.28 ms   (restore + reset + ipc; 60293 dirty pages/exec)
    non-normal results: 0 / 100

  run 4/6:
  snapshot creation (first exec): 228.30 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.4
    wall time: 22.591 s
    latency:   min 215.97 ms  mean 225.91 ms  median 225.40 ms  p99 238.47 ms  max 238.85 ms
    input execution: mean 202.20 ms  median 202.07 ms   (guest runtime)
    nyx overhead:    mean 23.71 ms  median 23.41 ms   (restore + reset + ipc; 60914 dirty pages/exec)
    non-normal results: 0 / 100

  run 5/6:
  snapshot creation (first exec): 217.78 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.5
    wall time: 22.075 s
    latency:   min 211.86 ms  mean 220.75 ms  median 220.40 ms  p99 229.27 ms  max 232.99 ms
    input execution: mean 197.78 ms  median 197.75 ms   (guest runtime)
    nyx overhead:    mean 22.96 ms  median 22.67 ms   (restore + reset + ipc; 60150 dirty pages/exec)
    non-normal results: 0 / 100

  run 6/6:
  snapshot creation (first exec): 231.83 ms
  steady-state (snapshot restore + target run):
    execs/sec: 4.4
    wall time: 22.760 s
    latency:   min 218.52 ms  mean 227.60 ms  median 227.41 ms  p99 238.67 ms  max 239.99 ms
    input execution: mean 203.89 ms  median 204.06 ms   (guest runtime)
    nyx overhead:    mean 23.71 ms  median 23.53 ms   (restore + reset + ipc; 60944 dirty pages/exec)
    non-normal results: 0 / 100

  aggregate over 6 runs:
    execs/sec: mean 4.4  stddev 0.0  min 4.4  max 4.5
    snapshot:  mean 227.66 ms
    latency (mean across runs):
      min 217.07 ms  mean 225.41 ms  median 225.19 ms  p99 234.79 ms  max 236.14 ms
    input execution (mean across runs): mean 201.93 ms  median 201.84 ms
    nyx overhead (mean across runs):     mean 23.48 ms  median 23.22 ms
    non-normal results: 0 / 600

Some points to note:

  • CLN also spawns a JSON-RPC request to bitcoin-cli to fetch the latest block information, so continuous polling results in many bitcoin-cli RPC calls (which will not be a no-op)
  • Even if there is a burst of -blocknotify events that invoke many lightning-cli syncblocks commands, subsequent calls are effectively no-ops because of the topo->extend_timer guard, which is set to NULL as soon as a block sync is in progress.

I think we need to run more trials over a longer duration to draw stronger conclusions. It would also help to run the benchmark on different machines with no background load. But, based on the design, I still feel that rigorous polling is less suitable than on-demand polling.

BTW, can we now remove the previous CLN 30s -> 2s patch?

I would like to keep that as well. The reason is that once a sync is in progress, all subsequent syncblocks commands become no-ops. If there’s a MineBlock delay where the first sync has almost completed and is updating the CLN state in updates_complete, any subsequent syncblocks request will also be ignored. The next sync will then only occur after the polling interval elapses or another MineBlock event arrives. Since there's a small window where a sync could be missed, I think keeping the 2s poll is reasonable

@morehouse
morehouse merged commit 44f6c39 into lnfuzz:master Jul 22, 2026
5 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants