mistercrunch opened a new pull request, #45862:
URL: https://github.com/apache/superset/pull/45862
### 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/data` is 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:
- authentication and permission checks,
- building the query context and object-level access checks,
- results-cache lookups, which are mostly cheap, combined with full database
round trips,
- SQL generation and Jinja rendering,
- opening a database connection (by default one per query, via `NullPool`),
- the database's own queueing and execution time,
- fetching rows and building DataFrames,
- pandas post-processing, time comparison queries, and contribution totals,
- writing the result back to the cache (pickling large frames can be slow),
- JSON-serializing the response.
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
`202` responses 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
```mermaid
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. All `chart_data.query.*`, `chart_data.cache.*`, `datasource.*`
and `database.*` 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`).
| Metric | Type | What it measures |
| --- | --- | --- |
| `chart_data.auth` | timer | `@protect`: authentication + permission check,
before the handler runs |
| `chart_data.chart_lookup` | timer | Loading the saved chart (`GET
/chart/<pk>/data/` only) |
| `chart_data.dashboard_filters` | timer | Resolving dashboard filter
context (`filters_dashboard_id` only) |
| `chart_data.query_context.build` | timer | Request → `QueryContext`,
including loading the datasource |
| `chart_data.query_context.validate` | timer | Object-level
`raise_for_access` checks |
| `chart_data.async.submit` | timer | Scheduling async tasks (requests that
return `202`) |
| `chart_data.command.execute` | timer | All queries of a synchronous
request |
| `chart_data.totals` | timer | Contribution totals query, only when a chart
needs one |
| `chart_data.query.total` | timer | One query, end to end |
| `chart_data.query.planning` | timer | Query validation, cache key, force
resolution |
| `chart_data.cache.key` | timer | Computing the results cache key (RLS +
extra cache keys / Jinja) |
| `chart_data.cache.get` | timer | Cache backend read + deserialization (not
emitted on bypass) |
| `chart_data.cache.hit` / `.miss` / `.bypass` | counter | Results cache
outcome. `bypass` = forced refresh or cache disabled |
| `chart_data.query.data_acquisition` | timer | Everything spent getting
data from the datasource on a miss or bypass |
| `chart_data.query.annotations` | timer | Annotation layer data, on a miss
or bypass |
| `chart_data.cache.set` | timer | Pickling and writing a fresh result to
the cache (actual writes only) |
| `chart_data.query.payload_assembly` | timer | Building the per-query
payload |
| `chart_data.response.serialize` | timer | JSON-encoding the response body |
| `datasource.query.sql_generation` | timer | Building and rendering SQL |
| `datasource.query.normalize` | timer | Normalizing temporal/metric columns
|
| `datasource.query.time_offsets` | timer | Time comparison queries and
joins |
| `datasource.query.post_processing` | timer | Pandas post-processing (only
when operations exist) |
| `database.connect.<engine>` | timer | Opening a DB connection |
| `database.execute.<engine>` | timer | Driver `cursor.execute()` for one
statement. For drivers whose `execute` blocks until completion, this covers the
database's queueing, compilation and execution, plus network |
| `database.fetch.<engine>` | timer | Fetching result rows from the driver |
| `database.dataframe.<engine>` | timer | Building the DataFrame from
fetched rows |
#### Questions these metrics answer
- **Superset or the database?** Compare `database.execute.<engine>` +
`database.fetch.<engine>` against `chart_data.query.total` and the endpoint
timer.
- **Is the cache helping?** Look at the hit/miss/bypass rates, at
`chart_data.cache.get` (is reading the cache itself slow?), and at
`chart_data.cache.set` (are large result writes delaying responses?).
- **Is connection setup expensive?** `database.connect.<engine>` shows this.
It matters with `NullPool` and engines whose authentication handshake is costly.
- **Is post-processing or serialization the bottleneck?** See
`datasource.query.post_processing`, `datasource.query.time_offsets` and
`chart_data.response.serialize`.
- **Is auth slow?** See `chart_data.auth` and
`chart_data.query_context.validate`.
#### Design decisions
- **Static dot-notation keys, no tags.** `BaseStatsLogger` has 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.
- **Namespaces follow the layer that owns the code.** `chart_data.*` is the
chart data API and query context processor. `datasource.*` and `database.*` 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.
- **Nested, not additive.** Phases nest; for example, `database.execute` is
inside `chart_data.query.data_acquisition`, which is inside
`chart_data.query.total`. Compare within one level; don't sum across levels.
- **Avoid noise from near-zero samples.** `cache.get` is skipped on bypass,
`data_acquisition` and `annotations` only fire when the datasource is actually
queried, `cache.set` only fires on real writes, and `totals` and
`post_processing` only fire when there is work to do.
- **Best-effort.** Every emission swallows metrics-backend errors, so
instrumentation can never change a response. Timers also emit when the measured
block raises, so slow failures such as timeouts stay visible.
- **Auth timing without touching FAB.** Two small decorators placed around
`@protect()` mark entry and handler start. They use `functools.wraps`, so FAB's
`_permission_name`, `_urls` and OpenAPI docstrings are kept.
- **Cost.** About 15–25 UDP sends per uncached query when StatsD is
configured. The default `DummyStatsLogger` only debug-logs.
#### Existing telemetry, for context
- `ChartDataRestApi.{data,get_data}.time` and the `.success/.warning/.error`
counters are unchanged.
- `loading_from_cache`, `loaded_from_cache`, `loaded_from_source` and
`set_cache_key` are unchanged. The new `chart_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. The `execute_sql`
event-log entry is also unchanged.
#### Out of scope (possible follow-ups)
- Time a request spends waiting for a WSGI worker. That happens before Flask
and is best measured at the load balancer or gunicorn.
- Per-request correlation IDs, and capturing warehouse query IDs in logs so
they can be joined with the database's query history.
- Splitting the database's own queue/compile/execute time. That data lives
in the warehouse's query history, not in the driver call.
### BEFORE/AFTER SCREENSHOTS OR ANIMATED GIF
N/A (backend metrics only).
### TESTING INSTRUCTIONS
1. Point Superset at a StatsD sink, e.g. `nc -ul 8125` or a local
`statsd`/Datadog agent:
```python
from superset.stats_logger import StatsdStatsLogger
STATS_LOGGER = StatsdStatsLogger(host="localhost", port=8125,
prefix="superset")
```
Or keep the default `DummyStatsLogger` and set the log level to `DEBUG`
to see `[stats_logger] (timing) ...` lines.
2. Load a dashboard. You should see `superset.chart_data.*`,
`superset.datasource.query.*` and `superset.database.*.<engine>` timers, and a
`chart_data.cache.miss` per query.
3. Reload. Cached charts emit `chart_data.cache.hit` and
`chart_data.cache.get`, but no `database.*` timers.
4. Force-refresh a chart. It emits `chart_data.cache.bypass` and no
`chart_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/dataframe` timers in `Database.get_df`.
### ADDITIONAL INFORMATION
- [ ] Has associated issue:
- [ ] Required feature flags:
- [ ] Changes UI
- [ ] Includes DB Migration (follow approval process in
[SIP-59](https://github.com/apache/superset/issues/13351))
- [ ] Migration is atomic, supports rollback & is backwards-compatible
- [ ] Confirm DB migration upgrade and downgrade tested
- [ ] Runtime estimates and downtime expectations provided
- [x] Introduces new feature or API
- [ ] Removes existing feature or API
Docs: new "Chart data latency metrics" section in
`docs/admin_docs/configuration/event-logging.mdx`.
🤖 Generated with [Claude Code](https://claude.com/claude-code)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
