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 the SMC.

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, yb-smc, 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.)
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 is the CPU time on that worker.

NULL before entering the run state, then 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 after the worker was finished running the query.

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

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 the five longest-running database replication restore operations that started on a specific date:
premdb=# select query_id, transaction_id, username, application_name, database_name, type, total_ms, submit_time 
from sys.log_query 
where application_name='replication service' and type='restore' and submit_time::date='2020-08-03' 
order by total_ms desc limit 5;
 query_id | transaction_id |     user_name      |  application_name   |   database_name   |  type   | total_ms  |         start_time         
----------+----------------+--------------------+---------------------+-------------------+---------+-----------+----------------------------
    98093 |          17980 | sys_ybd_replicator | replication service | premdb_replicated | restore | 15140.243 | 2020-08-03 13:20:20.704-07
    40248 |           5492 | sys_ybd_replicator | replication service | premdb_replicated | restore | 11287.063 | 2020-08-03 12:34:20.885-07
    38158 |           4998 | sys_ybd_replicator | replication service | premdb_replicated | restore |  3855.906 | 2020-08-03 12:33:21.077-07
    33489 |           3829 | sys_ybd_replicator | replication service | premdb_replicated | restore |  3304.325 | 2020-08-03 12:30:36.281-07
    33167 |           3829 | sys_ybd_replicator | replication service | premdb_replicated | restore |  1919.030 | 2020-08-03 12:30:32.753-07
(5 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)