Repository navigation
feat(chart-data): emit StatsD timers for each phase of the chart data API - #45862
mistercrunch wants to merge 3 commits into
Conversation
… API Break /api/v1/chart/data latency down by phase so slow dashboards can be attributed to auth, query context construction, the results cache, SQL generation, database connect/execute/fetch, post-processing, or response serialization. Adds best-effort, monotonic-clock helpers in superset/utils/timing_metrics.py and documents every key. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
github-actions
Bot
added
api
✅ Deploy Preview for superset-docs-preview ready!
To edit notification comments on pull requests, go to your Netlify project configuration. |
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## master #45862 +/- ##
==========================================
+ Coverage 84.69% 84.71% +0.02%
==========================================
Files 3069 3070 +1
Lines 205494 205784 +290
Branches 48314 48344 +30
==========================================
+ Hits 174038 174330 +292
+ Misses 28165 28158 -7
- Partials 3291 3296 +5
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
rebenitez1802
left a comment
rebenitez1802
left a comment
There was a problem hiding this comment.
Approve: no regressions — responses, permissions, OpenAPI and every existing metric match master end to end — but four of the new timers misreport what the docs say they measure; small, validated fixes below and inline (non-blocking).
🟡 Medium — chart_data.query.total / payload_assembly leave out result materialization
Both are emitted at the end of get_df_payload_result (superset/common/query_context_processor.py:513-517), but _materialize_full_payload (superset/common/query_actions.py:217: records/CSV/XLSX conversion, dtype extraction, the AUTO-currency query) runs after that, untimed. On a 100k-row table chart StatsD reports payload_assembly 0.6 ms and total 657 ms, while the CHART_DATA_INCLUDE_TIMING sidecar — described as their counterpart — reports 306 ms and 963 ms. Fix: wrap the call at query_actions.py:217 in timed("chart_data.query.materialize") and add a docs row (then total 714 + materialize 281 ≈ sidecar 995 ms), or emit both timers from the QueryTiming built in get_query_results_with_timing.
🟡 Medium — chart_data.cache.set times writes that never happen
timed("chart_data.cache.set") (superset/common/utils/query_cache_manager.py:161) also fires when set_and_log_cache returns early — the default NullCache and a -1 timeout — so every query on a default install adds a ~0.01 ms sample, contrary to "actual writes only". test_cache_set_timed_only_for_cache_writes codifies this: its success case runs against the unit-test NullCache and still expects a sample. Fix: time only attempted writes (timeout != CACHE_DISABLED_TIMEOUT and not isinstance(_cache[region].cache, NullCache), else nullcontext()); gating on result_persisted instead would also hide slow failed writes.
| timed("chart_data.response.serialize"), | ||
| event_logger.log_context(f"{self.__class__.__name__}.json_dumps"), |
There was a problem hiding this comment.
🟡 Medium — chart_data.response.serialize includes the event-log DB write
timed() is the outer context manager here, so it also covers the exit of event_logger.log_context, which with the default DBEventLogger is a synchronous INSERT + COMMIT to the metadata DB. With a 50 ms metadata write the timer reads ~52–55 ms while json.dumps takes ~0.03 ms (database.execute already nests correctly inside log_context("execute_sql")). Swapping the order fixes it:
| timed("chart_data.response.serialize"), | |
| event_logger.log_context(f"{self.__class__.__name__}.json_dumps"), | |
| event_logger.log_context(f"{self.__class__.__name__}.json_dumps"), | |
| timed("chart_data.response.serialize"), |
| from superset.utils.timing_metrics import ( | ||
| elapsed_ms, | ||
| emit_timing, | ||
| metric_suffix, | ||
| now_ns, | ||
| timed, | ||
| ) |
There was a problem hiding this comment.
Goes with the database.connect suggestion below, which leaves elapsed_ms, emit_timing and now_ns unused:
| from superset.utils.timing_metrics import ( | |
| elapsed_ms, | |
| emit_timing, | |
| metric_suffix, | |
| now_ns, | |
| timed, | |
| ) | |
| from superset.utils.timing_metrics import metric_suffix, timed |
| engine_suffix = metric_suffix(self.db_engine_spec.engine) | ||
| connect_start_ns = now_ns() | ||
| with self.get_raw_connection(catalog=catalog, schema=schema) as conn: | ||
| emit_timing( | ||
| f"database.connect.{engine_suffix}", elapsed_ms(connect_start_ns) | ||
| ) |
There was a problem hiding this comment.
🟡 Medium — database.connect.<engine> is never emitted when connecting fails
The timer is emitted inside the with body, so a failed or timed-out connect emits nothing: a 2 s postgres connect timeout produced no database.connect.postgresql while chart_data.query.data_acquisition read 2032 ms, contrary to "slow failures such as timeouts stay visible". Timing only the context manager's entry via ExitStack (same pattern as _open_with_oauth2_retry) fixes it; OAuth2 handling for connect and body errors is unchanged, and the rest of the block keeps its indentation. Apply together with the import suggestion at the top of the file.
| engine_suffix = metric_suffix(self.db_engine_spec.engine) | |
| connect_start_ns = now_ns() | |
| with self.get_raw_connection(catalog=catalog, schema=schema) as conn: | |
| emit_timing( | |
| f"database.connect.{engine_suffix}", elapsed_ms(connect_start_ns) | |
| ) | |
| engine_suffix = metric_suffix(self.db_engine_spec.engine) | |
| with ExitStack() as stack: | |
| with timed(f"database.connect.{engine_suffix}"): | |
| conn = stack.enter_context( | |
| self.get_raw_connection(catalog=catalog, schema=schema) | |
| ) |
… cache work
- Emit chart_data.query.{total,planning,data_acquisition,payload_assembly}
even when a phase raises; time database.connect.* for failed attempts.
- Count a missing results-cache backend as cache.bypass, not cache.miss.
- Scope database.dataframe.* to DataFrame construction, excluding the
mutator and post_process_df.
- Time result materialization as chart_data.query.materialize and document it.
- Only time chart_data.cache.set when a write is attempted (not for
NullCache or a disabled timeout).
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
468ce7e to
b1c937c
Compare
SUMMARY
When a dashboard is slow, the first question is always: is the time spent in Superset, or in the database? Today Superset can't answer that from its own metrics.
/api/v1/chart/datais where nearly all dashboard load time goes: every chart on a dashboard makes at least one call to it. The endpoint already has a single StatsD timer (ChartDataRestApi.data.time), but that one number mixes together:NullPool),Without a breakdown, "the dashboard is slow" turns into guesswork. Nobody can tell whether to tune the warehouse, the cache, a chart's post-processing, or Superset itself. The timer also has no tags, so cache hits, misses and async
202responses all land in the same distribution, and a fast cache hit can hide a slow query.This PR adds one StatsD timer per meaningful phase of the request, plus cache outcome counters. Each phase's duration can then be read directly instead of guessed by subtracting overlapping timers.
How a chart data request flows, and where each metric fires
flowchart TD A[HTTP request] --> B["@protect: auth + RBAC<br/><code>chart_data.auth</code>"] B --> C["Saved chart lookup (GET only)<br/><code>chart_data.chart_lookup</code><br/><code>chart_data.dashboard_filters</code>"] C --> D["Build query context<br/><code>chart_data.query_context.build</code>"] D --> E["Object-level access checks<br/><code>chart_data.query_context.validate</code>"] E -->|async_mode, cache miss| F["Schedule tasks, return 202<br/><code>chart_data.async.submit</code>"] E -->|sync| G["Run all queries<br/><code>chart_data.command.execute</code>"] G --> T["Contribution totals (if needed)<br/><code>chart_data.totals</code>"] G --> Q["Per query: <code>chart_data.query.total</code>"] Q --> Q1["Plan + cache key<br/><code>chart_data.query.planning</code><br/><code>chart_data.cache.key</code>"] Q1 --> Q2["Cache read<br/><code>chart_data.cache.get</code><br/><code>chart_data.cache.hit | miss | bypass</code>"] Q2 -->|hit| Q5 Q2 -->|miss or bypass| Q3["Datasource query<br/><code>chart_data.query.data_acquisition</code>"] Q3 --> S1["SQL generation<br/><code>datasource.query.sql_generation</code>"] S1 --> S2["<code>database.connect.<engine></code><br/><code>database.execute.<engine></code><br/><code>database.fetch.<engine></code><br/><code>database.dataframe.<engine></code>"] S2 --> S3["<code>datasource.query.normalize</code><br/><code>datasource.query.time_offsets</code><br/><code>datasource.query.post_processing</code>"] S3 --> Q4["Annotations + cache write<br/><code>chart_data.query.annotations</code><br/><code>chart_data.cache.set</code>"] Q4 --> Q5["Payload assembly<br/><code>chart_data.query.payload_assembly</code>"] Q5 --> R["JSON response<br/><code>chart_data.response.serialize</code>"]The async path (
GLOBAL_ASYNC_QUERIES) runs the same per-query code in the Celery worker. Allchart_data.query.*,chart_data.cache.*,datasource.*anddatabase.*metrics are emitted from the worker too, so async dashboards get the same breakdown.Metrics added
All timers are in milliseconds and measured with a monotonic clock (
perf_counter_ns).chart_data.auth@protect: authentication + permission check, before the handler runschart_data.chart_lookupGET /chart/<pk>/data/only)chart_data.dashboard_filtersfilters_dashboard_idonly)chart_data.query_context.buildQueryContext, including loading the datasourcechart_data.query_context.validateraise_for_accesscheckschart_data.async.submit202)chart_data.command.executechart_data.totalschart_data.query.totalchart_data.query.planningchart_data.cache.keychart_data.cache.getchart_data.cache.hit/.miss/.bypassbypass= forced refresh or cache disabledchart_data.query.data_acquisitionchart_data.query.annotationschart_data.cache.setchart_data.query.payload_assemblychart_data.response.serializedatasource.query.sql_generationdatasource.query.normalizedatasource.query.time_offsetsdatasource.query.post_processingdatabase.connect.<engine>database.execute.<engine>cursor.execute()for one statement. For drivers whoseexecuteblocks until completion, this covers the database's queueing, compilation and execution, plus networkdatabase.fetch.<engine>database.dataframe.<engine>Questions these metrics answer
database.execute.<engine>+database.fetch.<engine>againstchart_data.query.totaland the endpoint timer.chart_data.cache.get(is reading the cache itself slow?), and atchart_data.cache.set(are large result writes delaying responses?).database.connect.<engine>shows this. It matters withNullPooland engines whose authentication handshake is costly.datasource.query.post_processing,datasource.query.time_offsetsandchart_data.response.serialize.chart_data.authandchart_data.query_context.validate.Design decisions
BaseStatsLoggerhas no tag support, so any dimension has to live in the key. The only dimension added is the DB engine name (db_engine_spec.engine), which comes from a small fixed set and is normalized to one key segment. No chart, dashboard, user, database or tenant IDs, no SQL, and no cache keys appear in metric names. That keeps cardinality bounded and avoids leaking anything sensitive.chart_data.*is the chart data API and query context processor.datasource.*anddatabase.*are shared query execution code, so they are honestly named for what they measure and will also cover other features that use the same path.database.executeis insidechart_data.query.data_acquisition, which is insidechart_data.query.total. Compare within one level; don't sum across levels.cache.getis skipped on bypass,data_acquisitionandannotationsonly fire when the datasource is actually queried,cache.setonly fires on real writes, andtotalsandpost_processingonly fire when there is work to do.@protect()mark entry and handler start. They usefunctools.wraps, so FAB's_permission_name,_urlsand OpenAPI docstrings are kept.DummyStatsLoggeronly debug-logs.Existing telemetry, for context
ChartDataRestApi.{data,get_data}.timeand the.success/.warning/.errorcounters are unchanged.loading_from_cache,loaded_from_cache,loaded_from_sourceandset_cache_keyare unchanged. The newchart_data.cache.*counters add an explicit miss and bypass signal.CHART_DATA_INCLUDE_TIMING(per-query timing in the response body) is unchanged; these metrics are its aggregate counterpart. Theexecute_sqlevent-log entry is also unchanged.Out of scope (possible follow-ups)
BEFORE/AFTER SCREENSHOTS OR ANIMATED GIF
N/A (backend metrics only).
TESTING INSTRUCTIONS
nc -ul 8125or a localstatsd/Datadog agent:DummyStatsLoggerand set the log level toDEBUGto see[stats_logger] (timing) ...lines.superset.chart_data.*,superset.datasource.query.*andsuperset.database.*.<engine>timers, and achart_data.cache.missper query.chart_data.cache.hitandchart_data.cache.get, but nodatabase.*timers.chart_data.cache.bypassand nochart_data.cache.get.Unit tests cover the helpers (ms conversion, failures swallowed, timing on exceptions, key normalization, the auth decorator pair), the cache hit/miss/bypass outcomes and per-phase timers in the processor, cache-write timing for actual writes only, and the ordered
database.connect/execute/fetch/dataframetimers inDatabase.get_df.ADDITIONAL INFORMATION
Docs: new "Chart data latency metrics" section in
docs/admin_docs/configuration/event-logging.mdx.🤖 Generated with Claude Code