Analyzing SQL Execution Time with GBase 8c System View

#database

GBase 8c is a multimodal database that supports both primary-standby and distributed deployment modes. It provides rich internal tools, system tables, and views for diagnosing faults and performance issues. This article explains how to analyze SQL execution time using the dbe_perf.statement system view.

1. Overview

The dbe_perf.statement view is built on the get_instr_unique_sql() internal function. This function can display time information for SQL queries executed on a distributed CN node or the primary node in a primary-standby setup, including total execution time, executor time, and optimizer time.

The view can only be queried on a CN or primary node, not on standby nodes. The data for the get_instr_unique_sql() function comes from the g_instance.stat_cxt.UniqueSQLHashtbl hash table. Since the hash table has limited memory, it cannot store information for all SQL queries. You can adjust the number of SQL entries recorded by dbe_perf.statement by configuring the instr_unique_sql_count GUC parameter (default is 100). When a node is restarted, the contents of the hash table are cleared.

2. Example

The following example demonstrates how to retrieve statistics for the SQL statement UPDATE bmsql_warehouse SET w_ytd = w_ytd + $1 WHERE w_id = $2 during a benchmarksql test.

test=# SELECT * FROM dbe_perf.statement WHERE query ~ 'UPDATE bmsql_warehouse';

Result:

[ RECORD 1 ]
--------+----------------------------------------------------------------------
node_name            | cn1
node_id              | -1178713634
user_name            | test1
user_id              | 16974
unique_sql_id        | 739002000
query                | UPDATE bmsql_warehouse     SET w_ytd = w_ytd + $1     WHERE w_id = $2
n_calls              | 9339
min_elapse_time      | 150
max_elapse_time      | 26529
total_elapse_time    | 2512361
n_returned_rows      | 0
n_tuples_fetched     | 0
n_tuples_returned    | 0
n_tuples_inserted    | 0
n_tuples_updated     | 0
n_tuples_deleted     | 0
n_blocks_fetched     | 1
n_blocks_hit         | 1
n_soft_parse         | 0
n_hard_parse         | 0
db_time              | 2929210
CPU_time             | 906947
execution_time       | 0
parse_time           | 24
plan_time            | 0
rewrite_time         | 9
pl_execution_time    | 0
pl_compilation_time  | 0
data_io_time         | 0
net_send_info        | {"time":215081， "n_calls":28017， "size":1285855}
net_recv_info        | {"time":1385396， "n_calls":26612， "size":884261}
net_stream_send_info | {"time":0， "n_calls":0， "size":0}
net_stream_recv_info | {"time":0， "n_calls":0， "size":0}
last_updated         | 2022-12-12 13:51:59.767953+08
sort_count           | 0
sort_time            | 0
sort_mem_used        | 0
sort_spill_count     | 0
sort_spill_size      | 0
hash_count           | 0
hash_time            | 0
hash_mem_used        | 0
hash_spill_count     | 0
hash_spill_size      | 0

From this information, we can deduce:

This SQL statement was executed 9,339 times during the test.
The average execution time is calculated as db_time / n_calls = 313μs.
The actual CPU time spent is CPU_time / n_calls = 97μs.
Since this SQL uses lightproxy, plan_time, rewrite_time, and execution_time are all 0.

3. Field Descriptions

n_calls: The number of times this SQL was executed. All the times listed below are cumulative; divide by n_calls to get average times.
db_time: The total execution time for the SQL, measured from when the ReadCommand receives a message from the client to when the ReadyForQuery message is sent back.
CPU_time: Similar to db_time, but measured using clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tv), meaning only CPU time is counted (excluding time spent in the kernel).
parse_time: Time spent in the pg_parse_query function generating the query tree.
plan_time: Time spent by the planner function in generating the execution plan.
rewrite_time: Time spent in the pg_rewrite_query function rewriting the query.
execution_time: Time spent by the PortalRun function during query execution.
data_io_time: Time spent fetching blocks from tables. This is usually small because the CN only has metadata.
net_send_info: Information on how many times the CN sent execution plans or SQL to the DN, how much time it took, and the size of the data.
net_recv_info: Similar to net_send_info, but for data received by the CN from the DN.

4. Clearing Statistics

If you want to clear the statistics and restart the collection, you can call the reset_unique_sql function.

reset_unique_sql has three parameters:

The first parameter can be either global or local, indicating whether to clear global or local SQL data.
The second parameter, cleanType, should be set to all.
The third parameter, cleanValue, should be set to 0.

After calling this function, the view will be cleared:

test=# select reset_unique_sql('local'， 'all'， 0);
-[ RECORD 1 ]----+--
reset_unique_sql | t
test=# select * from dbe_perf.statement where query ~ 'UPDATE bmsql_warehouse';
(No rows)
test=#