lightning icon indicating copy to clipboard operation
lightning copied to clipboard

crates: improved json codec decoding performance

Open daywalker90 opened this issue 1 month ago • 1 comments

I wanted to benchmark my plugin on a big node so i made use of the giantnode script which sadly crashed at ~660k payments because my /tmp was full but whatever. I noticed again that the rust crates take way longer for rpc calls than on the cli even when using .call_raw(). I already know it was because of the MultiLineCodec but wasn't sure if it could be made faster and if so why it was so slow. So naturally i asked an LLM and it basically oneshotted something like this PR.

I tested this with a small plugin:

let now = Instant::now();

let _raw_pays: serde_json::Value = rpc.call_raw("listpays", &json!({})).await?;

log::info!("Got raw pays in {} ms", now.elapsed().as_millis());

let now = Instant::now();

let cln_rpc::Response::ListPays(_enum_pays) = rpc
    .call_enum(Request::ListPays(requests::ListpaysRequest {
        bolt11: None,
        index: None,
        limit: None,
        payment_hash: None,
        start: None,
        status: None,
    }))
    .await?
else {
    return Err(anyhow!("Unexpected response"));
};

log::info!("Got enum pays in {} ms", now.elapsed().as_millis());

let now = Instant::now();

let _typed_pays = rpc
    .call_typed(&requests::ListpaysRequest {
        bolt11: None,
        index: None,
        limit: None,
        payment_hash: None,
        start: None,
        status: None,
    })
    .await?;

log::info!("Got typed pays in {} ms", now.elapsed().as_millis());

let now = Instant::now();

for _ in 0..10_000 {
    let _getinfo: serde_json::Value = rpc.call_raw("getinfo", &json!({})).await?;
}

log::info!("Got 10k raw getinfos in {} ms", now.elapsed().as_millis());

let now = Instant::now();

for _ in 0..10_000 {
    let _getinfo = rpc.call_typed(&requests::GetinfoRequest {}).await?;
}

log::info!("Got 10k typed getinfos in {} ms", now.elapsed().as_millis());

which gives the following results:

Before:

2025-11-24T15:45:51.514Z INFO    plugin-decode-test: Got raw pays in 77028 ms
2025-11-24T15:47:14.078Z INFO    plugin-decode-test: Got enum pays in 82520 ms
2025-11-24T15:48:32.355Z INFO    plugin-decode-test: Got typed pays in 80817 ms
2025-11-24T15:48:33.159Z INFO    plugin-decode-test: Got 10k raw getinfos in 804 ms
2025-11-24T15:48:34.369Z INFO    plugin-decode-test: Got 10k typed getinfos in 861 ms

After:

2025-11-24T15:39:39.087Z INFO    plugin-decode-test: Got raw pays in 9850 ms
2025-11-24T15:39:50.632Z INFO    plugin-decode-test: Got enum pays in 14032 ms
2025-11-24T15:40:03.255Z INFO    plugin-decode-test: Got typed pays in 12622 ms
2025-11-24T15:40:04.030Z INFO    plugin-decode-test: Got 10k raw getinfos in 775 ms
2025-11-24T15:40:05.218Z INFO    plugin-decode-test: Got 10k typed getinfos in 843 ms

So from ~81s down to ~13s for typed calls.

For comparison on the cli it's basically equal to the "after, raw" pays: ~10s

Tested on debian 13 with an AMD Ryzen 5900x and 64GB RAM

daywalker90 avatar Nov 24 '25 16:11 daywalker90

Very cool, thanks @daywalker90, that quadratic explosion is my fault 🙇

cdecker avatar Nov 27 '25 13:11 cdecker