Product DocumentationAppearance
sys.log_query
This view records the history of SQL operations and bulk loads performed over the past seven days (by default).
Note: The statistical values recorded in this view are also available via the Query Details tabs in Yellowbrick Manager.
User accounts only see the queries they submit. Superuser accounts see all queries. (Commands executed by internal superusers, such as yellowbrick, are not logged.)
| Column Name | Data Type | Description |
|---|---|---|
| query_id | bigint | Unique query ID. When queries are restarted, multiple entries are logged to sys.log_query under the same query ID. In sys.query, a query ID always identifies one unique row. Query IDs are logged for ybload operations as well as SQL queries. |
| session_id | bigint | Unique ID of the session. Foreign key reference to sys.session and sys.log_session. |
| transaction_id | bigint | Unique transaction ID. NULL if transaction context has not yet been acquired. |
| plan_id | varchar(64) | Unique query plan ID. |
| state | varchar(50) | The current state of the query. In sys.log_query, this state is always a completion state: done, cancel, error. In sys.query, this state may be any of the states in the query lifecycle.When the BLOCK row store action is set for a table, inserts tracked by sys.query are always in the plan state. See ALTER TABLE. |
| blocked | varchar(255) | The reason the query is blocked; NULL if not blocked. For example, this column contains the lock requested when a query is waiting for an object-level lock. Note: This column is only found in sys.query; it is not needed in sys.log_query. |
| username | varchar(128) | User who ran the query. |
| application_name | varchar(128) | Name of the application that ran the query, such as ybsql, ym, or ybload. The application name for replication operations is replication service. |
| database_name | varchar(128) | Name of the database where the query was run. (The database ID is not tracked because the database may be dropped when the query is complete and recorded in sys.log_query.) |
| cluster_name | varchar(128) | Name of the virtual compute cluster that was used for the query. |
| type | varchar(128) | Type of query or operation, such as select, insert, update, delete, load, ctas, drop table, backup, restore. The maintenance type refers to background system operations. |
| tags | varchar(128) | Query tags in the system, as defined with a SET YBD_QUERY_TAGS command. Tags may be logged based on WLM rule processing. NULL if the query received no tags. |
| error_code | varchar(5) | Yellowbrick error code. |
| error_message | varchar(255) | Text of the error message, if any. |
| query_text | varchar(60000) | SQL text of the query. For readability the text is broken into multiple lines, with each line separated by a plus sign (+). |
| pool_id | varchar(128) | Resource pool that the query was assigned to. |
| priority | varchar(30) | WLM query priority: normal, low, high, or critical. |
| slot | bigint | Execution slot number for the query, within its resource pool. Each pool has a fixed maximum and minimum number of slots. |
| num_workers | integer | Total number of workers that participated in, or are participating in, running the query. NULL until the query leaves the assemble or acquire_resources state. Set to 1 for single-worker queries after the assemble phase. For multi-worker queries, the actual worker count is not set until after the acquire_resources phase. This column is set to 0 for front-end queries, including internal system queries. |
| longest_worker_id | varchar(38) | The worker that is currently taking the longest time to finish executing this query (or the worker that was the last to finish when the query was done). NULL until the query starts executing. In a distributed system, workers may run for different durations. This column helps identify which of the workers matter from a tuning perspective. The "longest-running worker" is the worker that finished last when the query was completed and moved to sys.log_query. While the query is running, the longest-running worker is either the worker with the highest io_spill_space_bytes (if spilling is occurring) or the worker with the highest run_ms value (if spilling is not occurring). |
| compile_percent | integer | The amount of resources (as a percentage of the total used) that the query used from when it started compiling until the last fragment was done. NULL until the query enters the compile state. |
| cpu_percent | integer | How effectively the CPU was used on the worker that dominated runtime (the longest worker). (run_ms - wait_cpu_ms - wait_io_ms) / (run_ms - wait_cpu_ms) |
| cpu_percent_max | integer | Calculated in the same way as cpu_percent, but using the largest CPU % of the cluster. For a perfectly non-skewed execution, this value will be the same as cpu_percent.For single-worker queries, this value should be equal to cpu_percent on that worker. |
| num_restart | integer | Number of restarts. When the query is restarted or moved by a user process, this number is incremented by 1. Initialized to 0. This value is incremented when: - A WLM rule triggers a w.moveToResourcePool() action, the target pool is full or has insufficient resources, and the query must restart.- A WLM rule triggers a w.restartInResourcePool() action.- A WLM profile change is activated (with the option to cancel running queries), the query is currently running, and is restarted. - An administrator runs a SQL MOVE or RESTART command.See also Moving Queries and Restarting Queries. |
| num_error | integer | Number of error-driven restarts. When the query errors out and is restarted by an error-recovery process, this number is incremented by 1. Initialized to 0. See also the description for the num_restart column. |
| parse_ms | decimal(18,3) | Time spent parsing the query text and acquiring locks. Initialized to 0 when the query is submitted. |
| wait_parse_ms | decimal(18,3) | Time spent waiting for the parser to become available. Initialized to 0 when the query is submitted. |
| wait_lock_ms | decimal(18,3) | Time spent blocked while waiting for locks during the parse/lock phase. Initialized to 0 when the query is submitted. |
| plan_ms | decimal(18,3) | Time spent generating the query plan. This measurement does not include time spent generating the XML serialization for the query compiler. Initialized to 0 when the query is submitted. |
| wait_plan_ms | decimal(18,3) | Time spent waiting for the query planner to become available. Initialized to 0 when the query is submitted. |
| assemble_ms | decimal(18,3) | Time spent assembling the query. The time starts just before the XML is serialized in the front-end database and ends when the generated C++ code is available. This time may be close to 0 when the query plan is found in the cache. NULL before entering the assemble state, then initialized to 0. |
| wait_assemble_ms | decimal(18,3) | Time spent waiting for assembly/preparation steps (XML serialisation, AST analysis, and C++ code generation) to be available to the query. This value also measures time where the assemble steps did not run for various reasons (such as waiting for internal locks). NULL before entering the queue, then initialized to 0. |
| compile_ms | decimal(18,3) | Duration of time when at least one query fragment is being compiled. The timer starts when the first fragment begins to compile and ends when the last fragment has finished compiling. NULL before compilation, then initialized to 0. Also 0 if the query is found in the compile cache. |
| wait_compile_ms | decimal(18,3) | Duration of time when at least one fragment could have been compiled, but it did not start compiling because the compile resource was not available. NULL before entering the compile state, then initialized to 0. |
| acquire_resources_ms | decimal(18,3) | How long it took to acquire resources to run the query, such as memory, spill space, and worker slots. NULL before entering the acquire_resources state, then initialized to 0. |
| run_ms | decimal(18,3) | How long the query was running on the longest-running worker node. This value represents the total time the query spent in the run state. Note that wait-time statistics are included in the run_ms total: run_ms = wait_run_cpu_ms + wait_run_io_ms + wait_run_spool_msTo get the true CPU consumption for the query (how much time the CPU spent doing actual work), calculate: run_ms - wait_run_cpu_ms - wait_run_io_msThe run_ms value is NULL before the query enters the run state, then it is initialized to 0. |
| wait_run_cpu_ms | decimal(18,3) | Time spent waiting for the CPU to become available. The query is not actively running though in the run state. This measurement is taken on the longest-running worker. NULL before entering the run state, then initialized to 0. |
| wait_run_io_ms | decimal(18,3) | Time spent waiting for I/O or other operations while the query is scheduled to run and is in the run state. This measurement is taken on the longest-running worker. NULL before entering the run state, then initialized to 0. |
| wait_run_spool_ms | decimal(18,3) | Time spent spooling the data when the worker has finished running the query. The time spent waiting for spool overlaps with the runtime of the query; spooling may occur while other runtime work is being done. NULL until spooling starts. |
| client_ms | decimal(18,3) | Duration of time from when the query finishes spooling data to when the client receives the last row in the result set. |
| wait_client_ms | decimal(18,3) | Total time spent waiting for the client. This time only starts counting when the last row has been spooled. This time goes up when:- Rows are not sent to the client because the client has not requested them. - Spooling is blocked (out of spool space) until the client has received more data. NULL before entering the client_wait state, then initialized to 0. |
| total_ms | decimal(18,3) | The total duration of the query. The following timings overlap and do not contribute to the total_ms measurement: cancel_ms, restart_ms, wlm_runtime_ms, and spool_ms.NULL until the query is in the done state. |
| cancel_ms | decimal(18,3) | Time spent waiting for the query to move out of the cancel state; how long it takes to completely cancel and tear down the query. |
| restart_ms | decimal(18,3) | Time spent waiting for a query to restart, once requested. |
| wlm_runtime_ms | decimal(18,3) | How long it takes to evaluate WLM runtime rules. |
| spool_ms | decimal(18,3) | How long it takes for the entire result set to be sent to the manager node for consumption by the client. This column returns NULL for queries that do not spool and returns NULL before the query starts spooling. |
| cache_efficiency | decimal(18,3) | Efficiency of the data cache, expressed as a percentage, where 100% means that all of the data blocks for the query were cached (held in local NVMe SSDs). |
| submit_time | timestamptz | When the query was submitted by the user. This timestamp remains constant during restarts. |
| done_time | timestamptz | When the query finished (and moved to the done state). |
| state_time | timestamptz | When the query entered the current state. This value is set to the submit_time when the query first enters the system. If the query restarts, this is the timestamp when the restart was initiated. |
| restart_time | timestamptz | When the query was restarted. NULL for queries that were not restarted. |
| io_read_bytes | bigint | Number of bytes read by the query (aggregated across all workers). This value does not include temporary storage reads. |
| io_write_bytes | bigint | Number of bytes written by the query (aggregated across all workers). This value does not include temporary storage writes. |
| io_spill_read_bytes | bigint | Number of bytes the query has read back from temporary storage on disk (aggregate of all spilling reads). This number may be lower than io_spill_write_bytes (for example, if the query has a LIMIT clause). This column returns 0 for queries that run on the worker nodes without spilling. For queries that did not reach the worker nodes, this column returns NULL. |
| io_spill_write_bytes | bigint | Number of bytes the query has spilled to disk, using temporary storage (aggregate of all spilling writes). This column returns 0 for queries that run on the worker nodes without spilling. For queries that did not reach the worker nodes, this column returns NULL. |
| io_network_bytes | bigint | Number of bytes moved internally over the network on the cluster (manager node to workers and vice versa). This number does not include data being returned to the client. |
| io_client_read_bytes | bigint | Total number of bytes sent by the client to the server (for example, via a ybsql \copy or ybload command). |
| io_client_write_bytes | bigint | Total number of bytes sent to the client. |
| io_spool_write_bytes | bigint | Total size of spool space written by the query. |
| rows_inserted | bigint | Number of rows inserted by the query (for UPDATE, INSERT, CTAS, ybload, \ycopy operations). |
| rows_deleted | bigint | Number of rows deleted by the query. For UPDATE statements, both rows_deleted and rows_inserted are both >0. |
| rows_returned | bigint | Number of rows the query returned to the client. |
| memory_bytes | bigint | Amount of memory consumed by the longest-running worker that ran this query. |
| memory_bytes_max | bigint | Maximum amount of memory used by any worker that ran this query. |
| io_spill_space_bytes | bigint | Amount of temporary space consumed by the longest-running worker that ran this query. This value is very useful when you are setting up spill space allocation for WLM resource pools. |
| io_spill_space_bytes_max | bigint | The maximum amount of temporary space consumed by any worker that ran this query. |
| io_spill_space_granted_bytes | bigint | The amount of spill space allowed by the query. NULL for front-end queries and queries that have not yet been granted space. |
| memory_estimated_bytes | bigint | The estimated memory per worker from the query plan. NULL until the query exits the compile state. |
| memory_required_bytes | bigint | The minimum amount of memory required per worker to start the query. NULL until the query exits the compile state. |
| memory_granted_bytes | bigint | Amount of memory per worker actually given to the query (during the acquire_resources phase) in its assigned resource pool and execution slot. NULL until the query enters the acquire_resources state. |
| memory_estimate_confidence | varchar(16) | None (no confidence), Low, High, or Unknown. These values describe the degree to which the estimated memory is thought to be reliable. |
Examples
You can monitor query activity at the cluster level with the sys.query and sys.log_query views, using the cluster_name column. For example:
premdb=> select username, application_name, database_name, cluster_name, rows_returned, submit_time
from sys.log_query
where
database_name='premdb'
and rows_returned >0
and submit_time like '2022-04-27%'
and cluster_name like 'bobrum%';
username | application_name | database_name | cluster_name | rows_returned | submit_time
-----------+------------------------------------+---------------+-------------------------+---------------+-------------------------------
ybtools10 | DBeaver 22.0.3 - Main <premdb> | premdb | bobrum-beta1-cluster-01 | 1 | 2022-04-27 22:30:24.967+00
ybtools10 | DBeaver 22.0.3 - Metadata <premdb> | premdb | bobrum-beta1-cluster-01 | 1 | 2022-04-27 22:30:26.217+00
ybtools10 | DBeaver 22.0.3 - Metadata <premdb> | premdb | bobrum-beta1-cluster-01 | 1 | 2022-04-27 22:30:26.739+00
ybtools10 | ybsql | premdb | bobrum-beta1-cluster-01 | 1 | 2022-04-27 21:29:24.142745+00
ybtools10 | ybsql | premdb | bobrum-beta1-cluster-01 | 1 | 2022-04-27 21:22:50.662631+00
ybtools10 | ybsql | premdb | bobrum-beta1-cluster-01 | 14 | 2022-04-27 21:18:07.953633+00
ybtools10 | ybsql | premdb | bobrum-beta1-cluster-01 | 13 | 2022-04-27 21:17:32.582684+00
ybtools10 | ybsql | premdb | bobrum-beta1-cluster-01 | 22 | 2022-04-27 21:14:34.362424+00
(8 rows)Return the total running time for queries run by a specific user:
premdb=> select query_id, state, username, total_ms, substr(query_text,1,50)
from sys.log_query where username='bobr' order by query_id desc;
query_id | state | username | total_ms | substr
----------+-------+----------+----------+----------------------------------------------------
248790 | done | bobr | 293.061 | select t1.season_name, t1.winners, homegoals+awayg
247096 | done | bobr | 115.999 | select season_name, numteams, sum(substr(ftscore,1
(3 rows)Return runtime statistics and the SQL text for UPDATE queries run by a single user:
premdb=> select query_id, username, application_name, type, state, substr(query_text,1,25) qrytxt, parse_ms, plan_ms, assemble_ms, compile_ms, run_ms, client_ms, total_ms
from sys.log_query
where type='update' and username='bobr'
order by 1 desc;
query_id | username | application_name | type | state | qrytxt | parse_ms | plan_ms | assemble_ms | compile_ms | run_ms | client_ms | total_ms
----------+----------+------------------+--------+-------+---------------------------+----------+---------+-------------+------------+-----------+-----------+-----------
1143640 | bobr | ybsql | update | done | update newmatchstats set | 0.852 | 2.345 | 49.589 | 1474.536 | 16070.043 | 1.051 | 17600.752
1141949 | bobr | ybsql | update | done | update newmatchstats set | 0.528 | 2.475 | 27.465 | 1319.912 | 16007.334 | 1.224 | 17360.764
1130126 | bobr | ybsql | update | done | update newmatchstats set | 0.492 | 2.377 | 21.911 | 1.643 | 71.297 | 0.920 | 100.528
1095945 | bobr | ybsql | update | done | update newmatchstats set | 0.380 | 1.504 | 26.710 | 0.637 | 81.441 | 0.641 | 112.782
(4 rows)Join the sys.log_query, sys.log_query_analyze, and sys.log_query_explain views to return statistics and plan information for a single query.
premdb=> select a.*, e.query_plan
from sys.log_query_analyze a join sys.log_query q on q.query_id = a.query_id join sys.log_query_explain e on e.plan_id = q.plan_id and e.node_id = a.node_id
where q.query_id = 258345
order by node_id;
-[ RECORD 1 ]--------+-----------------------------------------------------------------------------------------------------------------
query_id | 258345
node_id | 0
rows_planned | 774540
rows_actual | 0
memory_planned_bytes | 0
memory_actual_bytes | 524288
io_read_bytes | 0
io_write_bytes | 0
io_network_bytes | 0
io_network_count | 0
runtime_ms | 0.000
skew | 0
detail | [NULL]
query_plan | SEQUENCE +
| distribute none
-[ RECORD 2 ]--------+-----------------------------------------------------------------------------------------------------------------
query_id | 258345
node_id | 1
rows_planned | 774540
rows_actual | 0
memory_planned_bytes | 8388696
memory_actual_bytes | 524464
io_read_bytes | 0
io_write_bytes | 0
io_network_bytes | 0
io_network_count | 8
runtime_ms | 0.000
skew | 0
detail | [NULL]
query_plan | WRITE ROW STORE +
| (newmatchstats.seasonid, newmatchstats.matchday, newmatchstats.htid, newmatchstats.atid, newmatchstats.moment) +
| distribute (newmatchstats.seasonid)
-[ RECORD 3 ]--------+-----------------------------------------------------------------------------------------------------------------
query_id | 258345
node_id | 2
rows_planned | 774540
rows_actual | 0
memory_planned_bytes | 3221225472
memory_actual_bytes | 495452160
io_read_bytes | 0
io_write_bytes | 182235136
io_network_bytes | 0
io_network_count | 0
runtime_ms | 0.000
skew | 0
detail | [NULL]
query_plan | INSERT INTO newmatchstats +
| (newmatchstats.seasonid, newmatchstats.matchday, newmatchstats.htid, newmatchstats.atid, newmatchstats.moment) +
| distribute (newmatchstats.seasonid)
-[ RECORD 4 ]--------+-----------------------------------------------------------------------------------------------------------------
query_id | 258345
node_id | 3
rows_planned | 774540
rows_actual | 49570560
memory_planned_bytes | 2097152
memory_actual_bytes | 1048576
io_read_bytes | 0
io_write_bytes | 0
io_network_bytes | 0
io_network_count | 0
runtime_ms | 4.854
skew | 0.18614919823379
detail | [NULL]
query_plan | APPEND SCAN +
| (newmatchstats.seasonid, newmatchstats.matchday, newmatchstats.htid, newmatchstats.atid, newmatchstats.moment) +
| distribute (newmatchstats.seasonid)
...Return the 10 longest-running operations in terms of total running time:
premdb=> select query_id, type, submit_time, done_time, total_ms, rank() over(order by total_ms desc) from sys.log_query limit 10;
query_id | type | submit_time | done_time | total_ms | rank
----------+--------+----------------------------+----------------------------+----------+------
258345 | insert | 2020-09-09 17:59:01.871-07 | 2020-09-09 17:59:07.801-07 | 5930.091 | 1
116626 | select | 2020-09-09 16:28:15.35-07 | 2020-09-09 16:28:18.41-07 | 3059.581 | 2
258043 | insert | 2020-09-09 17:58:57.191-07 | 2020-09-09 17:59:00.22-07 | 3029.446 | 3
140372 | select | 2020-09-09 16:47:55.137-07 | 2020-09-09 16:47:58.087-07 | 2950.050 | 4
130453 | select | 2020-09-09 16:39:08.884-07 | 2020-09-09 16:39:11.778-07 | 2894.107 | 5
234651 | select | 2020-09-09 17:48:01.518-07 | 2020-09-09 17:48:04.087-07 | 2568.231 | 6
282685 | select | 2020-09-09 18:11:07.228-07 | 2020-09-09 18:11:09.47-07 | 2241.723 | 7
276565 | select | 2020-09-09 18:08:03.255-07 | 2020-09-09 18:08:05.291-07 | 2036.606 | 8
265009 | select | 2020-09-09 18:02:18.264-07 | 2020-09-09 18:02:20.3-07 | 2035.756 | 9
150281 | select | 2020-09-09 16:52:50.278-07 | 2020-09-09 16:52:52.312-07 | 2033.339 | 10
(10 rows)Return information for a query that was restarted in a different pool:
yellowbrick=# yellowbrick=# select query_id, transaction_id, state, pool_id, num_restart, submit_time, done_time, restart_ms, total_ms from sys.log_query where query_id=2573711;
query_id | transaction_id | state | pool_id | num_restart | submit_time | done_time | restart_ms | total_ms
----------+----------------+---------+-------------------+-------------+----------------------------+----------------------------+------------+------------
2573711 | 4294974926 | done | bobr_pool | 1 | 2020-09-18 16:56:28.829-07 | 2020-09-18 17:01:22.792-07 | 1.634 | 293963.304
2573711 | 4294974926 | restart | bobr_profile: mix | 0 | 2020-09-18 16:56:28.829-07 | 2020-09-18 16:56:51.945-07 | 0.831 | 23115.227
(2 rows)Parent topic:System Views