Speed up uni-watcher-info block processing time

[dboreham]

Per-block processing time for uni-info-watcher on Rhino is in excess of 1 second. Here's a recent sample from its log file:

2022-11-03T14:45:40.879Z vulcanize:job-runner Total block process time (13744625): 522ms
2022-11-03T14:45:41.392Z vulcanize:job-runner Total block process time (13744626): 513ms
2022-11-03T14:45:45.793Z vulcanize:job-runner Total block process time (13744627): 4401ms
2022-11-03T14:45:53.497Z vulcanize:job-runner Total block process time (13744628): 7704ms
2022-11-03T14:45:54.797Z vulcanize:job-runner Total block process time (13744629): 1300ms
2022-11-03T14:45:56.012Z vulcanize:job-runner Total block process time (13744630): 1215ms
2022-11-03T14:45:56.840Z vulcanize:job-runner Total block process time (13744631): 828ms
2022-11-03T14:46:02.681Z vulcanize:job-runner Total block process time (13744632): 5841ms
2022-11-03T14:46:02.938Z vulcanize:job-runner Total block process time (13744633): 257ms
2022-11-03T14:46:03.668Z vulcanize:job-runner Total block process time (13744634): 730ms
2022-11-03T14:46:04.580Z vulcanize:job-runner Total block process time (13744635): 912ms
2022-11-03T14:46:06.078Z vulcanize:job-runner Total block process time (13744636): 1498ms
2022-11-03T14:46:09.457Z vulcanize:job-runner Total block process time (13744637): 3379ms
2022-11-03T14:46:09.877Z vulcanize:job-runner Total block process time (13744638): 420ms
2022-11-03T14:46:11.976Z vulcanize:job-runner Total block process time (13744639): 2099ms
2022-11-03T14:46:12.923Z vulcanize:job-runner Total block process time (13744640): 947ms
2022-11-03T14:46:13.970Z vulcanize:job-runner Total block process time (13744641): 1047ms
2022-11-03T14:46:14.200Z vulcanize:job-runner Total block process time (13744642): 230ms
2022-11-03T14:46:14.553Z vulcanize:job-runner Total block process time (13744643): 352ms
2022-11-03T14:46:18.789Z vulcanize:job-runner Total block process time (13744644): 4237ms
2022-11-03T14:46:19.658Z vulcanize:job-runner Total block process time (13744645): 869ms
2022-11-03T14:46:20.860Z vulcanize:job-runner Total block process time (13744646): 1202ms

[dboreham]

On Rhino at present the container is : uniswap-merge-watcher-only-uni-info-watcher-job-runner-1

[dboreham]

SELECT CAST(eth.log_cids.block_number as Text), eth.log_cids.header_id as block_hash,
			eth.log_cids.leaf_cid, eth.log_cids.index, eth.log_cids.rct_id, eth.log_cids.address,
			eth.log_cids.topic0, eth.log_cids.topic1, eth.log_cids.topic2, eth.log_cids.topic3, eth.log_cids.log_data,
			data, eth.receipt_cids.leaf_cid as cid, eth.receipt_cids.post_status, eth.receipt_cids.tx_id AS tx_hash
				FROM eth.log_cids, eth.receipt_cids, public.blocks
				WHERE eth.log_cids.rct_id = receipt_cids.tx_id
				AND eth.log_cids.header_id = receipt_cids.header_id
				AND eth.log_cids.block_number = receipt_cids.block_number
				AND log_cids.leaf_mh_key = blocks.key
				AND log_cids.block_number = blocks.block_number
				AND receipt_cids.header_id = $1 AND receipt_cids.block_number = $2 ORDER BY log_cids.index

[dboreham]

Docker compose at:

/srv/watchers/uniswap-merge/uniswap-v3-info-watcher/uniswap-merge-watcher-only

[dboreham]

Initial findings:

1. There do not appear to be any heavy database queries executed (nothing more than 200ms) in either the ipld db or the watcher db's.
2. Watcher logs indicate the most costly operations are a set of calls to uniswap contract methods (see below).
3. Operations that were believed to be already optimized (e.g. fetch a single block) are still quite slow (120ms) according to logs.

[dboreham]

One example of a slow contract method call:

From watcher logs we see:

time:indexer#_updateFeeVars-eth_call_for_positions: 2.278s

Manually tracing the code this path goes through a GraphQL request to the uni-watcher, thence to ipld-eth-server via JSON-RPC and should finally hit the ipld-db as a fetch of one or more state values (associated Solidity here: https://github.com/vulcanize/uniswap-watcher-ts/blob/main/packages/uni-watcher/src/indexer.ts#L347)

It is hard to think why this would take 2+ seconds.