Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
indexer-alt: watermark timestamps and other logging improvements (#20120
) ## Description Track the timestamp associated with a watermark, include it in tracing messages, and introduce gauges to track the timestamps of the latest checkpoint gathered and written to the DB. This change also introduces a couple of other timestamp/watermark related tracing improvements: - Measure watermarks gathered and in DB for the sequential pipeline (previously just tracked the watermark after they were written to the DB). These will usually be the exact same, but may differ if the pipeline needs to retry a write. - Gets rid of the ordering and equality impls for `CommitterWatermark` -- these are no longer required. - Standardise the ordering of watermark traces between the sequential and concurrent pipelines, so that they are easier to compare with each other (they now share a common prefix). - Standardised tracing messages during committer/watermark teardown: Now in each exit edge, we log the reason for the exit, and then a message with the final watermark. ## Test plan Run `sum_obj_types` and `wal_obj_types` with a consistent range of `3600` and note that the difference in their timestamps is roughly an hour (to begin with, it's about 70 minutes): ``` sui$ cargo run -p sui-indexer-alt --release -- \ --database-url 'postgres://postgres:postgrespw@localhost:5432/sui_indexer_alt' \ indexer --remote-store-url 'https://checkpoints.mainnet.sui.io' \ --consistent-range 3600 --pipeline wal_obj_types --pipeline sum_obj_types` Running `/Users/ashokmenon/sui/idx-poc/target/release/sui-indexer-alt --database-url 'postgres://postgres:postgrespw@localhost:5432/sui_indexer_alt' indexer --remote-store-url 'https://checkpoints.mainnet.sui.io' --consistent-range 3600 --pipeline wal_obj_types --pipeline sum_obj_types` 2024-10-31T15:16:26.867221Z INFO sui_indexer_alt::db: Running migrations ... 2024-10-31T15:16:26.889145Z INFO sui_indexer_alt::db: Migrations complete. 2024-10-31T15:16:27.024406Z INFO sui_indexer_alt: Skipping pipeline ev_emit_mod 2024-10-31T15:16:27.024413Z INFO sui_indexer_alt: Skipping pipeline ev_struct_inst 2024-10-31T15:16:27.024414Z INFO sui_indexer_alt: Skipping pipeline kv_checkpoints 2024-10-31T15:16:27.024414Z INFO sui_indexer_alt: Skipping pipeline kv_objects 2024-10-31T15:16:27.024415Z INFO sui_indexer_alt: Skipping pipeline kv_transactions 2024-10-31T15:16:27.024416Z INFO sui_indexer_alt: Skipping pipeline obj_versions 2024-10-31T15:16:27.024416Z INFO sui_indexer_alt: Skipping pipeline tx_affected_objects 2024-10-31T15:16:27.024417Z INFO sui_indexer_alt: Skipping pipeline tx_balance_changes 2024-10-31T15:16:27.024417Z INFO sui_indexer_alt: Skipping pipeline wal_coin_balances 2024-10-31T15:16:27.033550Z INFO sui_indexer_alt: Skipping pipeline sum_coin_balances 2024-10-31T15:16:27.033607Z INFO sui_indexer_alt::pipeline::processor: Starting processor pipeline="wal_obj_types" 2024-10-31T15:16:27.033856Z INFO sui_indexer_alt::pipeline::concurrent::collector: Starting collector pipeline="wal_obj_types" 2024-10-31T15:16:27.033869Z INFO sui_indexer_alt::pipeline::concurrent::committer: Starting committer pipeline="wal_obj_types" 2024-10-31T15:16:27.033983Z INFO sui_indexer_alt: Skipping pipeline sum_packages 2024-10-31T15:16:27.034011Z INFO sui_indexer_alt::pipeline::processor: Starting processor pipeline="sum_obj_types" 2024-10-31T15:16:27.034183Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Starting watermark pipeline="wal_obj_types" watermark=CommitterWatermark { pipeline: "wal_obj_types", epoch_hi_inclusive: 0, checkpoint_hi_inclusive: 0, tx_hi: 0, timestamp_ms_hi_inclusive: 0 } 2024-10-31T15:16:27.034260Z INFO sui_indexer_alt::pipeline::sequential::committer: Starting committer pipeline="sum_obj_types" watermark=CommitterWatermark { pipeline: "sum_obj_types", epoch_hi_inclusive: 0, checkpoint_hi_inclusive: 0, tx_hi: 0, timestamp_ms_hi_inclusive: 0 } 2024-10-31T15:16:27.034305Z INFO sui_indexer_alt: Ingestion range first_checkpoint=0 last_checkpoint=None 2024-10-31T15:16:27.034339Z INFO sui_indexer_alt::metrics: Starting metrics service on 0.0.0.0:9184 2024-10-31T15:16:27.034351Z INFO sui_indexer_alt::ingestion::regulator: Starting ingestion regulator 2024-10-31T15:16:27.034355Z INFO sui_indexer_alt::ingestion::broadcaster: Starting ingestion broadcaster 2024-10-31T15:16:27.541400Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=212 transaction=213 timestamp=2023-04-13 13:28:25.836 UTC updated=true elapsed_ms=5.486208 2024-10-31T15:16:28.043533Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=515 transaction=516 timestamp=2023-04-13 13:36:17.240 UTC updated=true elapsed_ms=5.512666 2024-10-31T15:16:28.538421Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=1017 transaction=1018 timestamp=2023-04-13 13:48:04.584 UTC updated=true elapsed_ms=3.468209 2024-10-31T15:16:29.041788Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=1422 transaction=1423 timestamp=2023-04-13 13:57:11.577 UTC updated=true elapsed_ms=7.184292 2024-10-31T15:16:29.540675Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=1824 transaction=1825 timestamp=2023-04-13 14:05:59.154 UTC updated=true elapsed_ms=5.7144580000000005 2024-10-31T15:16:30.040987Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=2226 transaction=2227 timestamp=2023-04-13 14:14:54.721 UTC updated=true elapsed_ms=5.955416 2024-10-31T15:16:30.539394Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=2630 transaction=2631 timestamp=2023-04-13 14:23:21.636 UTC updated=true elapsed_ms=5.0003340000000005 2024-10-31T15:16:31.035944Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=3142 transaction=3143 timestamp=2023-04-13 14:34:00.192 UTC updated=true elapsed_ms=1.368042 2024-10-31T15:16:31.532346Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=71 transaction=72 timestamp=2023-04-13 13:24:36.662 UTC 2024-10-31T15:16:31.535237Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=3646 transaction=3647 timestamp=2023-04-13 14:45:19.227 UTC updated=true elapsed_ms=0.7080409999999999 2024-10-31T15:16:31.556459Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=103 transaction=104 timestamp=2023-04-13 13:25:35.491 UTC 2024-10-31T15:16:31.605247Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=151 transaction=152 timestamp=2023-04-13 13:27:01.087 UTC 2024-10-31T15:16:31.658676Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=203 transaction=204 timestamp=2023-04-13 13:28:14.431 UTC 2024-10-31T15:16:31.709093Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=251 transaction=252 timestamp=2023-04-13 13:29:41.350 UTC 2024-10-31T15:16:31.774101Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=304 transaction=305 timestamp=2023-04-13 13:31:05.962 UTC 2024-10-31T15:16:31.823847Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=351 transaction=352 timestamp=2023-04-13 13:32:06.748 UTC 2024-10-31T15:16:31.875613Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=404 transaction=405 timestamp=2023-04-13 13:33:26.122 UTC 2024-10-31T15:16:31.923673Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=452 transaction=453 timestamp=2023-04-13 13:34:41.672 UTC 2024-10-31T15:16:31.973523Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=502 transaction=503 timestamp=2023-04-13 13:35:54.245 UTC 2024-10-31T15:16:32.020968Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=553 transaction=554 timestamp=2023-04-13 13:37:12.723 UTC 2024-10-31T15:16:32.034336Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=4147 transaction=4148 timestamp=2023-04-13 14:56:30.470 UTC updated=true elapsed_ms=0.478916 2024-10-31T15:16:32.081115Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=603 transaction=604 timestamp=2023-04-13 13:38:26.226 UTC 2024-10-31T15:16:32.143228Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=657 transaction=658 timestamp=2023-04-13 13:39:32.583 UTC 2024-10-31T15:16:32.201323Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=710 transaction=711 timestamp=2023-04-13 13:40:44.461 UTC 2024-10-31T15:16:32.239715Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=751 transaction=752 timestamp=2023-04-13 13:41:40.955 UTC 2024-10-31T15:16:32.306828Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=803 transaction=804 timestamp=2023-04-13 13:43:00.433 UTC 2024-10-31T15:16:32.351995Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=854 transaction=855 timestamp=2023-04-13 13:44:21.487 UTC 2024-10-31T15:16:32.408044Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=903 transaction=904 timestamp=2023-04-13 13:45:33.468 UTC 2024-10-31T15:16:32.478623Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=963 transaction=964 timestamp=2023-04-13 13:46:48.531 UTC 2024-10-31T15:16:32.517822Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=1004 transaction=1005 timestamp=2023-04-13 13:47:43.997 UTC 2024-10-31T15:16:32.540701Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=4550 transaction=4551 timestamp=2023-04-13 15:05:30.690 UTC updated=true elapsed_ms=5.776375 2024-10-31T15:16:32.574600Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=1052 transaction=1053 timestamp=2023-04-13 13:48:55.253 UTC 2024-10-31T15:16:32.625726Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=1102 transaction=1103 timestamp=2023-04-13 13:49:57.288 UTC 2024-10-31T15:16:32.679135Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=1159 transaction=1160 timestamp=2023-04-13 13:51:06.819 UTC 2024-10-31T15:16:32.729858Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=1203 transaction=1204 timestamp=2023-04-13 13:52:11.201 UTC 2024-10-31T15:16:32.777044Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=1257 transaction=1258 timestamp=2023-04-13 13:53:26.750 UTC 2024-10-31T15:16:32.819603Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=1301 transaction=1302 timestamp=2023-04-13 13:54:17.123 UTC 2024-10-31T15:16:32.870028Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=1351 transaction=1352 timestamp=2023-04-13 13:55:24.124 UTC 2024-10-31T15:16:32.923059Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=1402 transaction=1403 timestamp=2023-04-13 13:56:49.078 UTC 2024-10-31T15:16:32.969159Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=1451 transaction=1452 timestamp=2023-04-13 13:57:56.351 UTC 2024-10-31T15:16:33.034831Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Watermark pipeline="wal_obj_types" epoch=0 checkpoint=5055 transaction=5056 timestamp=2023-04-13 15:16:38.038 UTC updated=true elapsed_ms=1.0442500000000001 2024-10-31T15:16:33.036266Z INFO sui_indexer_alt::pipeline::sequential::committer: Watermark pipeline="sum_obj_types" epoch=0 checkpoint=1501 transaction=1502 timestamp=2023-04-13 13:58:56.227 UTC ^C2024-10-31T15:16:33.091189Z INFO sui_indexer_alt::pipeline::concurrent::collector: Shutdown received, stopping collector pipeline="wal_obj_types" 2024-10-31T15:16:33.091195Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Shutdown received pipeline="wal_obj_types" 2024-10-31T15:16:33.091201Z INFO sui_indexer_alt::ingestion::regulator: Shutdown received, stopping regulator 2024-10-31T15:16:33.091213Z INFO sui_indexer_alt::metrics: Shutdown received, stopping metrics service 2024-10-31T15:16:33.091225Z INFO sui_indexer_alt::pipeline::concurrent::watermark: Stopping watermark task pipeline="wal_obj_types" watermark=CommitterWatermark { pipeline: "wal_obj_types", epoch_hi_inclusive: 0, checkpoint_hi_inclusive: 5055, tx_hi: 5056, timestamp_ms_hi_inclusive: 1681398998038 } 2024-10-31T15:16:33.091410Z INFO sui_indexer_alt::pipeline::concurrent::committer: Batches done, stopping committer pipeline="wal_obj_types" 2024-10-31T15:16:33.091721Z INFO sui_indexer_alt::pipeline::sequential::committer: Shutdown received pipeline="sum_obj_types" 2024-10-31T15:16:33.091725Z INFO sui_indexer_alt::pipeline::sequential::committer: Stopping committer pipeline="sum_obj_types" watermark=CommitterWatermark { pipeline: "sum_obj_types", epoch_hi_inclusive: 0, checkpoint_hi_inclusive: 1546, tx_hi: 1547, timestamp_ms_hi_inclusive: 1681394391225 } 2024-10-31T15:16:33.093829Z INFO sui_indexer_alt::pipeline::processor: Shutdown received, stopping processor pipeline="wal_obj_types" 2024-10-31T15:16:33.094014Z INFO sui_indexer_alt::pipeline::processor: Shutdown received, stopping processor pipeline="sum_obj_types" 2024-10-31T15:16:33.094406Z INFO sui_indexer_alt::ingestion::broadcaster: Shutdown received, stopping ingestion broadcaster 2024-10-31T15:16:33.094513Z INFO sui_indexer_alt: Indexing pipeline gracefully shut down ``` ## Stack - #20089 - #20114 - #20116 - #20117 - #20119 --- ## Release notes Check each box that your changes affect. If none of the boxes relate to your changes, release notes aren't required. For each box you select, include information after the relevant heading that describes the impact of your changes that a user might notice and any actions they must take to implement updates. - [ ] Protocol: - [ ] Nodes (Validators and Full nodes): - [ ] Indexer: - [ ] JSON-RPC: - [ ] GraphQL: - [ ] CLI: - [ ] Rust SDK: - [ ] REST API:
- Loading branch information