sys.log_query
This view records the history of SQL operations and bulk loads performed over the past seven days (by default).
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 |
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 When the |
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
|
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 |
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).
|
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 For single-worker queries, this value
should be equal to |
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:
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).
|
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.
|
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.
|
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.
|
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.
|
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.
|
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.
|
wait_run_spool_ms | decimal(18,3) | Time spent spooling the data after the worker was finished running the query.
|
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:
|
total_ms | decimal(18,3) | The total duration of the query. The following timings overlap and do not
contribute to the
|
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
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)
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)
...
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)
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)
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)