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), 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

Your platform team can add the cluster's view of the same time window; see 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). 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).

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.
• ~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:         │
│       <bucket>."<bucket>      │
│  /docs_profile".readings  │
│     .temperature DESC     │
│       <bucket>."<bucket>      │
│ /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.

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), 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.

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). 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).

Spark

df.explain() shows the VAST scan's pushed_down_predicates, and a Filter above the scan for what Spark evaluates itself (querying). 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). 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; 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,<max>)}] ]}: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).

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, 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.

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).
• 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: what to change once you know where the time goes.
• Querying and pushdowns: filters that push down.
• Performance: splits, endpoints and cluster settings.
• Data modeling: table structures that let a filter skip more.