Mempool syncing optimizations & fixups #89

shesek · 2024-06-01T14:43:23Z

Optimizations:

Send RPC requests in parallel over multiple TCP connections, without batching (38e73d9)

The number of parallel requests to send can be controlled with a new --daemon-parallelism CLI options (defaults to 4).
Continuously attempt to fetch a full mempool snapshot, keeping whatever transactions we were able to get each time (6a14f40)

Fixups (not strictly necessary for the other changes, but touches on related areas and the previous behavior was wrong):

Don't add transactions with unknown parents to ensure mempool consistency (c60207a)
Make sure the chain tip doesn't move while fetching the mempool (a6a796c)

This will require adjusting bitcoind's rpcthreads and possibly rpcworkqueue configuration options upwards. The default rpcthreads is 4, which would be exhausted by mempool fetching alone (electrs keeps at least one other open connection, and we probably want to allow some room for other clients too).

Based on top of #76. (now merged)

philippem · 2024-06-07T16:52:28Z

Overall this MR seems to greatly improve the initial sync and steady state of electrs alongside a slower bitcoind.

some issues found during testing

the electrum method blockchain.transaction.get will panic on the handling thread if the transaction is not known by electrs (panic starts at https://github.com/shesek/electrs/blob/202405-mempool-sync/src/electrum/server.rs#L375
some requests from electrs to bitcoind will disconnect waiting for recv, at https://github.com/shesek/electrs/blob/202405-mempool-sync/src/daemon.rs#L210
Increasing the rpcthreads parameter in bitcoind does not seem to change this. Electrs itself seems to recover. These recv disconnects happen with different rpcs (usually getrawtransaction, but also getbestblockhash)

RCasatta

utACK a6a796c code review

My comments are mostly styling and perf improv.

Note also I am not that familiar with the overall codebase, but all changes seems reasonable/

src/new_index/schema.rs

src/daemon.rs

src/new_index/mempool.rs

src/daemon.rs

philippem · 2024-06-18T23:33:48Z

* some requests from electrs to bitcoind will disconnect waiting for recv, at https://github.com/shesek/electrs/blob/202405-mempool-sync/src/daemon.rs#L210
  Increasing the `rpcthreads` parameter in bitcoind does not seem to change this. Electrs itself seems to recover. These recv disconnects happen with different rpcs (usually `getrawtransaction`, but also `getbestblockhash`)

While tracing this with wireshark, I observed that electrs sends a request (such as getbestblockhash), and waits for a response. After 30 seconds (and a few TCP Keep-Alive interactions), bitcoind sends a FIN,ACK without any text response. Seems to be some behaviour in bitcoind.

Following Blockstream#89 (comment)

Following Blockstream#89 (comment) and Blockstream#89 (comment)

shesek · 2024-08-06T02:30:28Z

the electrum method blockchain.transaction.get will panic on the handling thread if the transaction is not known by electrs

I was unable to reproduce this, the "missing transaction" message appears to be returned as a JSONRPC error without panicking:

# Client
$ echo '{"id": 1, "method": "blockchain.transaction.get", "params": ["0000000000000000000000000000000000000000000000000000000000000000"]}' | nc 172.17.0.3 60401
{"error":"missing transaction","id":1,"jsonrpc":"2.0"}

# Server logs
TRACE RPC Request("{\"id\": 1, \"method\": \"blockchain.transaction.get\", \"params\": [\"0000000000000000000000000000000000000000000000000000000000000000\"]}\n")
WARN rpc #1 blockchain.transaction.get [String("0000000000000000000000000000000000000000000000000000000000000000")] failed: Error: missing transaction
TRACE RPC Done
# ... keeps running

Seems to be some behaviour in bitcoind.

I'm seeing that behaviour on my local regtest env too.

RCasatta · 2024-08-09T07:28:42Z

utACK a6c181e

Following #89 (comment)

Following Blockstream#89 (comment) and Blockstream#89 (comment)

RCasatta

utACK f3a13e7

philippem · 2024-08-16T16:46:54Z

in analyzing pcap trace between local electrs and local. bitcoin rpc, we see electrs asking for getrawmempool on
3 times in 16 seconds, in a single socket connection. MR needs more analysis/testing.

philippem · 2024-08-16T16:51:33Z

2 issues

repeated requests for full mempool on one thread (correct?)
disconnects are actually coming from electrs, not bitcoind (screenshot of pcap)

philippem · 2024-08-16T16:53:13Z

2024-08-16T09:26:16.938-07:00 - INFO NetworkInfo { version: 270000, subversion: "/Satoshi:27.0.0/", relayfee: 1e-5 }
2024-08-16T09:26:16.938-07:00 - INFO BlockchainInfo { chain: "main", blocks: 857053, headers: 857053, bestblockhash: "00000000000000000003066eeec0d73da4cf50ee6bf7e31f9032145c17ad3d54", pruned: false, verificationprogress: 0.9999971, initialblockdownload: Some(false) }
2024-08-16T09:26:34.141-07:00 - INFO hash=00000000000000000003066eeec0d73da4cf50ee6bf7e31f9032145c17ad3d54 height=857053 @ 2024-08-16T16:18:23Z (2 left to index)
2024-08-16T09:27:14.773-07:00 - INFO Electrum RPC server running on 0.0.0.0:50001
2024-08-16T09:27:14.777-07:00 - INFO REST server running on 0.0.0.0:3001
2024-08-16T09:27:19.773-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.264-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.264-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.267-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.267-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:26.691-07:00 - WARN chain tip moved while updating mempool
2024-08-16T09:27:26.691-07:00 - WARN skipped failed mempool update, trying again in 5 seconds
2024-08-16T09:27:31.692-07:00 - INFO hash=000000000000000000008e575ea9a5b9bcd0591f6b749f975fd679fc8ca23e62 height=857054 @ 2024-08-16T16:26:43Z (1 left to index)

philippem · 2024-08-16T17:22:38Z

following one of the "disconnects":

electrs makes RPC request for "getrawtransaction"
bitcoind responds with data
electrs sits on connection for 30 seconds
bitcoin sends FIN,ACK but electrs does not close
electrs attempts to send more
bitcoin sends RST

electrs should be responding to the FIN,ACK and active, and reopen

philippem

see earlier comments about connection handling.

philippem · 2024-08-16T17:27:48Z

we are also seeing 5 second delays after receiving 500 from bitcoin. The 500 error is used by bitcoin rpc to indicate that the getrawtransaction call requested a non existent tx, which will happen after blocks are mined, and in presence of full rbf. Electrs should consider this case of error by inspecting the details of the json-rpc response, and not wait 5 seconds.

I misread the comment about the disconnects

shesek · 2024-08-20T19:29:05Z

repeated requests for full mempool on one thread ... we see electrs asking for getrawmempool on 3 times in 16 seconds, in a single socket connection

getrawmempool is used to get the list of mempool txids (not txs), and should be sent from the main (sync loop) thread using the same socket (unless it disconnects). It should be sent at least once every 5 seconds, possibly more if additional roundtrips are needed to get a full mempool view.

The 500 error is used by bitcoin rpc to indicate that the getrawtransaction call requested a non existent tx ... Electrs should consider this case of error by inspecting the details of the json-rpc response, and not wait 5 seconds.

This should already be the case. In fact only errors explicitly constructed as an ErrorKind::Connection would trigger the automatic reconnection behavior, other errors will bubble up. RPC errors for "tx not found" are identified and ignored, while other unexpected RPC errors terminate execution (without reconnecting).

disconnects are actually coming from electrs, not bitcoind (screenshot of pcap)

Looking into this.

shesek · 2024-08-28T03:08:17Z

electrs sits on connection for 30 seconds .. bitcoin sends FIN,ACK but electrs does not close

bitcoind appears to close the connection after a period of inactivity, which can be adjusted with the (hidden) config option rpcservertimeout (defaults to 30 seconds).

Adjusting it upwards made the disconnection issues I was experiencing in my local env go away. I also tested with electrs and bitcoind connected over the internet (local electrs connecting to a regtest bitcoind on a vps) and was able to retain open TCP connections with no disconnections for several hours (used every ~2 minutes, with rpcservertimeout set to 5 minutes).

I also tried investigating what's causing electrs not to close immediately in reply to bitcoind's FIN, but do not have an answer yet.

@TheBlueMatt

This actually hurts performance because the batched response has to be bueffered on the bitcoind side, as @TheBlueMatt explains at romanz#373 (comment) Instead, send multiple individual RPC requests in parallel using a thread pool, with a separate RPC TCP connection for each thread. Also see romanz#374

The indexing process was adding transactions into the store so that prevouts funded & spent within the same batch could be looked up via Mempool::lookup_txos(). If the indexing process later failed for any reason, these transactions would remain in the store. With this change, we instead explicitly look for prevouts funded within the same batch, then look for the rest in the chain/mempool indexes and fail if any are missing, without keeping the transactions in the store.

Previously, if any of the mempool transactions were not available because they were evicted between getting the mempool txids and txs themselves, the mempool syncing operation would be aborted and tried again from scratch. With this change, we instead keep whatever transactions we were able to fetch, then get the updated list of mempool txids and re-try fetching missing ones continuously until we're able to get a full snapshot.

- Reduce logging level for bitcoind's JSONRPC response errors These can happen pretty often for missing mempool txs and do not warrant warn-level logging. Unexpected RPC errors will bubble up and be handled appropriately. - Add more verbose logging for mempool syncing

Keep RPC TCP connections open between sync runs and reuse them, to reduce TCP connection initialization overhead.

Following Blockstream#89 (comment) and Blockstream#89 (comment)

shesek · 2024-09-11T00:19:27Z

Rebased and added some more verbose logging for mempool syncing.

philippem · 2024-09-11T16:20:18Z

testing latest commit using local electrs and bitcoind, I set parameters in bitcoin.conf

rpcthreads=16
rpcservertimeout=600
rpcworkqueue=50

I have not seen any "disconnected from daemon while receiving" messages.

RCasatta · 2024-09-21T06:51:23Z

utACK 7a068bf

Following Blockstream#89 (comment)

Following Blockstream#89 (comment) and Blockstream#89 (comment)

RCasatta previously approved these changes Jun 10, 2024

View reviewed changes

shesek added a commit to shesek/electrs that referenced this pull request Aug 6, 2024

Refactor lookup_txos() to use zip()

4f037c4

Following Blockstream#89 (comment)

shesek added a commit to shesek/electrs that referenced this pull request Aug 6, 2024

Avoid recomputing txids when possible

a6c181e

Following Blockstream#89 (comment) and Blockstream#89 (comment)

shesek dismissed RCasatta’s stale review via a6c181e August 6, 2024 02:23

shesek force-pushed the 202405-mempool-sync branch from a6a796c to a6c181e Compare August 6, 2024 02:23

RCasatta mentioned this pull request Aug 9, 2024

Use rust bitcoin deserialize_hex when upgrading version #94

Open

RCasatta previously approved these changes Aug 13, 2024

View reviewed changes

philippem pushed a commit that referenced this pull request Aug 13, 2024

Refactor lookup_txos() to use zip()

fca4867

Following #89 (comment)

shesek added a commit to shesek/electrs that referenced this pull request Aug 13, 2024

Avoid recomputing txids when possible

f3a13e7

Following Blockstream#89 (comment) and Blockstream#89 (comment)

shesek dismissed RCasatta’s stale review via f3a13e7 August 13, 2024 20:03

shesek force-pushed the 202405-mempool-sync branch from a6c181e to f3a13e7 Compare August 13, 2024 20:03

RCasatta previously approved these changes Aug 14, 2024

View reviewed changes

philippem marked this pull request as draft August 16, 2024 16:47

philippem requested review from philippem and RCasatta August 16, 2024 16:49

philippem requested changes Aug 16, 2024

View reviewed changes

shesek added 2 commits September 11, 2024 02:48

shesek added 5 commits September 11, 2024 02:48

Make sure the chain tip doesn't move while fetching the mempool

e3481c7

Reuse RPC threads and TCP connections

aee32b6

Keep RPC TCP connections open between sync runs and reuse them, to reduce TCP connection initialization overhead.

Avoid recomputing txids when possible

7a068bf

Following Blockstream#89 (comment) and Blockstream#89 (comment)

shesek force-pushed the 202405-mempool-sync branch from f3a13e7 to 7a068bf Compare September 11, 2024 00:18

philippem marked this pull request as ready for review September 12, 2024 22:31

This was referenced Sep 25, 2024

Make lookup_txos error instead of panic #116

Closed

Add /txs endpoint to submit tx packages #119

Open

Tx cache #110

Draft

RCasatta approved these changes Sep 29, 2024

View reviewed changes

philippem approved these changes Oct 1, 2024

View reviewed changes

RCasatta merged commit 5168871 into Blockstream:new-index Oct 1, 2024
2 checks passed

rem1-dev pushed a commit to rem1-dev/electrs that referenced this pull request Nov 5, 2024

Refactor lookup_txos() to use zip()

00484e8

Following Blockstream#89 (comment)

rem1-dev pushed a commit to rem1-dev/electrs that referenced this pull request Nov 5, 2024

Avoid recomputing txids when possible

1081711

Following Blockstream#89 (comment) and Blockstream#89 (comment)

rem1-dev pushed a commit to rem1-dev/electrs that referenced this pull request Nov 6, 2024

Avoid recomputing txids when possible

ea061ce

Following Blockstream#89 (comment) and Blockstream#89 (comment)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Mempool syncing optimizations & fixups #89

Mempool syncing optimizations & fixups #89

shesek commented Jun 1, 2024 •

edited

Loading

philippem commented Jun 7, 2024

RCasatta left a comment

philippem commented Jun 18, 2024

shesek commented Aug 6, 2024 •

edited

Loading

RCasatta commented Aug 9, 2024

RCasatta left a comment

philippem commented Aug 16, 2024

philippem commented Aug 16, 2024

philippem commented Aug 16, 2024

philippem commented Aug 16, 2024

philippem left a comment

philippem commented Aug 16, 2024

shesek commented Aug 20, 2024 •

edited

Loading

shesek commented Aug 28, 2024 •

edited

Loading

shesek commented Sep 11, 2024

philippem commented Sep 11, 2024

RCasatta commented Sep 21, 2024 •

edited

Loading

Mempool syncing optimizations & fixups #89

Mempool syncing optimizations & fixups #89

Conversation

shesek commented Jun 1, 2024 • edited Loading

philippem commented Jun 7, 2024

RCasatta left a comment

Choose a reason for hiding this comment

philippem commented Jun 18, 2024

shesek commented Aug 6, 2024 • edited Loading

RCasatta commented Aug 9, 2024

RCasatta left a comment

Choose a reason for hiding this comment

philippem commented Aug 16, 2024

philippem commented Aug 16, 2024

philippem commented Aug 16, 2024

philippem commented Aug 16, 2024

philippem left a comment

Choose a reason for hiding this comment

philippem commented Aug 16, 2024

shesek commented Aug 20, 2024 • edited Loading

shesek commented Aug 28, 2024 • edited Loading

shesek commented Sep 11, 2024

philippem commented Sep 11, 2024

RCasatta commented Sep 21, 2024 • edited Loading

shesek commented Jun 1, 2024 •

edited

Loading

shesek commented Aug 6, 2024 •

edited

Loading

shesek commented Aug 20, 2024 •

edited

Loading

shesek commented Aug 28, 2024 •

edited

Loading

RCasatta commented Sep 21, 2024 •

edited

Loading