--- title: "Profile a query" slug: "dev-database-guides-profile-a-query" updated: 2026-10-30T18:19:11Z published: 2026-10-30T18:19:11Z canonical: "docs.vastdata.com/dev-database-guides-profile-a-query" --- > ## Documentation Index > Fetch the complete documentation index at: https://docs.vastdata.com/llms.txt > Use this file to discover all available pages before exploring further. # Profile a query *Applies to VAST Cluster 5.5. Examples use the VAST DataBase Python SDK 2.1.0.* When a query is slower than you expect, a profile answers three questions: did the filter push down to VAST DataBase, how much did VAST DataBase send back, and where did the time go. This guide shows what you can see from each client: timings and plans from the VAST Query Engine over ADBC, `EXPLAIN ANALYZE` in Trino, what the Python SDK and Spark show, and the cluster metrics your platform team can read. It ends with what to send support. The Python blocks connect to the Query Engine with the ADBC driver, as in [VAST Query Engine (ADBC)](/develop/docs/dev-database-integrations-adbc), and create their own table in a schema called `docs_profile`. Run them in order in one Python session; the SQL block runs in the Trino CLI. Below each block is the output you should see. ## What each client shows | Client | Did the filter push down? | Where did the time go? | What to give support | | --- | --- | --- | --- | | VAST Query Engine (ADBC) | `EXPLAIN` | Your own timing of execute and fetch | The query ID | | Trino | `EXPLAIN` | `EXPLAIN ANALYZE`, and Trino's query statistics | The Trino query ID and the time it ran | | Spark | `df.explain()` | The Spark UI | The time it ran | | Python SDK | No `EXPLAIN`: the predicate you pass is exactly what's pushed down | Your own timing of `select()` through the end of reading | The transaction ID from the SDK's log | Your platform team can add the cluster's view of the same time window; see [ask your platform team](/develop/docs/dev-database-guides-profile-a-query#ask-your-platform-team). ## Set up You need the Query Engine endpoint in `QE_ENDPOINT`, a key pair in `AWS_ACCESS_KEY_ID` and `AWS_SECRET_ACCESS_KEY`, and your bucket in `VASTDB_BUCKET` ([setup prerequisites](/develop/docs/dev-database-operations-setup-prerequisites)). This block connects, creates a table of 200,000 readings, and loads it with ADBC bulk ingest: ``` import os import re import time import adbc_driver_manager import adbc_driver_manager.dbapi as dbapi import adbc_driver_vastdb import pyarrow as pa BUCKET = os.environ["VASTDB_BUCKET"] SCHEMA = f'"{BUCKET}/docs_profile"' TABLE = f"{SCHEMA}.readings" conn = dbapi.connect( driver=adbc_driver_vastdb.get_driver_path(), db_kwargs={ "vast.db.endpoint": os.environ["QE_ENDPOINT"], "vast.db.access_key": os.environ["AWS_ACCESS_KEY_ID"], "vast.db.secret_key": os.environ["AWS_SECRET_ACCESS_KEY"], }, autocommit=True, ) def sql(query): with conn.cursor() as cur: cur.execute(query) return cur.fetchall() N = 200_000 data = pa.table({ "id": pa.array(range(N), pa.int64()), "sensor": [f"s{i % 10}" for i in range(N)], "temperature": [(i % 500) / 10 for i in range(N)], "note": [f"n-{i % 7}" for i in range(N)], }) sql(f"CREATE SCHEMA IF NOT EXISTS {SCHEMA}") sql(f"CREATE TABLE IF NOT EXISTS {TABLE} " "(id BIGINT, sensor VARCHAR, temperature DOUBLE, note VARCHAR)") for start in range(0, N, 50_000): with conn.cursor() as icur: icur.adbc_ingest("readings", data.slice(start, 50_000), mode="append", catalog_name="vastdb", db_schema_name=f"{BUCKET}/docs_profile") print(sql(f"SELECT count(*) FROM {TABLE}")) ``` ``` [(200000,)] ``` ## Time the query With the VAST ADBC driver, `execute()` returns once the query has started, and the work shows up while you fetch, even for a one-row result. So time `execute()` and the fetch together, and run the query several times. Reuse the connection: opening one is part of the cost of a short request ([measure recall and latency](/develop/docs/dev-vector-search-guides-developer-observability#time-the-query-not-the-pipeline)). ``` def timed(query, runs=5): execute_s, total_s = [], [] for _ in range(runs): with conn.cursor() as cur: start = time.perf_counter() cur.execute(query) executed = time.perf_counter() result = cur.fetch_arrow_table() done = time.perf_counter() execute_s.append(executed - start) total_s.append(done - start) median = lambda xs: sorted(xs)[len(xs) // 2] return result.num_rows, {"execute_s": median(execute_s), "total_s": median(total_s)} rows, medians = timed(f"SELECT id, temperature FROM {TABLE} " "WHERE sensor = 's3' AND temperature >= 49") print(rows, "rows;", sorted(medians)) ``` ``` 400 rows; ['execute_s', 'total_s'] ``` The example prints only the names, so its output doesn't change between runs; print the values in your own code. Compare `total_s` for different versions of the same query, on the same connection. ## Read the plan with EXPLAIN `EXPLAIN <query>` returns one row with two columns. The first holds `physical_plan`, and the second the plan, drawn as boxes, with the table scan, `VAST_SCAN`, at the bottom. This helper prints both: ``` def explain(query): with conn.cursor() as cur: cur.execute("EXPLAIN " + query) key, plan = cur.fetchone() print(key) print(plan) explain(f"SELECT id, temperature FROM {TABLE} WHERE sensor = 's3' AND temperature >= 49") ``` ``` physical_plan ┌───────────────────────────┐ │ PROJECTION │ │ ──────────────────── │ │ id │ │ temperature │ │ │ │ ~175000 Rows │ └─────────────┬─────────────┘ ┌─────────────┴─────────────┐ │ VAST_SCAN │ │ ──────────────────── │ │ Function: VAST_SCAN │ │ │ │ Projections: │ │ temperature │ │ id │ │ │ │ ~175000 Rows │ └───────────────────────────┘ ``` The `VAST_SCAN` box lists the columns it reads and an estimated row count, but not the filters that VAST DataBase evaluates. Neither condition appears anywhere in this plan: both were pushed down. Now put a function on the filtered column: ``` explain(f"SELECT id, temperature FROM {TABLE} WHERE upper(sensor) = 'S3'") ``` ``` physical_plan ┌───────────────────────────┐ │ PROJECTION │ │ ──────────────────── │ │ #1 │ │ #2 │ │ │ │ ~175000 Rows │ └─────────────┬─────────────┘ ┌─────────────┴─────────────┐ │ FILTER │ │ ──────────────────── │ │ (upper(sensor) = 'S3') │ │ │ │ ~175000 Rows │ └─────────────┬─────────────┘ ┌─────────────┴─────────────┐ │ VAST_SCAN │ │ ──────────────────── │ │ Function: VAST_SCAN │ │ │ │ Projections: │ │ sensor │ │ id │ │ temperature │ │ │ │ ~175000 Rows │ └───────────────────────────┘ ``` This time the plan has a `FILTER` box above the scan, holding `upper(sensor) = 'S3'`. The Query Engine evaluates that condition itself, on rows that VAST DataBase returns unfiltered. To read a Query Engine plan: - **A condition that's missing from the plan** was handed to VAST DataBase. - **A condition in a `FILTER` box** is evaluated by the Query Engine, after the scan. Rewrite it so the column is compared with a literal; see [pushdowns](/develop/docs/dev-database-reference-pushdowns). - **`~N Rows` is the table's row count**, on every box, whatever the filter. Don't read it as an estimate of how many rows your filter matches. A top-N query plans a `TOP_N` step, with its limit and sort keys, over the scan: ``` explain(f"SELECT id, temperature FROM {TABLE} WHERE sensor = 's3' " "ORDER BY temperature DESC, id LIMIT 3") ``` ``` physical_plan ┌───────────────────────────┐ │ TOP_N │ │ ──────────────────── │ │ Top: 3 │ │ │ │ Order By: │ │ ." │ │ /docs_profile".readings │ │ .temperature DESC │ │ ." │ │ /docs_profile".readings.id│ │ ASC │ └─────────────┬─────────────┘ ┌─────────────┴─────────────┐ │ VAST_SCAN │ │ ──────────────────── │ │ Function: VAST_SCAN │ │ │ │ Projections: │ │ id │ │ temperature │ │ │ │ ~175000 Rows │ └───────────────────────────┘ ``` For tooling, `EXPLAIN (FORMAT json) <query>` returns the same plan as JSON, one object per step. For vector search, the plan shows whether the search uses the index (a `VAST_VEC_INDEX_SCAN` step); see [query design](/develop/docs/dev-vector-search-guides-query-design#check-the-plan-with-explain). ## What the Query Engine doesn't have `EXPLAIN ANALYZE` isn't supported in the Query Engine in VAST Cluster 5.5. It fails before the query runs: ``` with conn.cursor() as cur: try: cur.execute(f"EXPLAIN ANALYZE SELECT count(*) FROM {TABLE} WHERE sensor = 's3'") except adbc_driver_manager.DatabaseError as e: # The server's own message is inside the driver's error text. print(type(e).__name__ + ":", re.search(r'\]: (.*?)"', str(e)).group(1)) ``` ``` InternalError: The operator 'EXPLAIN_ANALYZE' type=63 is currently not supported. ``` You can't turn on profiling with SQL either: `SET` and `PRAGMA` statements fail with `The operator 'SET' type=69 is currently not supported.`. Session settings are passed as ADBC connection options instead ([search session settings](/develop/docs/dev-vector-search-reference-configuration)), and setting a profiling option that way returns no profile either. So for the run itself, use your own timing and [ask your platform team](/develop/docs/dev-database-guides-profile-a-query#ask-your-platform-team). ## Record the query ID Every Query Engine query has an ID. After `execute()`, read it from the statement with the option `vast.db.last_query_id`. It's a statement (cursor) option; reading it from the connection fails: ``` with conn.cursor() as cur: cur.execute(f"SELECT count(*) FROM {TABLE} WHERE sensor = 's3'") cur.fetchall() query_id = cur.adbc_statement.get_option("vast.db.last_query_id") print(re.sub(r"0x[0-9a-f]+|\d+", "N", query_id)) ``` ``` QueryId(req_id = N, vip_id = N) ``` The example masks the numbers; log the real value with the query's start time. If `execute()` fails, the option isn't set, but the error text carries a request ID in the form `[req=0x…]`: ``` with conn.cursor() as cur: try: cur.execute(f"SELECT sensor, count(*) FROM {TABLE} GROUP BY sensor") except adbc_driver_manager.DatabaseError as e: print("request ID in the error:", bool(re.search(r"\[req=0x[0-9a-f]+\]", str(e)))) try: cur.adbc_statement.get_option("vast.db.last_query_id") except adbc_driver_manager.Error as e: print("last_query_id after a failed execute:", type(e).__name__) ``` ``` request ID in the error: True last_query_id after a failed execute: ProgrammingError ``` Keep the whole error message for a support case. ## Python SDK The SDK has no `EXPLAIN`. What it pushes down is exactly the `predicate` you pass: one it can't send raises `NotImplementedError` before any request ([querying](/develop/docs/dev-database-guides-querying#rewrite-filters-that-dont-push-down)). `select()` returns a reader before the rows arrive, so time from `select()` to the end of reading, not just the call. `QueryConfig(query_id=...)` only names the SDK's worker threads; it isn't sent to the cluster. For a support case, log the transaction ID instead: the `vastdb.transaction` logger records it at DEBUG ([SDK logging](/develop/docs/dev-database-operations-monitoring-your-workload#sdk-logging)). ## Spark `df.explain()` shows the VAST scan's `pushed_down_predicates`, and a `Filter` above the scan for what Spark evaluates itself ([querying](/develop/docs/dev-database-guides-querying#spark)). For where the time went, use Spark's own tools, such as the SQL tab of the Spark UI. ## Trino: EXPLAIN ANALYZE In Trino, start with `EXPLAIN` to see what's pushed down ([Trino](/develop/docs/dev-database-integrations-trino#explain)). Then `EXPLAIN ANALYZE` runs the query and reports, for each step, the time spent and the rows and bytes that went in and out. This query reads the table from [Set up](/develop/docs/dev-database-guides-profile-a-query#set-up); the examples use the database (bucket) `vastdb`, so use yours instead. The times and sizes in the output differ on every run: ``` EXPLAIN ANALYZE SELECT sensor, count(*) AS readings FROM vast."vastdb/docs_profile".readings WHERE temperature >= 49 AND note LIKE '%-1' GROUP BY sensor; ``` ``` Query Plan ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ Trino version: 478 Queued: 430.42us, Analysis: 477.20ms, Planning: 591.22ms, Execution: 1.05s Fragment 1 [HASH] CPU: 15.64ms, Scheduled: 27.16ms, Blocked 7.12s (Input: 3.32s, Output: 0.00ns), Input: 10 rows (160B); per task: avg.: 10.00 std.dev.: 0.00, Output: 10 rows (160B) Peak Memory: 2.13kB, Tasks count: 1; per task: max: 2.13kB Output layout: [sensor, count] Output partitioning: SINGLE [] Aggregate[type = FINAL, keys = [sensor]] │ Layout: [sensor:varchar, count:bigint] │ Estimates: {rows: ? (?), cpu: ?, memory: ?, network: 0B} │ CPU: 6.00ms (2.96%), Scheduled: 6.00ms (0.59%), Blocked: 0.00ns (0.00%), Output: 10 rows (160B) │ Input avg.: 0.63 rows, Input std.dev.: 148.32% │ count := count(count_0) └─ LocalExchange[partitioning = HASH, arguments = [sensor::varchar]] │ Layout: [sensor:varchar, count_0:bigint] │ Estimates: {rows: ? (?), cpu: ?, memory: 0B, network: 0B} │ CPU: 2.00ms (0.99%), Scheduled: 2.00ms (0.20%), Blocked: 3.56s (51.74%), Output: 10 rows (160B) │ Input avg.: 0.63 rows, Input std.dev.: 387.30% └─ RemoteSource[sourceFragmentIds = [2]] Layout: [sensor:varchar, count_0:bigint] CPU: 0.00ns (0.00%), Scheduled: 0.00ns (0.00%), Blocked: 3.32s (48.26%), Output: 10 rows (160B) Input avg.: 0.63 rows, Input std.dev.: 387.30% Fragment 2 [SOURCE] CPU: 198.36ms, Scheduled: 1.02s, Blocked 0.00ns (Input: 0.00ns, Output: 0.00ns), Input: 4000 rows (58.59kB); per task: avg.: 4000.00 std.dev.: 0.00, Output: 10 rows (160B) Peak Memory: 466B, Tasks count: 1; per task: max: 466B Output layout: [sensor, count_0] Output partitioning: HASH [sensor] Aggregate[type = PARTIAL, keys = [sensor]] │ Layout: [sensor:varchar, count_0:bigint] │ CPU: 27.00ms (13.30%), Scheduled: 34.00ms (3.34%), Blocked: 0.00ns (0.00%), Output: 10 rows (160B) │ Input avg.: 71.50 rows, Input std.dev.: 264.58% │ count_0 := count(*) └─ ScanFilterProject[table = vast:vastdb/docs_profile:readings@{VastColumnHandle{field={"name":"temperature","nullable":true,"type":{"name":"floatingpoint","precision":"DOUBLE"},"children":[],"metadata":[{"value":"66","key":"VAST:column_id"}]}, path=[], expr=null}=[ SortedRangeSet[type=double, ranges=1, {[49.0,)}] ]}:complex=null:limit=none:sorted_by@[Optional.empty], handle:VastObjectDetails{name='readings', handle='9789841333657100869', numRows=0, sizeInBytes=0, numPartitions=0, sortingKeyEnabled=false, sortingScore=0, writeAmplification=1, acummulativeRowInseritionCount=0, mstPointer=0}, filterPredicate = $like(note, LikePattern '[%-1]')] Layout: [sensor:varchar] Estimates: {rows: ? (?), cpu: ?, memory: 0B, network: 0B}/{rows: ? (?), cpu: ?, memory: 0B, network: 0B}/{rows: ? (?), cpu: ?, memory: 0B, network: 0B} CPU: 168.00ms (82.76%), Scheduled: 975.00ms (95.87%), Blocked: 0.00ns (0.00%), Output: 572 rows (3.91kB) Input avg.: 500.00 rows, Input std.dev.: 264.58% note := VastColumnHandle{field={"name":"note","nullable":true,"type":{"name":"utf8"},"children":[],"metadata":[{"value":"67","key":"VAST:column_id"}]}, path=[], expr=null} sensor := VastColumnHandle{field={"name":"sensor","nullable":true,"type":{"name":"utf8"},"children":[],"metadata":[{"value":"65","key":"VAST:column_id"}]}, path=[], expr=null} Input: 4000 rows (58.59kB), Filtered: 85.70%, Physical input: 72.80kB, Physical input time: 0.00ns, Splits: 8, Splits generation wait time: 0.42ms (1 row) ``` Timings and sizes change from run to run. Look at the VAST scan step, `ScanFilterProject`: - **`Input: N rows`** is the rows VAST DataBase returned, after its own filtering. Here it has already applied `temperature >= 49`. - **`Filtered: P%`** is the share of those rows that Trino then removed itself: here, the `LIKE '%-1'` that the connector doesn't push down. - **`Splits: n`** is the number of VAST splits the scan ran ([performance](/develop/docs/dev-database-operations-performance#spread-work-across-endpoints)). A large `Input` with a high `Filtered` share means Trino did the filtering; rewrite the filter so more of it pushes down. `EXPLAIN ANALYZE VERBOSE` adds the connector's own counters for the scan. Don't use `EXPLAIN (TYPE IO)` to check pushdown: its column constraints are empty even for a pushed filter. Trino's query IDs are Trino's own. Find them, and each query's statistics, in the Trino Web UI or the `system.runtime.queries` table. ## Clean up ``` sql(f"DROP TABLE IF EXISTS {TABLE}") sql(f"DROP SCHEMA IF EXISTS {SCHEMA}") conn.close() print("Dropped docs_profile") ``` ``` Dropped docs_profile ``` ## Ask your platform team The cluster keeps database metrics that no client can read. According to [Monitoring VAST DataBases](/docs-5-5/docs/monitoring-vast-databases), the VAST Web UI shows: - On the dashboard: database bandwidth, running queries and rows scanned per second. - In predefined analytics reports: VAST DB latency, bandwidth, rows (scanned, filtered out, imported, inserted, updated and deleted per second) and requests per request type. - Custom reports built from VAST DB metrics. These are rates for the whole cluster or for each CNode, sampled at intervals, not figures for one query. Ask for the window your query ran in, and if you can, run it on a quiet cluster or repeat it for a minute so it stands out. **Admin task: send to your platform team.** See [Monitoring VAST DataBases](/docs-5-5/docs/monitoring-vast-databases). ## What to give support - The SQL, or the SDK call with its predicate and columns. - The client and its version: SDK, ADBC driver, Trino or Spark connector ([versions](/develop/docs/dev-database-reference-versions)). - The query ID (`vast.db.last_query_id`), or the full error message with its `[req=0x…]` request ID. For the SDK, the transaction ID from the log; for Trino, the Trino query ID. - When the query ran, with the time zone, and how long it took against how long you expected. - The plan: `EXPLAIN` from the Query Engine, `EXPLAIN ANALYZE` from Trino, or `df.explain()` from Spark. ## Next steps - [Optimize queries](/develop/docs/dev-database-guides-optimize-queries): what to change once you know where the time goes. - [Querying](/develop/docs/dev-database-guides-querying) and [pushdowns](/develop/docs/dev-database-reference-pushdowns): filters that push down. - [Performance](/develop/docs/dev-database-operations-performance): splits, endpoints and cluster settings. - [Data modeling](/develop/docs/dev-database-guides-data-modeling): table structures that let a filter skip more.