hasura / hasura/graphql-engine
High CPU and long graphql-engine server startup times
- Dominant language
- TypeScript
- Stars
- 32.1k
- Forks
- 3k
- PR merge metrics
- PR metrics pending
Description
### Version Information
Server Version: v2.17.1
### Environment
OSS
### What is the current behaviour?
For several weeks, we’ve noticed large CPU spikes on our `graphql-engine` containers whenever we do a metadata apply or metadata reload. This normally happens as part of our CI/CD process when we make changes to migrations or metadata.
Last week, the situation worsened and we haven’t yet found an explanation for it or figured out how to address it. The two primary things we’ve noticed are:
* `graphql-engine` container CPU spikes to 400% on metadata reload (our containers are currently running with 4 CPUs on AWS, and the pod uses all available CPU), sometimes the CPU stays elevated above a normal steady state of ~10%
* the server startup time according to the logs have increased from ~5s or less to consistently over 30s up to around 90s, the logs look like `{"level":"info","detail":{"kind":"server","info":{"message":"starting API server","time_taken":57.231940186}},"type":"startup","timestamp":"2024-09-27T22:01:52.029+0000"}`
The long startup/refresh times cause our containers to become unhealthy frequently, and the high CPU usage is concerning. We’re currently running 20 `graphql-engine` instances in our main AWS region. We’d like to better understand what is happening on the instance during the startup/reload process and whether there’s anything we can change about our setup to help mitigate this.
### What is the expected behaviour?
Small and short CPU spikes during a startup or refresh
### How to reproduce the issue?
N/A
### Screenshots or Screencast
N/A
### Please provide any traces or logs that could help here.
One example of logs where the startup takes a long time, note the 50s between the third log line (`source_catalog_migrate`) and when the server logs the startup completed:
```
{"level":"info","detail":{"kind":"postgres_connection","info":{"database_url":"postgres://","retries":1}},"type":"startup","timestamp":"2024-09-30T13:51:30.673+0000"}
{"level":"info","detail":{"kind":"server_configuration","info":{"enable_allowlist":false,"infer_function_permissions":true,"remote_schema_permissions":false,"jwt_secret":[{"claims_format":"json","claims_namespace":"https://hasura.io/jwt/claims","type":"","issuer":"","key":""}],"websocket_connection_init_timeout":"Refined (Seconds {seconds = 3s})","v1-boolean-null-collapse":true,"enable_telemetry":false,"enabled_log_types":["startup","webhook-log","http-log","websocket-log"],"cors_config":{"disabled":false,"allowed_origins":"*"},"stringify_numeric_types":false,"enabled_apis":["config","pgdump","metadata","graphql"],"websocket_keep_alive":"KeepAliveDelay {unKeepAliveDelay = Refined (Seconds {seconds = 5s})}","transaction_isolation":"ISOLATION LEVEL READ COMMITTED","admin_secret_set":true,"graceful_shutdown_timeout":60,"live_query_options":{"batch_size":100,"refetch_delay":1},"server_host":"HostAny","log_level":"info","use_prepared_statements":true,"enable_metadata_query_logging":false,"enable_console":true,"port":8080,"events_fetch_batch_size":100,"websocket_compression_options":"NoCompression","enable_maintenance_mode":false}},"type":"startup","timestamp":"2024-09-30T13:51:30.673+0000"}
{"level":"info","detail":{"kind":"source_catalog_migrate","info":{"source":"default","message":"source \"default\" is already at the latest catalog version (3)."}},"type":"startup","timestamp":"2024-09-30T13:51:31.761+0000"}
{"level":"info","detail":{"kind":"server","info":{"message":"starting API server","time_taken":50.188699656}},"type":"startup","timestamp":"2024-09-30T13:52:20.841+0000"}
{"level":"info","detail":{"kind":"scheduled_triggers","info":"preparing data"},"type":"startup","timestamp":"2024-09-30T13:52:20.841+0000"}
{"level":"info","detail":{"kind":"event_triggers","info":"starting workers"},"type":"startup","timestamp":"2024-09-30T13:52:20.841+0000"}
{"level":"info","detail":{"kind":"schema-sync","info":{"thread_id":"ThreadId 155","instance_id":"20915651-51c1-4784-b353-954245a228b0","message":"processor thread started"}},"type":"startup","timestamp":"2024-09-30T13:52:20.841+0000"}
{"level":"info","detail":{"kind":"schema-sync","info":{"thread_id":"ThreadId 145","instance_id":"20915651-51c1-4784-b353-954245a228b0","message":"listener thread started"}},"type":"startup","timestamp":"2024-09-30T13:52:20.841+0000"}
{"level":"info","detail":{"kind":"schema-sync","info":"Schema sync enabled. Polling at Refined (Milliseconds {milliseconds = 1s})"},"type":"startup","timestamp":"2024-09-30T13:52:20.841+0000"}
{"level":"info","detail":{"kind":"catalog_migrate","info":"Already at the latest catalog version (47); nothing to do."},"type":"startup","timestamp":"2024-09-30T13:52:20.841+0000"}
{"level":"info","detail":{"kind":"source_catalog_migrate","info":{"source":"default","message":"source \"default\" is already at the latest catalog version (3)."}},"type":"startup","timestamp":"2024-09-30T13:55:41.242+0000"}
{"level":"info","detail":{"kind":"source_catalog_migrate","info":{"source":"default","message":"source \"default\" is already at the latest catalog version (3)."}},"type":"startup","timestamp":"2024-09-30T14:00:44.156+0000"}
{"level":"info","detail":{"kind":"source_catalog_migrate","info":{"source":"default","message":"source \"default\" is already at the latest catalog version (3)."}},"type":"startup","timestamp":"2024-09-30T14:06:34.048+0000"}
{"level":"info","detail":{"kind":"source_catalog_migrate","info":{"source":"default","message":"source \"default\" is already at the latest catalog version (3)."}},"type":"startup","timestamp":"2024-09-30T14:08:12.129+0000"}
```
### Any possible solutions/workarounds you're aware of?
N/A
### Keywords
High CPU
Contributor guide
Research direction
No source files, tests, or reproducible steps are named. Start by examining the metadata reload and startup sequence around the logged gaps between source_catalog_migrate and the API server message, then compare CPU and timing data across affected containers. Done means identifying a reproducible cause and documenting a verified mitigation or expected behavior.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- aws, graphql, postgresql
- Domain
- api, backend, databases, observability, performance
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 30/100