Adjust chain.runtime_events indexes #500
Conversation
Andrew7234
requested review from
aefhm,
mitjat,
pro-wh and
ptrus
as code owners
| @@ -0,0 +1,13 @@ | |||
| BEGIN; | |||
|
|
|||
| DROP INDEX chain.ix_runtime_related_transactions_address; -- This index is a prefix of an existing index and therefore unnecessary | |||
| @@ -129,10 +129,10 @@ CREATE TABLE chain.runtime_events | |||
| evm_log_signature BYTEA CHECK (octet_length(evm_log_signature) = 32) | |||
| ); | |||
| CREATE INDEX ix_runtime_events_round ON chain.runtime_events(runtime, round); -- for sorting by round, when there are no filters applied | |||
| CREATE INDEX ix_runtime_events_tx_hash ON chain.runtime_events(tx_hash); | |||
| CREATE INDEX ix_runtime_events_tx_eth_hash ON chain.runtime_events(tx_eth_hash); | |||
| CREATE INDEX ix_runtime_events_tx_hash ON chain.runtime_events/*USING hash */(tx_hash); -- updated in 13_runtime_indexes.up.sql | |||
There was a problem hiding this comment.
is this the first we're using /* ... */ comments? is this postgresql specific syntax?
There was a problem hiding this comment.
tests don't complain about it 💁
There was a problem hiding this comment.
Thank you for the informative PR description!
The new query plan still looked somewhat convoluted, and the timing somewhat slow. I don't understand why that Gather merge is taking so long; in my understanding it's a merge sort of 348 rows, but looks like my understanding is off :/
Anyway, it made me think of this uglier but much faster query. The outer SELECT is a copy paste of the old query. The main trick is in the comment of the subselect, which is a copy paste of the old query but limited to the events table:
explain analyze SELECT
evs.round,
evs.tx_index,
evs.tx_hash,
evs.tx_eth_hash,
evs.timestamp,
evs.type,
evs.body,
evs.evm_log_name,
evs.evm_log_params,
tokens.symbol,
CASE -- NOTE: There are three queries that use this CASE via copy-paste; edit both if changing.
WHEN tokens.token_type = 20 THEN 'ERC20'
WHEN tokens.token_type = 721 THEN 'ERC721'
ELSE NULL -- Our openapi spec doesn't allow us to output this, but better this than a null value (which causes nil dereference)
END AS token_type,
tokens.decimals
FROM
-- This subselect selects all appropriate events AND APPLIES SORTING AND LIMITING. Sorting and limiting now, rather than after the joins,
-- is much more efficient. It is valid because the subsequent joins will keep the number of rows unchanged, but Postgres cannot know this,
-- so we force the execution plan with this subselect.
(SELECT
evs.round,
evs.tx_index,
evs.tx_hash,
evs.tx_eth_hash,
evs.timestamp,
evs.type,
evs.body,
evs.evm_log_name,
evs.evm_log_params
FROM chain.runtime_events as evs
WHERE evs.runtime='sapphire' and evs.evm_log_signature=decode('ddf252ad1be2c89b69c2b068fc378daa952ba7f163c4a11628f55a4df523b3ef', 'hex') order by evs.round desc, evs.tx_index, evs.type, evs.body::text limit 1000 offset 0
) evs
-- Look up the oasis-style address derived from evs.body.address.
-- The derivation is just a keccak hash and we could theoretically compute it instead of looking it up,
-- but the implementing/importing the right hash function in postgres would take some work.
LEFT JOIN chain.address_preimages AS preimages ON
DECODE(evs.body ->> 'address', 'base64')=preimages.address_data AND
preimages.context_identifier = 'oasis-runtime-sdk/address: secp256k1eth' AND
preimages.context_version = 0
LEFT JOIN chain.evm_tokens as tokens ON
('sapphire'=tokens.runtime) AND --------- !!!!!!!!!!!!!!! CHANGE from orig query: hardcoded runtime because we don't have access to evs.runtime. We could, but there's no point in passing it through from the subquery.
(preimages.address=tokens.token_address);
Here's the query plan:
Hash Left Join (cost=1928.05..1964.40 rows=1000 width=556) (actual time=40.071..42.296 rows=1000 loops=1)
Hash Cond: ((preimages.address)::text = (tokens.token_address)::text)
-> Hash Left Join (cost=1917.67..1946.40 rows=1000 width=565) (actual time=39.902..41.567 rows=1000 loops=1)
Hash Cond: (decode((evs.body ->> 'address'::text), 'base64'::text) = preimages.address_data)
-> Limit (cost=1474.21..1476.71 rows=1000 width=550) (actual time=34.454..34.748 rows=1000 loops=1)
-> Sort (cost=1474.21..1492.18 rows=7190 width=550) (actual time=34.452..34.640 rows=1000 loops=1)
Sort Key: evs.round DESC, evs.tx_index, evs.type, ((evs.body)::text)
Sort Method: top-N heapsort Memory: 1778kB
-> Index Scan using ix_runtime_events_evm_log_signature on runtime_events evs (cost=0.43..1079.99 rows=7190 width=550) (actual time=0.027..25.520 rows=6626 loops=1)
Index Cond: (evm_log_signature = '\xddf252ad1be2c89b69c2b068fc378daa952ba7f163c4a11628f55a4df523b3ef'::bytea)
Filter: (runtime = 'sapphire'::runtime)
-> Hash (cost=325.22..325.22 rows=9460 width=68) (actual time=5.313..5.314 rows=9385 loops=1)
Buckets: 16384 Batches: 1 Memory Usage: 1045kB
-> Seq Scan on address_preimages preimages (cost=0.00..325.22 rows=9460 width=68) (actual time=0.021..3.422 rows=9385 loops=1)
Filter: ((context_identifier = 'oasis-runtime-sdk/address: secp256k1eth'::text) AND ((context_version)::integer = 0))
Rows Removed by Filter: 20
-> Hash (cost=7.19..7.19 rows=255 width=57) (actual time=0.147..0.147 rows=260 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 32kB
-> Seq Scan on evm_tokens tokens (cost=0.00..7.19 rows=255 width=57) (actual time=0.012..0.086 rows=260 loops=1)
Filter: ('sapphire'::runtime = runtime)
Planning Time: 0.592 ms
Execution Time: 42.448 ms
(22 rows)
This was on staging testnet, which doesn't have your new ix_runtime_events_evm_log_signature yet; presumably, the new index should make it only faster still?
Uh oh ... alarmingly, on prod mainnet, both my query and the original query take forever; I interrupted the EXPLAIN after a minute. This shouldn't happen regardless of whether the new index is here, I thought?
I was going to suggest that if you'd rather keep this PR's scope limited, let's go ahead and merge in these new indexes: they LGTM, thank you for them, and as discussed above, they should be helpful regardless of which of the two query variants we use.
But in the view of those super long queries in prod mainnet, I think this deserves another more holistic look before pushing a partial solution, because we seem to not understand what's going on so the partial solution might actually be harmful.
Still your call on whether the revised query belongs in this PR or a separate one, and if the latter, whether you'd prefer me to push it out or if you're happy to do it yourself.
Edit edit: In prod mainnet, the same query went from 3 minutes to 1 second after rerunning a few times 😖 . And both my and original query need 1 second because they don't use the evm_signature filter. I don't know why. I'll stop here.
| @@ -129,10 +129,10 @@ CREATE TABLE chain.runtime_events | |||
| evm_log_signature BYTEA CHECK (octet_length(evm_log_signature) = 32) | |||
| ); | |||
| CREATE INDEX ix_runtime_events_round ON chain.runtime_events(runtime, round); -- for sorting by round, when there are no filters applied | |||
| CREATE INDEX ix_runtime_events_tx_hash ON chain.runtime_events(tx_hash); | |||
| CREATE INDEX ix_runtime_events_tx_eth_hash ON chain.runtime_events(tx_eth_hash); | |||
| CREATE INDEX ix_runtime_events_tx_hash ON chain.runtime_events/*USING hash */(tx_hash); -- updated in 13_runtime_indexes.up.sql | |||
|
oh it's because the query wants some quite sophisticated ordering. the index is only sorted down to round, so it doesn't know about how the tx_index and event type are ordered within that. so it's sorting all matching events, ever |
But "all matching events" in this case is ... only 348 of them ( |
|
no it's this one from the events side of the join |
|
Thanks for the thorough testing!
Hm the index wasn't applied to either production or staging yet, so it makes sense that the original query is slow. Seems like your optimized query would also benefit from the index, so I tested it out. Original (current) query with new Optimized query with index: The optimized query(20-40ms) is consistently faster than the original (90-120ms), so I think overall I'm leaning towards adding it, just not in this PR. The optimized query is more complex but the performance speedup certainly seems worth it.
Probably the postgres cache. I confirmed that both queries slow significantly (> 1min) after removing the index. |
remove extraneous index add comments
Andrew7234
force-pushed
the
andrew7234/runtime-events-api-speedup
branch
from
3782435 to
9994acf
Compare
@lukaw3d found that the
/eventsendpoint was slow when a related account was not specified in the query (rel=oasis12345). Theexplain analyzeof the query:The issue is that postgres is scanning backwards by round and filtering by
evm_log_signature, and is not using the existing index onevm_log_signaturebecause of theorder by round desc. This PR updates the index to be more useful to the query. No other queries use this index.New timings
I also updated the tx_hash and eth_tx_hash indexes to better match the ones in
chain.runtime_transactions