search

FuelLabs / fuel-indexer

🗃 The Fuel indexer is a standalone service that can be used to index various components of the Fuel blockchain.
https://docs.fuel.network/docs/indexer/
140 stars 66 forks source link

Connection pool timeouts with QA benchmarking #1430

Open deekerno opened 10 months ago

deekerno commented 10 months ago

When running our QA benchmarks, I get an error with database pool timeouts.

Command: cargo run -p fuel-indexer-benchmarks --bin qa -- --network beta-4.fuel.network --runs 10 --blocks 25000 --num-additional-indexers 3

❯ cargo run -p fuel-indexer-benchmarks --bin qa -- --network beta-4.fuel.network --runs 10 --blocks 25000 --num-additional-indexers 3
    Finished dev [unoptimized + debuginfo] target(s) in 0.48s
     Running `target/debug/qa --network beta-4.fuel.network --runs 10 --blocks 25000 --num-additional-indexers 3`
✅ Successfully started the indexer service at PID 98784
2023-10-24T15:33:07.370931Z  INFO fuel_indexer::commands::run: 115: Configuration: IndexerConfig { metering_points: Some(30000000000), log_level: "info", verbose: false, local_fuel_node: false, indexer_net_config: false, fuel_node: FuelClientConfig { host: "beta-4.fuel.network", port: "80" }, web_api: WebApiConfig { host: "localhost", port: "29987", max_body_size: 5242880 }, database: PostgresConfig { user: "postgres", password: "XXXX", host: "localhost", port: "5432", database: "postgres", verbose: "false" }, metrics: false, stop_idle_indexers: false, run_migrations: true, authentication: AuthenticationConfig { enabled: false, strategy: None, jwt_secret: "XXXX", jwt_issuer: None, jwt_expiry: None }, rate_limit: RateLimitConfig { enabled: false, request_count: Some(10), window_size: Some(5) }, replace_indexer: true, accept_sql_queries: false, block_page_size: 20, allow_non_sequential_blocks: true, disable_toolchain_version_check: false }
2023-10-24T15:33:07.372514Z  WARN sqlx_core::postgres::options::parse: 103: ignoring unrecognized connect parameter: verbose=false
2023-10-24T15:33:07.408496Z  INFO sqlx::postgres::notice: 157: identifier "graph_registry_graph_root_version_schema_name_schema_identifier_key" will be truncated to "graph_registry_graph_root_version_schema_name_schema_identifier"
2023-10-24T15:33:07.427230Z  INFO fuel_indexer_lib::utils: 144: Parsed SocketAddr '127.0.0.1:29987' from 'localhost:29987'
2023-10-24T15:33:08.031286Z  INFO qa: 410: Chain head is currently at block number 5753820
2023-10-24T15:33:08.031613Z  INFO qa: 559: Performing 10 runs, indexing 25000 blocks per run.
2023-10-24T15:33:08.031647Z  INFO qa: 562: Start blocks: [0, 575382, 1150764, 1726146, 2301528, 2876910, 3452292, 4027674, 4603056, 5178438]
2023-10-24T15:33:08.041101Z  INFO qa: 576: Deploying additional indexer #1
▹▹▸▹▹ ⏰ Building indexer...                                                                                                                                                                                              Finished release [optimized] target(s) in 0.16s
▪▪▪▪▪ ✅ Build succeeded.                                                                                                                                                                                             Deploying indexer...
▸▹▹▹▹ 🚀 Deploying...                                                                                                                                                                                                 2023-10-24T15:33:17.759894Z  INFO tower_http::trace::on_request: 88: started processing request
2023-10-24T15:33:17.866334Z  INFO fuel_indexer_postgres: 572: Registered Asset(Manifest) with Version(050c3ec8e19c9e65d556a387470466bf63197c485c06a149f9b2bcce1c5ab492) to Indexer(fuellabs.hello_world_0).
2023-10-24T15:33:17.867234Z  INFO fuel_indexer_postgres: 572: Registered Asset(Schema) with Version(780caa2e6464415ff2f96bfc600e6ff4887f206c07d47771ce8646e668aa5c27) to Indexer(fuellabs.hello_world_0).
2023-10-24T15:33:17.868343Z  INFO fuel_indexer_schema::db::manager: 35: SchemaManager creating schema for Indexer(fuellabs.hello_world_0) with Version(780caa2e6464415ff2f96bfc600e6ff4887f206c07d47771ce8646e668aa5c27).
▹▸▹▹▹ 🚀 Deploying...                                                                                                                                                                                                 2023-10-24T15:33:17.901715Z  INFO fuel_indexer_postgres: 572: Registered Asset(Wasm) with Version(611ddfd16ea49ac985628d86e134845a2311f6ed35ed156c8f528e8ea85ebecb) to Indexer(fuellabs.hello_world_0).
2023-10-24T15:33:17.902379Z  INFO tower_http::trace::on_response: 254: finished processing request latency=142482 μs status=200
▪▪▪▪▪ ✅ Successfully deployed indexer.                                                                                                                                                                               2023-10-24T15:33:17.905730Z  INFO fuel_indexer::service: 443: Resuming Indexer(fuellabs.hello_world_0) from block 1
2023-10-24T15:33:18.070851Z  INFO fuel_indexer::database: 219: Database loading schema for Indexer(fuellabs.hello_world_0) with Version(780caa2e6464415ff2f96bfc600e6ff4887f206c07d47771ce8646e668aa5c27).
2023-10-24T15:33:18.075945Z  INFO fuel_indexer::executor: 106: Indexer(fuellabs.hello_world_0) subscribing to Fuel node at beta-4.fuel.network:80
2023-10-24T15:33:18.077022Z  WARN fuel_indexer::executor: 114: No end_block specified in the manifest. Indexer(fuellabs.hello_world_0) will run forever.
2023-10-24T15:33:18.081570Z  INFO sqlx::postgres::notice: 157: trigger "trigger_ensure_block_height_consecutive" for relation "fuellabs_hello_world_0.indexmetadataentity" does not exist, skipping
2023-10-24T15:33:18.904742Z  INFO qa: 576: Deploying additional indexer #2
▹▹▸▹▹ ⏰ Building indexer...                                                                                                                                                                                              Finished release [optimized] target(s) in 0.15s
▪▪▪▪▪ ✅ Build succeeded.                                                                                                                                                                                             Deploying indexer...
▸▹▹▹▹ 🚀 Deploying...                                                                                                                                                                                                 2023-10-24T15:33:28.637981Z  INFO tower_http::trace::on_request: 88: started processing request
2023-10-24T15:33:28.751105Z  INFO fuel_indexer_postgres: 572: Registered Asset(Manifest) with Version(bb9a3b4a71fc8d27fa35aa53230f23b3e3e200258f50e1ddf6d891e2ddf9f6ef) to Indexer(fuellabs.hello_world_1).
2023-10-24T15:33:28.752333Z  INFO fuel_indexer_postgres: 572: Registered Asset(Schema) with Version(780caa2e6464415ff2f96bfc600e6ff4887f206c07d47771ce8646e668aa5c27) to Indexer(fuellabs.hello_world_1).
2023-10-24T15:33:28.753153Z  INFO fuel_indexer_schema::db::manager: 35: SchemaManager creating schema for Indexer(fuellabs.hello_world_1) with Version(780caa2e6464415ff2f96bfc600e6ff4887f206c07d47771ce8646e668aa5c27).
▹▸▹▹▹ 🚀 Deploying...                                                                                                                                                                                                 2023-10-24T15:33:28.782538Z  INFO fuel_indexer_postgres: 572: Registered Asset(Wasm) with Version(1e90867b800eae14bed1a03ddb595dda1a101e187b0a6906e3cbc247c57ab798) to Indexer(fuellabs.hello_world_1).
2023-10-24T15:33:28.783410Z  INFO tower_http::trace::on_response: 254: finished processing request latency=145427 μs status=200
▪▪▪▪▪ ✅ Successfully deployed indexer.                                                                                                                                                                               2023-10-24T15:33:28.787123Z  INFO fuel_indexer::service: 443: Resuming Indexer(fuellabs.hello_world_1) from block 1
2023-10-24T15:33:28.960141Z  INFO fuel_indexer::database: 219: Database loading schema for Indexer(fuellabs.hello_world_1) with Version(780caa2e6464415ff2f96bfc600e6ff4887f206c07d47771ce8646e668aa5c27).
2023-10-24T15:33:28.965444Z  INFO fuel_indexer::executor: 106: Indexer(fuellabs.hello_world_1) subscribing to Fuel node at beta-4.fuel.network:80
2023-10-24T15:33:28.965469Z  WARN fuel_indexer::executor: 114: No end_block specified in the manifest. Indexer(fuellabs.hello_world_1) will run forever.
2023-10-24T15:33:28.969576Z  INFO sqlx::postgres::notice: 157: trigger "trigger_ensure_block_height_consecutive" for relation "fuellabs_hello_world_1.indexmetadataentity" does not exist, skipping
2023-10-24T15:33:29.785878Z  INFO qa: 576: Deploying additional indexer #3
▹▹▹▸▹ ⏰ Building indexer...                                                                                                                                                                                              Finished release [optimized] target(s) in 0.16s
▪▪▪▪▪ ✅ Build succeeded.                                                                                                                                                                                             Deploying indexer...
▸▹▹▹▹ 🚀 Deploying...                                                                                                                                                                                                 2023-10-24T15:33:39.596706Z  INFO tower_http::trace::on_request: 88: started processing request
2023-10-24T15:33:39.705525Z  INFO fuel_indexer_postgres: 572: Registered Asset(Manifest) with Version(8556e09a06135bc777e7b3d419d059a2074fcd87f45df9d008605aac91be5947) to Indexer(fuellabs.hello_world_2).
2023-10-24T15:33:39.706692Z  INFO fuel_indexer_postgres: 572: Registered Asset(Schema) with Version(780caa2e6464415ff2f96bfc600e6ff4887f206c07d47771ce8646e668aa5c27) to Indexer(fuellabs.hello_world_2).
2023-10-24T15:33:39.707325Z  INFO fuel_indexer_schema::db::manager: 35: SchemaManager creating schema for Indexer(fuellabs.hello_world_2) with Version(780caa2e6464415ff2f96bfc600e6ff4887f206c07d47771ce8646e668aa5c27).
▹▸▹▹▹ 🚀 Deploying...                                                                                                                                                                                                 2023-10-24T15:33:39.739697Z  INFO fuel_indexer_postgres: 572: Registered Asset(Wasm) with Version(cde5e8914f51a4f47e161ec2e9e7ec13ead4e12083de1d3f90c6c259f7990ee8) to Indexer(fuellabs.hello_world_2).
2023-10-24T15:33:39.740244Z  INFO tower_http::trace::on_response: 254: finished processing request latency=143538 μs status=200
▪▪▪▪▪ ✅ Successfully deployed indexer.                                                                                                                                                                               2023-10-24T15:33:39.743838Z  INFO fuel_indexer::service: 443: Resuming Indexer(fuellabs.hello_world_2) from block 1
2023-10-24T15:33:39.912870Z  INFO fuel_indexer::database: 219: Database loading schema for Indexer(fuellabs.hello_world_2) with Version(780caa2e6464415ff2f96bfc600e6ff4887f206c07d47771ce8646e668aa5c27).
2023-10-24T15:33:39.918749Z  INFO fuel_indexer::executor: 106: Indexer(fuellabs.hello_world_2) subscribing to Fuel node at beta-4.fuel.network:80
2023-10-24T15:33:39.918773Z  WARN fuel_indexer::executor: 114: No end_block specified in the manifest. Indexer(fuellabs.hello_world_2) will run forever.
2023-10-24T15:33:39.922511Z  INFO sqlx::postgres::notice: 157: trigger "trigger_ensure_block_height_consecutive" for relation "fuellabs_hello_world_2.indexmetadataentity" does not exist, skipping
2023-10-24T15:33:40.743727Z  INFO qa: 594: ✅ All additional indexers deployed.
2023-10-24T15:33:40.743799Z  INFO qa: 608: Run 1 will index block #0 - #25000
▹▸▹▹▹ ⏰ Building indexer...                                                                                                                                                                                              Finished release [optimized] target(s) in 0.16s
▪▪▪▪▪ ✅ Build succeeded.                                                                                                                                                                                             Deploying indexer...
▸▹▹▹▹ 🚀 Deploying...                                                                                                                                                                                                 2023-10-24T15:33:54.776009Z  INFO tower_http::trace::on_request: 88: started processing request
2023-10-24T15:33:54.888052Z  INFO fuel_indexer_postgres: 572: Registered Asset(Manifest) with Version(5b6073a68cf9875cf765a6041c44be5c421d1f74a1639868418a7485c81e1eed) to Indexer(fuellabs.explorer).
2023-10-24T15:33:54.890044Z  INFO fuel_indexer_postgres: 572: Registered Asset(Schema) with Version(bca69dba935a24f511cef34298b2e1e6e8637c29244b208458c3b73ca6088be3) to Indexer(fuellabs.explorer).
2023-10-24T15:33:54.891153Z  INFO fuel_indexer_schema::db::manager: 35: SchemaManager creating schema for Indexer(fuellabs.explorer) with Version(bca69dba935a24f511cef34298b2e1e6e8637c29244b208458c3b73ca6088be3).
▹▸▹▹▹ 🚀 Deploying...                                                                                                                                                                                                 2023-10-24T15:33:54.995331Z  INFO sqlx::postgres::notice: 157: identifier "fk_blocks_transactionidfragments_transactionidfragment_id__transactionidfragment_id" will be truncated to "fk_blocks_transactionidfragments_transactionidfragment_id__tran"
2023-10-24T15:33:54.995784Z  INFO sqlx::postgres::notice: 157: identifier "blocks_transactionidfragments__block_id_transactionidfragment_id_pk" will be truncated to "blocks_transactionidfragments__block_id_transactionidfragment_i"
2023-10-24T15:33:55.017965Z  INFO fuel_indexer_postgres: 572: Registered Asset(Wasm) with Version(da4b01d14b85f4a1122a5f0eb757c737749f4cbf1f64f4a7c52626711fbd9aa1) to Indexer(fuellabs.explorer).
2023-10-24T15:33:55.019199Z  INFO tower_http::trace::on_response: 254: finished processing request latency=243188 μs status=200
▪▪▪▪▪ ✅ Successfully deployed indexer.                                                                                                                                                                               2023-10-24T15:33:55.026801Z  INFO fuel_indexer::service: 443: Resuming Indexer(fuellabs.explorer) from block 1
2023-10-24T15:33:55.226087Z  INFO fuel_indexer::database: 219: Database loading schema for Indexer(fuellabs.explorer) with Version(bca69dba935a24f511cef34298b2e1e6e8637c29244b208458c3b73ca6088be3).
2023-10-24T15:34:25.228439Z ERROR fuel_indexer::executor: 869: Could not instantiate WasmIndexExecutor(fuellabs.explorer): SqlxError(PoolTimedOut).
2023-10-24T15:34:25.228457Z ERROR fuel_indexer::service: 320: Failed to reload Indexer(fuellabs.explorer): WasmExecutionInstantiationError
ra0x3 commented 10 months ago
lostman commented 10 months ago

@ra0x3, I haven't seen this with the QA script. However, I haven't used it enough, and only with standard settings.

The last time I saw an issue like this was when I was doing benchmarking for metering points.

cat /opt/homebrew/var/postgresql@15/postgresql.conf | grep max_connections
max_connections = 100           # (change requires restart)

I don't remember whether this is the default or whether I edited it, so check yours.

We may be creating too many pools. If that's the case we need to make sure we clone a single handle throughout the whole indexer.

Also, we could add connection monitoring to the QA script: https://github.com/FuelLabs/fuel-indexer/issues/1433