RPC call duration skyrocketed after upgrade to v2.7.2-stable

[lacasian]

• Parity Ethereum version: v2.7.2
• Operating system: Linux
• Installation: dockerhub
• Fully synchronized: yes
• Network: ethereum mainnet
• Restarted: yes

Configuration:

  - --auto-update=none
  - --mode=active
  - --tracing=on
  - --pruning=archive
  - --db-compaction=ssd
  - --scale-verifiers
  - --num-verifiers=6
  - --jsonrpc-server-threads=5
  - --jsonrpc-threads=5
  - --cache-size=8000

After we upgraded from v2.5.13-stable to v2.7.2-stable, we've seen a huge spike in RPC call execution durations.

Here's a screenshot from our monitoring:

[dvdplm]

Thank you for the report, this looks worrying. Roughly how many RPC calls per second are you making here?

[lacasian]

@dvdplm It looks very worrying, indeed.

The RPC calls we're executing can be seen in the screenshot I posted. We're executing those for every new block. In the case of eth_getTransactionReceipt we're doing a batch call for all transactions included in the block. Also worth mentioning that those calls are executed in sequential order, not in parallel.

That being said + considering the avg durations for the calls after the upgrade, I'd say it's way less than 1 RPC per second.

[lacasian]

Small update here: it looks like it went back to normal after a while. Will continue to monitor it and see if the problems come back.

[ordian]

@kwix we have changed a few rocksdb parameters from 2.5 to 2.7, it could be a background rocksdb process doing a compaction, could you show us your rocksdb log file?
~/.local/share/io.parity.ethereum/chains/ethereum/db/<your account>/overlayrecent/db/LOG

[lacasian]

Hey @ordian !

This path ......./overlayrecent/db/LOG does not exist on my machine.
24h later, the RPC duration is still normal. Will close the issue for now.

[ordian]

@kwix sorry, I meant s/overlayrecent/archive (depends on your --pruning flag)
~/.local/share/io.parity.ethereum/chains/ethereum/db/<your account>/archive/db/LOG

[lacasian]

Here's the log you asked for:
LOG.log

From what I can see, it starts today but the event happened 2 days ago.

Thanks for looking into this!

[ordian]

Right, have you restarted the node today?

you can see a bunch of compaction_finished events in the log, my suspicion is that due to rocksdb cache settings change in 2.7 it triggered the whole db compaction/reorganization on disk, so all RPC requests were blocked on I/O. My recommendation is to add some monitoring for I/O (if you don't have it already).

If you encounter this issue again, please let us know.

[valer-cara]

Indeed the step-up in latency is correlated with a compaction at start time.

We zoomed out a little and noticed that there are very similar load increases correlated with container restarts in the past as well; so I think we can safely assume there's no correlation with this upgrade :)

Thanks! Closing this one 🙌