Query Profiling Statistics
AnalyticDB PostgreSQL版提供了查询执行信息收集(Query Profiling Statistics)功能,开启该功能后,系统会自动收集并记录查询执行过程的统计信息,您可以通过系统视图浏览并检查执行较慢的SQL查询语句。
在AnalyticDB PostgreSQL版中,查询的执行过程被分解为多个算子并依次执行。在特定情况下,为了排查与分析查询执行的异常状态,需要查看查询执行过程的细节数据,例如某一特定算子执行过程消耗的时间,输入输出的行数,占用的资源(内存,I/O)等。AnalyticDB PostgreSQL版支持查询执行细节信息收集和记录,通过查询中各个算子的执行记录,您可以发现执行过程中存在的问题,进而排查并分析异常问题。
开启查询执行信息收集功能
默认情况下,查询执行信息收集功能处于关闭状态,您可以通过queryprofile.enable参数开启或关闭该功能。
- 查看当前查询执行信息收集状态:
SHOW queryprofile.enable; - 会话级别开启查询执行信息收集功能:
SET queryprofile.enable = ON; - 会话级别关闭查询执行信息收集功能:
SET queryprofile.enable = OFF; - 开启当前库的查询执行信息收集功能:
ALTER DATABASE <dbname> SET queryprofile.enable = ON;
如果需要实例级别开启或关闭Query Profiling Statistics功能,请提交工单联系技术支持进行修改。
查看查询执行信息
开启查询执行信息收集功能后,您可以通过查询执行信息提供的系统视图查看运行中或历史的查询和执行过程。
查询执行信息视图
- queryprofile.query_exec_history:用于查看历史查询的信息。
- queryprofile.query_exec_status:用于查看正在运行的查询的信息。
- queryprofile.node_exec_history:用于查看历史查询执行过程信息。
- queryprofile.node_exec_status:用于查看正在运行的查询执行过程信息。
queryprofile.query_exec_history和queryprofile.query_exec_status视图结构一致,视图中字段说明如下:
| 字段 | 类型 | 说明 |
| queryid | int8 | 查询ID,即查询的唯一标识。 |
| sessid | integer | 查询所属的会话ID。 |
| commandid | integer | 查询在其所属会话中的编号。 |
| starttime | timestamptz | 查询开始的时间。 |
| runtime | float8 | 查询运行的总时间,单位为秒(s)。 |
| stmt_text | text | 查询对应的SQL文本。 |
queryprofile.node_exec_history和queryprofile.node_exec_status视图结构一致,视图中字段说明如下:
| 字段 | 类型 | 说明 |
| queryid | int8 | 算子所属的查询ID,即查询的唯一标识。 |
| stmtid | int8 | 算子所属查询ID所对应的SQL ID。 |
| sessid | integer | 算子所属的会话ID。 |
| commandid | integer | 算子所属的查询在其会话中的编号ID。 |
| nodeid | integer | 算子在查询执行计划中的ID。 |
| sliceid | integer | 算子在执行计划中所属的Slice ID。 |
| nodetypeid | integer | 算子类型ID。 |
| nodename | text | 算子类型。 |
| tuplesout | int8 | 算子执行过程中输出的数据行数。 |
| tuplesin | int8 | 算子执行过程中输入的数据行数。 |
| tuplesplan | int8 | 算子在执行计划中的输入行数。 |
| execmem | float8 | 执行器分配给算子的内存。 |
| workmem | float8 | 算子工作占用内存。 |
| starttime | timestamptz | 算子开始执行的时间。 |
| endtime | timestamptz | 算子结束执行的时间。 |
| duration | float8 | 算子执行消耗的时间,单位为秒(s)。 说明 该字段并非算子执行开始结束执行时间的间隔(可能包含下层算子执行消耗的时间),而是该算子本身执行所消耗的时间。 |
| diskreadsize | int8 | 算子从磁盘读取数据量。 |
| diskreadtime | float8 | 算子从磁盘读取数据消耗的时间,单位为秒(s)。 |
| netiosize | int8 | 数据在不同节点间网络传输的数据量。 |
| netiotime | float8 | 数据在不同节点间网络传输消耗的时间,单位为秒(s)。 |
queryprofile.node_exec_history和queryprofile.node_exec_status视图中每一个查询算子对应一行数据,其中记录了查询执行过程中在该算子阶段的基本执行信息和消耗的资源,您可以根据视图中的信息定位到执行异常的阶段,优化查询执行过程。
查看正在运行的查询执行信息
示例1
查看正在运行的查询,SQL如下:
SELECT * FROM queryprofile.query_exec_status;示例2
查看正在运行的查询执行过程,SQL如下:
SELECT * FROM queryprofile.node_exec_status;查看历史的查询执行信息
示例1
查看历史查询,SQL如下:
SELECT * FROM queryprofile.query_exec_history;示例2
查看历史查询执行过程,SQL如下:
SELECT * FROM queryprofile.node_exec_history;修改运行中查询执行信息视图的更新频率
AnalyticDB PostgreSQL版提供了queryprofile.refresh_interval参数,用于控制queryprofile.query_exec_status和queryprofile.node_exec_status视图的更新频率,该参数值表示执行过程中执行算子每次更新统计数据所间隔的处理数据行数。
queryprofile.refresh_interval参数的默认值为1000,表示算子每读入1000行数据更新一次统计数据;0表示关闭动态收集查询执行信息功能。
您可以通过如下SQL查看查询执行信息更新频率:
SHOW queryprofile.refresh_interval;返回示例如下:
queryprofile.refresh_interval
-------------------------------
1000
(1 row)历史查询执行信息回收
AnalyticDB PostgreSQL版提供了queryprofile.max_query_num和queryprofile.query_time_limit两个参数用于控制历史查询信息回收:
- queryprofile.max_query_num:用于控制保留的最大记录数。该参数值默认为10000,即保存最近10000条历史查询信息。您可以通过如下SQL查看保留的最大记录数:
SHOW queryprofile.max_query_num; - queryprofile.query_time_limit:用于清除记录中的短查询,总执行时长低于设置阈值的查询在查询信息回收时会被优先回收,单位为秒(s)。该参数值默认为1,即总执行时长小于1秒的查询会优先回收。您可以通过如下SQL查看保留最短查询的时长:
SHOW queryprofile.query_time_limit;
例如,queryprofile.max_query_num的值为10000,queryprofile.query_time_limit的值为1时,表示查询信息数量超过10000时会触发查询信息回收,查询信息回收会优先回收总执行时长小于1s的查询信息,如果记录中已没有总执行时长小于1s的记录,系统将会从最早的查询信息开始回收。
使用示例
查询执行信息可用于排查与分析查询执行的异常状态。当查询执行信息收集处于打开状态时,系统会收集所有查询的执行过程数据,您可通过执行过程数据获得如下信息:
- 系统中慢SQL或正在执行的查询。
- 查询执行信息中包含的各个算子信息及其输入或输出行数。
- 查询执行过程中耗时多的算子。
- 单一算子执行时占用的资源量,例如内存,磁盘 I/O,网络 I/O。
操作步骤如下:
- 在当前会话中开启查询执行信息收集功能,SQL如下:
SET queryprofile.enable = ON; - 查看历史查询执行信息,此处以获取最近10条历史查询执行信息为例,SQL示例如下:
SELECT * FROM queryprofile.query_exec_history ORDER BY starttime DESC limit 10;返回示例如下:
postgres=# select * from queryprofile.query_exec_history order by starttime desc limit 10; queryid | sessid | commandid | starttime | duration | stmt_text ----------+--------+-----------+------------------------------+-----------+--------------------------------------------------------------- 6902xxx93| 51 | 2 | 2021-11-15 13:56:10.009499+08 | 7.081067 | select | | | | | o_orderpriority, | | | | | count(*) as order_count | | | | | from | | | | | tpch_row.orders | | | | | where | | | | | o_orderdate >= date '1993-07-01' | | | | | and o_orderdate < date '1993-07-01' + interval '3' month | | | | | and exists ( | | | | | select | | | | | * | | | | | from | | | | | tpch_row.lineitem | | | | | where | | | | | l_orderkey = o_orderkey | | | | | and l_commitdate < l_receiptdate | | | | | ) | | | | | group by | | | | | o_orderpriority | | | | | order by | | | | | o_orderpriority; 6902xxx15| 50 | 2 | 2021-11-15 13:55:16.851294+08 | 2.030295 | UPDATE pgbench_accounts SET abalance = abalance + 2417 WHERE aid = 2413784; 6902xxx53| 4 | 130 | 2021-11-15 13:54:21.275643+08 | 0.010542 | select * from gp_dist_wait_status(); 6902xxx61| 49 | 2 | 2021-11-15 13:53:52.169785+08 | 37.360402 | select | | | | | l_orderkey, | | | | | sum(l_extendedprice * (1 - l_discount)) as revenue, | | | | | o_orderdate, | | | | | o_shippriority | | | | | from | | | | | tpch_row.customer, | | | | | tpch_row.orders, | | | | | tpch_row.lineitem | | | | | where | | | | | c_mktsegment = 'BUILDING' | | | | | and c_custkey = o_custkey | | | | | and l_orderkey = o_orderkey | | | | | and o_orderdate < date '1995-03-15' | | | | | and l_shipdate > date '1995-03-15' | | | | | group by | | | | | l_orderkey, | | | | | o_orderdate, | | | | | o_shippriority | | | | | order by | | | | | revenue desc, | | | | | o_orderdate; 6902xxx27| 48 | 2 | 2021-11-15 13:53:34.800577+08 | 5.130622 | UPDATE pgbench_accounts SET abalance = abalance + 2417 WHERE aid = 2413784; 6902xxx96| 20 | 6 | 2021-11-15 13:53:07.890833+08 | 0.005257 | select * from queryprofile.query_exec_history order by starttime desc limit 10; 6902xxx65| 20 | 4 | 2021-11-15 13:52:59.982712+08 | 0.004991 | select * from queryprofile.query_exec_history order by starttime desc limit 10; 6902xxx63| 20 | 2 | 2021-11-15 13:52:31.892249+08 | 0.085879 | INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (137, 86, 2837845, 3097, CURRENT_TIMESTAMP); 6902xxx34| 47 | 179 | 2021-11-15 13:52:27.419061+08 | 0.001344 | SELECT abalance FROM pgbench_accounts WHERE aid = 2884169 and bid = 17; 6902xxx24| 47 | 177 | 2021-11-15 13:52:27.416713+08 | 0.001163 | INSERT INTO pgbench_tellers values(677, 65, 0); (10 rows) - 从以上返回结果中找到需要分析的查询执行信息,使用从queryprofile.query_exec_history视图中获取的queryid字段,在queryprofile.node_exec_history视图中获取该查询的执行过程,SQL示例如下:
SELECT * FROM queryprofile.node_exec_history WHERE queryid = 6902*********93;返回示例如下:
postgres=# select * from queryprofile.node_exec_history where queryid = 6902xxx93; queryid | stmtid | sessid | commandid | nodeid | sliceid | nodetypeid | nodename | tuplesout | tuplesin | tuplesplan | execmem | workmem | starttime | endtime | duration | diskreadsize | diskreadtime | netiosize ---------+--------+--------+-----------+--------+---------+------------+---------------------+-----------+----------+------------+---------+---------+-----------------------------------+-----------------------------------+----------+--------------+--------------+----------- 690270970009093 | 690270970009093 | 51 | 2 | 10 | 1 | 134 | Hash Aggregate | 2290502 | 6316985 | 1611885 | 65210K | 98817K | 2021-11-15 13:56:10.026638+08 | 2021-11-15 13:56:16.969234+08 | 2.408 | 55296K | 0.000 | 0K 690270970009093 | 690270970009093 | 51 | 2 | 3 | 2 | 133 | Sort | 3 | 3 | 5 | 129K | 65K | 2021-11-15 13:56:10.024229+08 | 2021-11-15 13:56:17.087943+08 | 0.003 | 0K | 0.000 | 0K 690270970009093 | 690270970009093 | 51 | 2 | 9 | 1 | 138 | Hash | 0 | 0 | 1611885 | 83969K | 42534K | 2021-11-15 13:56:10.026638+08 | 2021-11-15 13:56:16.969272+08 | 0.000 | 0K | 0.000 | 0K 690270970009093 | 690270970009093 | 51 | 2 | 2 | 1 | 134 | Hash Aggregate | 5 | 87606 | 5 | 0K | 0K | 2021-11-15 13:56:10.026631+08 | 2021-11-15 13:56:16.969343+08 | 0.014 | 0K | 0.000 | 0K 690270970009093 | 690270970009093 | 51 | 2 | 2 | 2 | 134 | Group Aggregate | 1 | 3 | 1 | 0K | 0K | 2021-11-15 13:56:10.024223+08 | 2021-11-15 13:56:17.088002+08 | 0.000 | 0K | 0.000 | 0K 690270970009093 | 690270970009093 | 51 | 2 | 7 | 1 | 131 | Hash Join | 87606 | 2386083 | 1611885 | 0K | 0K | 2021-11-15 13:56:10.026636+08 | 2021-11-15 13:56:16.969308+08 | 0.981 | 24544K | 0.000 | 0K 690270970009093 | 690270970009093 | 51 | 2 | 4 | 2 | 142 | Redistribute Motion | 3 | 3 | 5 | 0K | 0K | 2021-11-15 13:56:10.024238+08 | 2021-11-15 13:56:17.087545+08 | 7.060 | 0K | 0.000 | 1K 690270970009093 | 690270970009093 | 51 | 2 | 8 | 1 | 111 | Seq Scan | 95581 | 2497711 | 2310848 | 1 | 0K | 2021-11-15 13:56:10.026636+08 | 2021-11-15 13:56:16.96899+08 | 0.879 | 354144K | 0.000 | 0K 690270970009093 | 690270970009093 | 51 | 2 | 5 | 0 | 142 | Gather Motion | 5 | 5 | 5 | 0K | 0K | 2021-11-15 13:56:10.009499+08 | 2021-11-15 13:56:17.090556+08 | 7.063 | 0K | 0.000 | 1K 690270970009093 | 690270970009093 | 51 | 2 | 11 | 1 | 111 | Seq Scan | 6316985 | 9990397 | 11999982 | 1 | 0K | 2021-11-15 13:56:10.026648+08 | 2021-11-15 13:56:16.969189+08 | 2.659 | 1524640K | 0.000 | 0K (10 rows)从返回结果中可以看到算子名称、耗时、输入行数、输出行数、占用资源等信息。您可根据表中结果对每一个算子的执行记录进行分析,以定位和解决性能问题。