Python Observability

Tracing Slow SQL Queries in Python

A single slow query in a single trace is easy to find and usually not the most important one. The query worth fixing is the one that costs the most in total, across every request that issues it, and finding it needs query spans that can be grouped by statement across the whole fleet. This page covers making query spans groupable, ranking by total time, joining application spans to the database's own statistics, and handing the result to the execution plan where the actual reason lives. It is a task article under database and I/O performance observability, part of the Python profiling and performance observability section.

The ranking decides what gets fixed Four statement templates are shown in two rankings. Ranked by p99 latency, a nightly report query taking two point four seconds comes first, followed by a search query at four hundred milliseconds, a product lookup at eighteen milliseconds, and a session read at three milliseconds. Ranked by total time per hour — execution count multiplied by average duration — the order reverses almost entirely: the session read, executed nine hundred thousand times an hour, accounts for forty-five minutes of database time; the product lookup accounts for twenty-one minutes; the search query for eleven; and the report query for under a minute. The note records that optimising the first item in the latency ranking would save almost nothing, while a small improvement to the first item in the total-time ranking would save more than fixing the report query entirely. the same four statements, ranked two ways by p99 latency nightly report · 2.4 s search · 400 ms product lookup · 18 ms session read · 3 ms by total time per hour session read · 45 min · 900k calls product lookup · 21 min search · 11 min nightly report · under 1 min the latency ranking directs effort at the dramatic query the total-time ranking directs it at the expensive one — shaving 1 ms off the session read saves 15 minutes an hour fixing the report query entirely saves under one
Latency rankings find the dramatic queries. Total-time rankings find the expensive ones, and they are rarely the same.

Prerequisites

pip install "opentelemetry-sdk>=1.27.0,<2.0.0" \
            "opentelemetry-instrumentation-sqlalchemy>=0.48b0,<1.0.0" \
            "sqlalchemy>=2.0.0,<3.0.0"

Implementation

Step 1 — Record a sanitised template on every query span. The statement attribute is what lets spans group: two executions of the same query with different parameters must produce the same attribute value. Drivers that use placeholders produce templates naturally; the risk is drivers or ORMs that interpolate values before execution, which produce a distinct string per call. Checking one real span for values in its statement is worth doing before trusting any aggregation.

from opentelemetry.instrumentation.sqlalchemy import SQLAlchemyInstrumentor

SQLAlchemyInstrumentor().instrument(
    engine=engine,
    enable_commenter=True,        # trace context appended as a SQL comment
    commenter_options={"db_driver": False, "db_framework": False},
)

Expected Output: a query span whose statement groups with every other execution of the same query.

{
  "name": "SELECT app",
  "attributes": {
    "db.system": "postgresql",
    "db.statement": "SELECT id, sku, price FROM products WHERE id = %(id_1)s",
    "db.operation": "SELECT",
    "db.sql.table": "products"
  },
  "durationMs": 18.4
}

Step 2 — Rank templates by total time. Total time is execution count multiplied by average duration, per template, over a window. It is what the database spends and what users collectively wait, and it is a query any trace backend that supports grouping can answer. Sorting by it rather than by latency is the single most useful change to how slow queries are prioritised.

-- against a span store that supports SQL over spans
SELECT attributes['db.statement']                    AS template,
       count(*)                                      AS executions,
       avg(duration_ms)                              AS avg_ms,
       sum(duration_ms) / 1000 / 60                  AS total_minutes
FROM spans
WHERE service = 'checkout' AND attributes['db.system'] = 'postgresql'
  AND start_time > now() - interval '1 hour'
GROUP BY template
ORDER BY total_minutes DESC
LIMIT 10;

Expected Output: the ranking that decides what to optimise.

template                                            executions  avg_ms  total_minutes
SELECT data FROM sessions WHERE key = %(key)s          904112     3.0          45.2
SELECT id, sku, price FROM products WHERE id = …       70214    18.0          21.1
SELECT … FROM products WHERE name ILIKE %(q)s            1702   402.0          11.4
SELECT … FROM orders JOIN … GROUP BY …                     2  2410.0           0.1

Step 3 — Attach the trace context to the SQL. Appending the trace and span identifiers as a comment means the database's own slow-query log and statistics carry them. A query found in the database's view — the path a database administrator usually takes — can then be traced back to the request and code that issued it, and a slow span in a trace can be matched to the database's record of the same execution. This join is what turns two teams looking at two tools into one investigation.

Step 4 — Record rows returned. A query that is slow because it returns fifty thousand rows needs pagination or a narrower selection, not an index. One that is slow while returning one row needs an index or a better plan. Recording the row count on the span, which most instrumentation can do from the cursor, separates the two without opening the database at all.

from sqlalchemy import event
from opentelemetry import trace

@event.listens_for(engine, "after_cursor_execute")
def _rows(conn, cursor, statement, parameters, context, executemany):
    span = trace.get_current_span()
    if span.is_recording() and cursor.rowcount is not None and cursor.rowcount >= 0:
        span.set_attribute("db.response.returned_rows", cursor.rowcount)

Step 5 — Take the template to the execution plan. The span identifies which query and how much it costs. Why it costs that — a sequential scan, a poor join order, lock waits — is visible only in the database's plan and wait statistics. Taking the template from the top of the total-time ranking, substituting representative values and reading the plan is the step where the fix is actually found.

EXPLAIN (ANALYZE, BUFFERS)
SELECT data FROM sessions WHERE key = 'representative-value';
Joining the two views of one query On the left, the application's trace shows a query span inside a request, with its duration and statement template. On the right, the database's slow-query log records the same execution from the database's side, including its plan summary, rows examined and lock wait time. The two are joined by the trace identifier, which the instrumentation appended to the statement as a SQL comment and which the database recorded verbatim. From the application side, a slow span leads to the database's detail about why it was slow. From the database side, a slow query found by a database administrator leads to the request, the endpoint and the code that issued it. The note records that without the comment the two views describe the same event with no way to connect them. one execution, two records, one join key application trace GET /search · 612 ms SELECT … ILIKE · 402 ms trace_id 9f2a71c4… which code, which endpoint database slow-query log Seq Scan on products rows examined 1 204 118 /*traceparent='00-9f2a71c4…'*/ why it was slow without the comment these describe the same event with no way to connect them with it, each side is one lookup away from the other
The application knows which code issued the query. The database knows why it was slow. A comment in the SQL is the join between them.

Reading the ranking correctly

The total-time ranking is powerful and it has three properties worth understanding before acting on it.

It rewards small improvements to frequent queries. Shaving one millisecond from a query executed nine hundred thousand times an hour saves fifteen minutes of database time per hour. That is often achievable with a covering index or a narrower column list, and it is invisible in any latency-focused view because the query was never slow.

It can point at a query that should not run at all. A session read at the top of the ranking is frequently a sign that it is executed more often than necessary — once per middleware layer, or once per template include — rather than a sign that it is slow. The fix is then caching it for the duration of the request, and the query count per request from database and I/O performance observability confirms whether that is the case.

It is window-sensitive. A ranking over one hour at midday and one over one hour at night can differ substantially, because workloads change through the day. Batch jobs dominate at night; interactive queries dominate during the day. Taking the ranking over the peak period — which is when the database's capacity actually matters — is usually the right choice.

There is also a caveat about sampling. If traces are sampled, the executions counted in the span store are a fraction of the real total, and the ranking is proportional rather than absolute. Tail sampling that preferentially keeps slow traces distorts it further, over-representing slow queries. For an accurate total-time ranking, the database's own statistics — which count every execution — are the better source, and the trace context in the SQL comment is what lets the two be reconciled.

ORM-generated queries

Most Python services do not write SQL directly, and ORM-generated queries have properties that affect all of the above.

The statement template from an ORM is usually long, repetitive and stable, which is good for grouping and occasionally bad for readability: a query selecting forty columns by name produces a statement several hundred characters long before the interesting part. Truncating the attribute keeps span size reasonable, and the table attribute becomes the more useful grouping dimension for a first look.

ORMs also generate query shapes that are hard to see from the calling code. Lazy loading of a relationship produces a separate query per accessed object; an eager-loading option produces a join or a second query with an IN list whose length varies with the result set. The second case is particularly relevant to grouping, because an IN list with a different number of placeholders is a different template — ten items and eleven items produce two statements that do not group together. Some drivers normalise these, and where they do not, the ranking fragments one logical query into many. Recognising the pattern and grouping by the statement's prefix rather than its full text recovers the correct total.

Finally, the most expensive ORM query is frequently not one statement but one call site that issues many. That is the repetition problem, and it is invisible in any per-statement ranking — each individual execution is cheap. The query count per request, and the most-repeated-statement attribute on the server span, are what surface it.

Three rankings, three different fixes A table of three ways to rank slow queries and what each tends to surface. Ranked by p99 duration, the list shows occasional very slow queries, often caused by locks or cold caches; fixes are indexes or lock avoidance. Ranked by total time, which is call count times mean duration, the list shows queries that dominate database load; fixes are caching or batching. Ranked by call count, the list shows queries issued far more often than expected; the fix is usually an N plus one pattern in code. The note says total time is the ranking that most often leads to the largest improvement. rank by surfaces typical fix p99 duration rare, very slow queries index, avoid locks total time queries dominating load cache or batch call count queries issued too often fix N+1 in code total time (calls × mean) most often leads to the biggest win
The slowest query is rarely the most expensive one. Ranking by total time shows where the database's effort goes.

Configuration options

Attribute or setting Purpose Note
db.statement groups executions template only, never values
db.operation SELECT, INSERT, … coarse grouping
db.sql.table the primary table helps attribute cost to data
db.response.returned_rows result size separates "too much data" from "slow plan"
SQL commenter trace context in the SQL joins to database-side logs
Statement truncation bounded attribute size long generated SQL inflates spans

Verification

Confirm the statement attribute groups correctly by checking the number of distinct values against the number of distinct queries the code actually issues.

SELECT count(DISTINCT attributes['db.statement']) AS distinct_templates,
       count(*) AS executions
FROM spans
WHERE service = 'checkout' AND start_time > now() - interval '1 hour'
  AND attributes['db.system'] IS NOT NULL;

Expected Output: tens or low hundreds of templates against hundreds of thousands of executions.

distinct_templates  executions
                84      981204

Distinct templates close to the number of executions means values are being interpolated into the statement, which breaks grouping and puts data into telemetry — the first thing to fix before trusting any ranking.

Common mistakes

Ranking by latency. Error signature: an optimisation of a rare slow query with no effect on database load. Root cause: latency ignores frequency. Remediation: rank by total time.

Values in the statement attribute. Error signature: no two spans share a statement, and data appears in telemetry. Root cause: interpolated SQL captured after substitution. Remediation: capture templates; verify with the distinct count above.

Treating the span as the diagnosis. Error signature: a guess at an index that does not help. Root cause: the span shows cost, not cause. Remediation: take the template to the execution plan.

No link to the database's view. Error signature: an application team and a database team investigating the same query separately. Root cause: nothing joins the two records. Remediation: enable SQL commenting.

Ranking from sampled traces as though they were complete. Error signature: totals that disagree with the database's own statistics. Root cause: sampling, particularly sampling that favours slow traces. Remediation: use the database's statistics for totals and traces for attribution.

Frequently Asked Questions

Why rank queries by total time rather than by p99 latency?

Because total time is what the database and the users actually pay. A query taking five milliseconds and executed a million times an hour costs far more than one taking two seconds executed twice. Latency rankings direct effort at the dramatic queries rather than the expensive ones.

What is SQL commenting and why use it?

Appending the trace context to each statement as a comment. The database records the comment in its own logs and statistics, so a slow query found in the database can be traced back to the request and code that issued it, and the reverse.

Should the statement attribute contain parameter values?

Never. Values leak data into telemetry and make every execution a distinct attribute value, which prevents grouping and inflates storage. Record the template with placeholders.

Can spans show why a query is slow?

They show that it is slow, how often it runs and how many rows it returns. The reason — a missing index, a poor plan, lock contention — is visible in the database's execution plan and wait statistics. The span's job is to identify which query to examine.

Related Guides