Request timeout on first call to Cube API after server's start-up

[postnow-stripe]

Problem

Request timeout on first call to Cube API after server's start-up.

Context

We use Cube API to generate SQL. We don't connect Cube to Trino cluster, but use it solely for SQL generation purposes. Our data model contains ~200 different cubes and uses Jinja templates extensively. We don’t have pre-aggregations defined.

We simply call Cube REST API endpoint to get SQL:

curl -H "Authorization: <REDACTED>" -G --data-urlencode 'query=SELECT MEASURE(example.example) FROM example' --data-urlencode 'format=sql'    http://localhost:4000/cubejs-api/v1/sql

Logs

The first call to the API hangs for a while (>5 minutes and frequently times out), but consequent calls are very fast (~200ms on average).

Logs says that the schema compilation process usually takes about 20 seconds:
cube_api-1  | 2025-07-22 18:09:07,717 TRACE [cubejs_native::transport] [transport] Meta ->
cube_api-1  | {"message":"Compiling schema","version":"default_schema_version","requestId":"2db7c219-a64c-4d0b-b675-b27b75431e4d-span-1"}
cube_api-1  | 2025-07-22 18:09:13,931 TRACE [cubejs_native::template::entry] Restart jinja workers
cube_api-1  | 2025-07-22 18:09:13,931 TRACE [cubejs_native::template::workers] Closing jinja thread, id: 0, threadId: ThreadId(12)
cube_api-1  | 2025-07-22 18:09:19,742 TRACE [cubejs_native::template::entry] Restart jinja workers
cube_api-1  | 2025-07-22 18:09:19,742 TRACE [cubejs_native::template::workers] Closing jinja thread, id: 0, threadId: ThreadId(14)
cube_api-1  | {"message":"Compiling schema completed","version":"default_schema_version","requestId":"2db7c219-a64c-4d0b-b675-b27b75431e4d-span-1","duration":17982}

What happens next is a mystery. It builds a plan (fast), rewrites a query (fast) and then hangs without any hints what’s going on:

cube_api-1  | 2025-07-22 18:09:25,789 TRACE [cubejs_native::transport] [transport] Meta <- Some("e9ab9c4d-9c2f-4119-aa9b-a0ab107b9531") <hidden>
cube_api-1  | 2025-07-22 18:09:25,792 DEBUG [cubesql::compile::parser] Parsing SQL: SELECT MEASURE(example.example) FROM example
cube_api-1  | 2025-07-22 18:09:25,793 TRACE [cubejs_native::transport] [transport] Meta ->
cube_api-1  | 2025-07-22 18:09:25,871 TRACE [cubejs_native::transport] [transport] Meta <- Some("e9ab9c4d-9c2f-4119-aa9b-a0ab107b9531") <hidden>
cube_api-1  | 2025-07-22 18:09:25,874 DEBUG [cubesql::compile::query_engine] Initial Plan: Projection: #measure(example.example)
cube_api-1  |   Aggregate: groupBy=[[]], aggr=[[measure(#example.example)]]
cube_api-1  |     TableScan: example projection=None
cube_api-1  | 2025-07-22 18:09:25,886 DEBUG [cubesql::compile::rewrite::rewriter] Iterations: [Iteration { egraph_nodes: 22, egraph_classes: 22, applied: {"cube-scan": 1}, hook_time: 2.08e-7, search_time: 4.9334e-5, apply_time: 7.8916e-5, rebuild_time: 5.75e-6, total_time: 0.00013475, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 38, egraph_classes: 37, applied: {"push-down-aggregate": 1, "wrapper-cube-scan-wrap": 1}, hook_time: 4.1e-8, search_time: 3.6958e-5, apply_time: 7.95e-5, rebuild_time: 5e-6, total_time: 0.000121875, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 57, egraph_classes: 54, applied: {"member-pushdown-replacer-aggregate-group-tail": 1, "member-pushdown-replacer-aggregate-aggr-push-down": 1, "wrapper-finalize-pull-up-replacer": 1, "wrapper-push-down-aggregate-to-cube-scan": 1}, hook_time: 8.3e-8, search_time: 4.7708e-5, apply_time: 5.8417e-5, rebuild_time: 1.925e-5, total_time: 0.000125708, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 89, egraph_classes: 81, applied: {"member-pushdown-replacer-column-find-matching-old-member-udaf-fun": 1, "wrapper-aggregate-aggr-expr-push-down": 1, "wrapper-aggregate-group-expr-tail": 1}, hook_time: 4.2e-8, search_time: 0.00010575, apply_time: 5.1666e-5, rebuild_time: 5.541e-6, total_time: 0.000163334, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 96, egraph_classes: 85, applied: {"member-pushdown-replacer-udaf-fun": 1, "wrapper-member-pushdown-replacer-udaf-fun": 1}, hook_time: 4.2e-8, search_time: 6.725e-5, apply_time: 7.5792e-5, rebuild_time: 7.875e-6, total_time: 0.000151416, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 104, egraph_classes: 91, applied: {"push-down-projection": 1, "wrapper-cube-scan-wrap": 1, "wrapper-aggregate-aggr-expr-pull-up": 1}, hook_time: 4.1e-8, search_time: 6.4417e-5, apply_time: 5.675e-5, rebuild_time: 4.875e-6, total_time: 0.000126417, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 113, egraph_classes: 97, applied: {"member-pushdown-replacer-projection-push-down": 1, "wrapper-finalize-pull-up-replacer": 1, "wrapper-pull-up-to-cube-scan-non-wrapped-select": 1, "wrapper-push-down-projection-to-cube-scan": 1}, hook_time: 4.2e-8, search_time: 4.9708e-5, apply_time: 8.4584e-5, rebuild_time: 6.583e-6, total_time: 0.000141208, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 136, egraph_classes: 116, applied: {"member-pushdown-replacer-column-find-matching-old-member-column": 1, "wrapper-finalize-pull-up-replacer": 1, "wrapper-push-down-projection-to-cube-scan": 1, "wrapper-projection-expr-push-down": 1}, hook_time: 4.2e-8, search_time: 6.7792e-5, apply_time: 5.4709e-5, rebuild_time: 6.792e-6, total_time: 0.000129625, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 152, egraph_classes: 128, applied: {"member-pushdown-replacer-column-measure": 1, "wrapper-projection-expr-push-down": 1, "wrapper-push-down-column": 1}, hook_time: 4.2e-8, search_time: 7.0875e-5, apply_time: 5e-5, rebuild_time: 1.6208e-5, total_time: 0.000137459, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 1, stop_reason: None }, Iteration { egraph_nodes: 156, egraph_classes: 127, applied: {"wrapper-cube-scan-wrap": 1, "wrapper-projection-expr-pull-up": 1, "wrapper-push-down-column": 1}, hook_time: 4.2e-8, search_time: 8.2791e-5, apply_time: 5.6333e-5, rebuild_time: 5.791e-6, total_time: 0.00014525, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 163, egraph_classes: 131, applied: {"wrapper-finalize-pull-up-replacer": 1, "wrapper-pull-up-to-cube-scan-non-wrapped-select": 1, "wrapper-projection-expr-pull-up": 1}, hook_time: 4.1e-8, search_time: 5.0583e-5, apply_time: 4.1709e-5, rebuild_time: 4.875e-6, total_time: 9.75e-5, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 168, egraph_classes: 133, applied: {"wrapper-finalize-pull-up-replacer": 1, "wrapper-pull-up-to-cube-scan-non-trivial-wrapped-select": 1}, hook_time: 4.2e-8, search_time: 3.6375e-5, apply_time: 4.0875e-5, rebuild_time: 4.417e-6, total_time: 8.1959e-5, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 172, egraph_classes: 135, applied: {"wrapper-finalize-pull-up-replacer": 1}, hook_time: 4.1e-8, search_time: 2.6042e-5, apply_time: 3.7125e-5, rebuild_time: 4.042e-6, total_time: 6.7542e-5, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: None }, Iteration { egraph_nodes: 173, egraph_classes: 135, applied: {}, hook_time: 4.1e-8, search_time: 3.1167e-5, apply_time: 3.6083e-5, rebuild_time: 3.75e-6, total_time: 7.1458e-5, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: Some(Saturated) }]
cube_api-1  | 2025-07-22 18:09:25,887 DEBUG [cubesql::compile::rewrite::rewriter] Iterations: [Iteration { egraph_nodes: 173, egraph_classes: 135, applied: {}, hook_time: 8.3e-8, search_time: 0.000340083, apply_time: 6.7375e-5, rebuild_time: 3.708e-6, total_time: 0.000411666, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: Some(Saturated) }]
cube_api-1  | 2025-07-22 18:09:25,897 DEBUG [cubesql::compile::rewrite::rewriter] Iterations: [Iteration { egraph_nodes: 173, egraph_classes: 135, applied: {}, hook_time: 1.25e-7, search_time: 0.00038, apply_time: 8.975e-5, rebuild_time: 5.083e-6, total_time: 0.000475375, data: IterInfo { debug_qtrace_eclasses: None }, n_rebuilds: 0, stop_reason: Some(Saturated) }]
cube_api-1  | 2025-07-22 18:09:25,897 DEBUG [cubesql::compile::rewrite::rewriter] Best cost: CubePlanCost {
cube_api-1  |     replacers: 0,
cube_api-1  |     penalized_ast_size_outside_wrapper: 0,
cube_api-1  |     table_scans: 0,
cube_api-1  |     empty_wrappers: 0,
cube_api-1  |     non_detected_cube_scans: 0,
cube_api-1  |     unwrapped_subqueries: 0,
cube_api-1  |     member_errors: 0,
cube_api-1  |     ungrouped_aggregates: 0,
cube_api-1  |     non_pushed_down_window: 0,
cube_api-1  |     non_pushed_down_grouping_sets: 0,
cube_api-1  |     non_pushed_down_limit_sort: 0,
cube_api-1  |     joins: 0,
cube_api-1  |     wrapper_nodes: 0,
cube_api-1  |     ast_size_outside_wrapper: 0,
cube_api-1  |     wrapped_select_non_push_to_cube: 0,
cube_api-1  |     wrapped_select_ungrouped_scan: 0,
cube_api-1  |     filters: 0,
cube_api-1  |     structure_points: 0,
cube_api-1  |     zero_members_wrapper: 0,
cube_api-1  |     filter_members: 0,
cube_api-1  |     cube_members: 1,
cube_api-1  |     errors: 0,
cube_api-1  |     time_dimensions_used_as_dimensions: 0,
cube_api-1  |     max_time_dimensions_granularity: 0,
cube_api-1  |     cube_scan_nodes: 1,
cube_api-1  |     ast_size_without_alias: 16,
cube_api-1  |     ast_size: 16,
cube_api-1  |     ast_size_inside_wrapper: 0,
cube_api-1  |     ungrouped_nodes: 0,
cube_api-1  | }
cube_api-1  | 2025-07-22 18:09:25,897 DEBUG [cubesql::compile::rewrite::rewriter] Best: (CubeScan
cube_api-1  |   CubeScanAliasToCube([("example", "example")])
cube_api-1  |   (CubeScanMembers (Measure example.example (ColumnExpr #example.measure(example.example))))
cube_api-1  |   CubeScanFilters
cube_api-1  |   CubeScanOrder
cube_api-1  |   None
cube_api-1  |   None
cube_api-1  |   false
cube_api-1  |   false
cube_api-1  |   false
cube_api-1  |   false
cube_api-1  |   CubeScanJoinHints([]))
cube_api-1  | 2025-07-22 18:09:25,898 DEBUG [cubesql::compile::query_engine] Rewrite: CubeScan: request={
cube_api-1  |   "measures": [
cube_api-1  |     "example.example"
cube_api-1  |   ],
cube_api-1  |   "dimensions": [],
cube_api-1  |   "segments": [],
cube_api-1  |   "order": []
cube_api-1  | }
cube_api-1  | {"message":"Query Rewrite","query":{"measures":["example.example"],"dimensions":[],"segments":[],"order":[]},"securityContext":{...},"requestId":"e52dbc8d-8d98-407b-8e4e-fa1db51c6b5b-span-1","appName":"NULL","protocol":"postgres","apiType":"sql"}
cube_api-1  | {"message":"Query Rewrite completed","normalizedQueries":[{"measures":["example.example"],"dimensions":[],"segments":[],"order":[],"timezone":"UTC","filters":[],"timeDimensions":[]}],"duration":1,"query":{"measures":["example.example"],"dimensions":[],"segments":[],"order":[]},"securityContext":{...},"requestId":"e52dbc8d-8d98-407b-8e4e-fa1db51c6b5b-span-1","appName":"NULL","protocol":"postgres","apiType":"sql"}

After 5 minutes, it returns a response back to the client:

cube_api-1  | {"message":"Outgoing network usage","service":"api-http","bytes":1387,"path":"/cubejs-api/v1/sql","securityContext":{...},"requestId":"0047acfe-cb2b-42fd-8d46-c1648af4d289-span-1"}

Suspect?

I’m not very familiar with the codebase of a Cube, but I was able to measure execution time and noticed that most of the time for the first API request, Cube spends when calling methods related to pre-aggregations, despite there’s none defined in our data model.

Calls:

const getSqlFn = () => compilers.compiler.withQuery(sqlGenerator, () => ({
      external: sqlGenerator.externalPreAggregationQuery(),
      sql: sqlGenerator.buildSqlAndParams(exportAnnotatedSql),
      lambdaQueries: **sqlGenerator.buildLambdaQuery()**,
      timeDimensionAlias: sqlGenerator.timeDimensions[0] && sqlGenerator.timeDimensions[0].unescapedAliasName(),
      timeDimensionField: sqlGenerator.timeDimensions[0] && sqlGenerator.timeDimensions[0].dimension,
      order: sqlGenerator.order,
      cacheKeyQueries: sqlGenerator.cacheKeyQueries(),
      preAggregations: **sqlGenerator.preAggregations.preAggregationsDescription()**,
      dataSource: sqlGenerator.dataSource,
      aliasNameToMember: sqlGenerator.aliasNameToMember,
      rollupMatchResults: includeDebugInfo ?
        **sqlGenerator.preAggregations.rollupMatchResultDescriptions()** : undefined,
      canUseTransformedQuery: **sqlGenerator.preAggregations.canUseTransformedQuery()**
    }));

When I commented out some pre-aggregation code, the API became very responsive and returned results back immediately on the first API call, once the schema compilation step was done.

Is there a way to investigate it and to opt-out of the expensive pre-aggregation calls for case when we only need a SQL generation logic?

Set-up

Cube v.1.3.39

Environment variables:

CUBESQL_STREAM_MODE=true
CUBEJS_API_SECRET=secret
CUBEJS_SCHEMA_PATH=models
CUBEJS_PG_SQL_PORT=15432
CUBEJS_SQL_USER=user 
CUBEJS_SQL_PASSWORD=password
CUBEJS_LOG_LEVEL=trace

[igorlukanin]

@postnow-stripe Thanks for filing this issue!

May I also ask you to provide a sample data model and a runnable Docker Compose configuration that demonstrates the behavior from the issue? I believe the data model can be generated or templated in this case. I'm asking about that so that we'll be reproducing and investigation exactly the issue you've reported—so it would be great to have some common ground here.