慢Query的查询与分析可以帮助您对系统中发生的慢Query或失败Query进行诊断、分析和采取优化措施。本文将介绍在Hologres中如何查看慢Query日志并分析。
使用限制
- 该功能仅Hologres V0.10及以上版本支持,请在Hologres管理控制台的实例详情页查看当前实例版本,如果您的实例是V0.10以下版本,请您使用自助升级或通过搜索(钉钉群号:32314975)加入实时数仓Hologres交流群申请升级实例。
- 慢Query日志默认保留一个月的数据,但是HoloWeb仅支持查最近7天的数据,如果需要查询一个月内的数据请使用SQL进行查询。
- 慢Query日志记录所有的DDL语句、所有执行失败的SQL语句以及执行时间大于一秒的SQL语句(例如INSERT、SELECT、UPDATE、DELETE等)。
- 为了保证系统稳定性,避免流量超载,单次查询最多从服务器端传输10000条慢Query日志。
- 当前SQL记录的上限是51200个字符,超过可能会被截断。
- 对于慢Query日志中的
plan
字段,SQL运行超过10s
才会记录,可以通过GUC参数log_min_duration_query_plan
修改记录时长,使用详情请参见配置项。 - Hologres V0.10版本的FAILED Query,不显示内存、读盘、读取量、CPU时间、query_stats等运行时的统计信息。
查看query_log表
1s
的Query,若需要展示100ms~1s
内的Query,请按照下面的配置项修改展示时间)。其主要包含的字段信息如下:字段 | 字段类型 | 说明 |
---|---|---|
usename | text | 查询的用户名。 |
status | text | 查询的最终状态,成功或失败。
|
query_id | text | Query的ID,代表Query的唯一性。 失败的Query一定会有query_id,成功的Query不一定会有。 |
datname | text | 查询的数据库名称。 |
command_tag | text | 查询的类型。 包括:
|
duration | integer | 查询的耗时(ms)。duration 代表SQL的总耗时时间,包含:
|
message | text | 报错的信息。 |
query_start | timestamptz | 查询开始时间。 |
query_date | text | 查询开始日期。 |
query | text | 查询的文本内容。 |
result_rows | bigint | 返回的行数。 如果是INSERT命令,则返回插入的行数。 |
result_bytes | bigint | 返回的字节数。 |
read_rows | bigint | 读取的数据行数。 非精确值。如果使用了Bitmap索引,跟实际的扫描行数有差别。 |
read_bytes | bigint | 读取的字节数。 |
affected_rows | bigint | DML影响的行数。 |
affected_bytes | bigint | DML影响的字节数。 |
memory_bytes | bigint | 各节点上使用的内存峰值的累加值(非精确)。 代表Query在所有运行节点上使用的内存峰值的累加值。粗略地体现Query的数据读取量。 |
shuffle_bytes | bigint | 数据Shuffle估计字节数(非精确)。 粗略地体现数据在网络中的传输量。 |
cpu_time_ms | bigint | 总的CPU时间(毫秒,非精确)。 体现所有计算任务所耗费的CPU时间,是多个CPU Core计算时间的累加,粗略地体现复杂度。 |
physical_reads | bigint | 物理读的次数。 反映从磁盘读取Record Batch的次数,粗略地体现内存缓存未命中数量。 |
pid | integer | 查询服务进程ID。 |
application_name | text | 查询应用类型。 其中常见的应用类型如下:
|
engine_type | text[] | 查询用到的引擎。 包含如下引擎类型:
|
client_addr | text | Query的来源地址。 代表应用的出口IP,不一定是真实的应用IP。 |
table_write | text | SQL写入的表。 |
table_read | text[] | SQL读取的表。 |
session_id | text | Session ID。 |
session_start | timestamptz | Session开启时间。 代表连接开始建立的时间。 |
command_id | text | 命令或语句编号ID。 |
optimization_cost | integer | 查询执行计划的耗时。 耗时较高通常情况是SQL较复杂。 |
start_query_cost | integer | 查询启动耗时。 耗时较高通常是因为在等锁或者等待资源。 |
get_next_cost | integer | 查询执行耗时。 耗时较高通常是因为计算量太大,执行时间较长,可根据业务情况优化SQL。 |
extended_cost | text | 查询的其他详细耗时。 除optimization_cost 、start_query_cost 、get_next_cost三个耗时之外的其他耗时,可以通过 extend_cost 字段进一步查看,通常包括如下耗时。
|
plan | text | 查询对应的执行计划。 |
statistics | text | 查询对应的执行时统计信息。 |
visualization_info | text | 查询Plan可视化信息。 |
query_detail | text | 查询的其他扩展信息(JSON格式存储)。 |
query_extinfo | text[] | 查询的其他扩展信息(ARRAY格式存储)。 |
授予查看权限
慢Query日志需要有一定的权限才能查看,其权限规则和授权方式说明如下:
- 查看实例所有DB的慢Query日志。
- 授予用户Superuser权限。Superuser账号可以查看实例所有DB的全部慢Query日志,给用户授予Superuser用户的权限,使用户有权限查看实例所有DB的慢Query日志。
ALTER USER "云账号ID" SUPERUSER;--将“云账号ID”替换为实际用户名。如果是RAM用户,账号ID前需要添加“p4_”。
- 将用户添加到pg_read_all_stats用户组。除Superuser外,Hologres还支持pg_read_all_stats用户组查看所有DB慢Query日志,普通用户如果需要查看所有日志,可以联系Superuser授权加入该用户组。授权方式如下:
GRANT pg_read_all_stats TO "云账号ID";--专家权限模型授权 CALL spm_grant('pg_read_all_stats', '云账号ID'); -- SPM权限模型 CALL slpm_grant('pg_read_all_stats', '云账号ID'); -- SLPM权限模型
- 授予用户Superuser权限。
- 查看本DB的慢Query日志。开启简单权限模型(SPM)或基于Schema级别的简单权限模型(SLPM),将用户加入db_admin用户组,db_admin角色可以查看本DB的query日志。
CALL spm_grant('<db_name>_admin', '云账号ID'); -- SPM权限模型 CALL slpm_grant('<db_name>.admin', '云账号ID'); -- SLPM权限模型
- 普通用户只能查询当前账号对应DB下自己执行的慢Query日志。
HoloWeb可视化查看慢Query
- 当前HoloWeb支持查看最多七天的历史慢Query日志。
- 仅支持Superuser账号查看,普通有权限的账号请使用SQL命令查看。
- 登录HoloWeb控制台,详情请参见连接HoloWeb。
- 单击顶部导航栏的诊断与优化。
- 在左侧导航栏单击历史慢Query。
- 在历史慢Query页面顶部,编辑查询条件。
参数说明请参见历史慢Query。
- 单击查询,在Query趋势分析和Query列表区域展示查询结果。
- Query趋势分析
Query趋势分析通过可视化的方式展示近期慢Query、失败Query发生的趋势,可以重点监控慢Query发生频率较高的阶段,更好的定位问题高发期并集中解决问题。
- Query列表
Query列表可视化展示慢Query、失败Query的详细信息,参数说明请参见历史慢Query。也可以单击自定义列选择Query列表需要展示的列信息。
- Query趋势分析
诊断Query
- 查询query_log总查询数
- 查询每个用户的慢Query情况
- 查询某个慢Query的具体信息
- 查询最近10分钟消耗比较高的Query
- 查看最近3小时内每小时的Query访问量和数据读取总量
- 查看与昨天同一时间对比过去3小时的数据访问量情况
- 查询最近10分钟Query各阶段耗时比较高的Query
- 查询最先失败的Query
- 查询query_log总查询数(默认为近1个月内的数据)。
执行结果具体如下,表示近1个月内总共执行了44个耗时大于指定阈值的Query。select count(*) from hologres.hg_query_log;
count ------- 44 (1 row)
- 查询每个用户的慢Query个数。
执行结果具体如下,其中select usename as "用户", count(1) as "Query个数" from hologres.hg_query_log group by usename order by count(1) desc;
count(1)
的单位是个数。用户 | Query个数 -----------------------+----- 1111111111111111 | 27 2222222222222222 | 11 3333333333333333 | 4 4444444444444444 | 2 (4 rows)
- 查询某个慢Query的具体信息。
执行结果具体如下,更多关于各参数的说明,请参见查看query_log表。select * from hologres.hg_query_log where query_id = '13001450118416xxxx';
usename | status | query_id | datname| command_tag | duration | message | query_start | query_date | query | result_rows | result_bytes | read_rows |read_bytes | affected_rows | affected_bytes | memory_bytes | shuffle_bytes | cpu_time_ms | physical_reads | pid | application_name | engine_type | client_addr | table_write | table_read | session_id | session_start | command_id | optimization_cost | start_query_cost | get_next_cost | extended_cost | plan | statistics | visualization_info | query_detail | query_extinfo -----------------------+---------+--------------------+---------+-------------+----------+---------+------------------------+------------+---------------------------------------------------------------------------------------------------------+-------------+--------------+-----------+------------+---------------+----------------+--------------+---------------+-------------+----------------+---------+------------------+-------------+---------------+-------------+------------+-----------------+------------------------+------------+-------------------+------------------+---------------+---------------+------+------------+--------------------+--------------+--------------- p4_11111111111xxxx | SUCCESS | 13001450118416xxxx | dbname | SELECT | 149 | | 2021-03-30 23:45:01+08 | 20210330 | explain analyze select * from tablename where user_id = '20210330010xxxx' limit 1000; | 1000 | 417172 | 0 | 0 | -1 | -1 | 26731376 | 476603616 | 321626 | 0 | 1984913 | psql | {HQE} | 33.41.xxx.xxx | | | 6063475a.1e4991 | 2021-03-30 23:44:26+08 | 0 | 58 | 22 | 67 | | | | | | (1 row)
- 查询最近某个时间段(如10分钟)消耗比较高的Query。您也可以根据业务需求修改具体时间,查询目标时间段消耗比较高的Query。
执行结果具体如下:select status as "状态", duration as "耗时(ms)", query_start as "开始时间", (read_bytes/1048576)::text || ' MB' as "读取量", (memory_bytes/1048576)::text || ' MB' as "内存", (shuffle_bytes/1048576)::text || ' MB' as "Shuffle", (cpu_time_ms/1000)::text || ' s' as "CPU时间", physical_reads as "读盘", query_id as "QueryID", query::char(30) from hologres.hg_query_log where query_start >= now() - interval '10 min' order by duration desc, read_bytes desc, shuffle_bytes desc, memory_bytes desc, cpu_time_ms desc, physical_reads desc limit 100;
状态 | 耗时(ms) | 开始时间 | 读取量 | 内存 | Shuffle | CPU时间 | 读盘 | QueryID | query ---------+---------+------------------------+--------+-------+---------+---------+------+--------------------+-------------------------------- SUCCESS | 149 | 2021-03-30 23:45:01+08 | 0 MB | 25 MB | 454 MB | 321 s | 0 | 13001450118416xxxx | explain analyze select * from SUCCESS | 137 | 2021-03-30 23:49:18+08 | 247 MB | 21 MB | 213 MB | 803 s | 7771 | 13001491818416xxxx | explain analyze select * from FAILED | 53 | 2021-03-30 23:48:43+08 | 0 MB | 0 MB | 0 MB | 0 s | 0 | 13001484318416xxxx | select ds::bigint / 0 from pub (3 rows)
- 查看最近3小时内每小时的Query访问量和数据读取总量,用于对比判断每个小时是否有数据量变化。
SELECT date_trunc('hour', query_start) AS query_start, count(1) AS query_count, sum(read_bytes) AS read_bytes, sum(cpu_time_ms) AS cpu_time_ms FROM hologres.hg_query_log WHERE query_start >= now() - interval '3 h' GROUP BY 1;
- 查看与昨天同一时间对比过去3小时的数据访问量情况,用于判断相较于昨日是否有数据量访问变化。
SELECT query_date, count(1) AS query_count, sum(read_bytes) AS read_bytes, sum(cpu_time_ms) AS cpu_time_ms FROM hologres.hg_query_log WHERE query_start >= now() - interval '3 h' GROUP BY query_date UNION ALL SELECT query_date, count(1) AS query_count, sum(read_bytes) AS read_bytes, sum(cpu_time_ms) AS cpu_time_ms FROM hologres.hg_query_log WHERE query_start >= now() - interval '1d 3h' AND query_start <= now() - interval '1d' GROUP BY query_date;
- 查询最近时间段(如最近10分钟)Query各阶段耗时比较高的Query。您也可以根据业务需求修改具体时间,查询目标时间段Query各阶段耗时比较高的Query。
执行结果具体如下:select status as "状态", duration as "耗时(ms)", optimization_cost as "优化耗时(ms)", start_query_cost as "启动耗时(ms)", get_next_cost as "执行耗时(ms)", duration-optimization_cost-start_query_cost-get_next_cost as "其他耗时(ms)", query_id as "QueryID", query::char(30) from hologres.hg_query_log where query_start >= now() - interval '10 min' order by duration desc, start_query_cost desc, optimization_cost, get_next_cost desc, duration-optimization_cost-start_query_cost-get_next_cost desc limit 100;
状态 | 耗时(ms) | 优化耗时(ms) | 启动耗时(ms) | 执行耗时(ms) | 其他耗时(ms) | QueryID | query ---------+----------+--------------+--------------+--------------+--------------+--------------------+-------------------------------- SUCCESS | 4572 | 521 | 320 | 3726 | 5 | 6000260625679xxxx | -- /* user: wang ip: xxx.xx.x SUCCESS | 1490 | 538 | 98 | 846 | 8 | 12000250867886xxxx | -- /* user: lisa ip: xxx.xx.x SUCCESS | 1230 | 502 | 95 | 625 | 8 | 26000512070295xxxx | -- /* user: zhang ip: xxx.xx. (3 rows)
- 查询最先失败的Query。
执行结果具体如下:select status as "状态", regexp_replace(message, '\n', ' ')::char(150) as "报错信息", duration as "耗时(ms)", query_start as "开始时间", query_id as "QueryID", query::char(100) as "Query" from hologres.hg_query_log where query_start between '2021-03-25 17:00:00'::timestamptz and '2021-03-25 17:42:00'::timestamptz + interval '2 min' and status = 'FAILED' order by query_start asc limit 100;
状态 | 报错信息 | 耗时(ms) | 开始时间 | QueryID | Query --------+--------------------------------------------------------------------------------------------------------------------------------------------------------+-------+------------------------+-------------------+------- FAILED | Query:[1070285448673xxxx] code: kActorInvokeError msg: "[holo_query_executor.cc:330 operator()] HGERR_code XX000 HGERR_msge internal error: status { c | 1460 | 2021-03-25 17:28:54+08 | 1070285448673xxxx | S... FAILED | Query:[1016285560553xxxx] code: kActorInvokeError msg: "[holo_query_executor.cc:330 operator()] HGERR_code XX000 HGERR_msge internal error: status { c | 131 | 2021-03-25 17:28:55+08 | 1016285560553xxxx | S... (2 rows)
慢Query日志导出
Hologres支持使用INSERT语句将慢Query日志(hg_query_log)中的数据导出到您自定义的内部表或者MaxCompute、OSS等外部表。
- 注意事项。为了正确和高效地导出慢Query日志中的数据,您需要注意以下几点。
- 执行
INSERT INTO ... SELECT ... FROM hologres.hg_query_log;
的账号,需要有hologres.hg_query_log
表的相应访问权限,详情请参见授予查看权限。如果需要导出全实例的慢Query日志,则需要执行INSERT
命令的账号拥有Superuser或者pg_read_all_stats权限,否则查询的hologres.hg_query_log
表数据不全,导致导出的数据不完整。 - query_start是慢Query日志表的索引,按照时间范围导出时,查询条件请带上
query_start
列来选择时间范围,这样性能更好,资源消耗更少。 - 使用
query_start
筛选时间范围时,不要在query_start
上再嵌套表达式,否则会妨碍索引命中。例如where to_char(query_start, 'yyyymmdd') = '20220101';
更好的写法应该是:where query_start >= to_char('20220101', 'yyyy-mm-dd') and query_start < to_char('20220102', 'yyyy-mm-dd') ;
。
- 执行
- 示例一:导出至Hologres内部表。
在Hologres中执行如下命令将慢Query日志导出至query_log_download内部表。
--Hologres SQL CREATE TABLE query_log_download ( usename text, status text, query_id text, datname text, command_tag text, duration integer, message text, query_start timestamp with time zone, query_date text, query text, result_rows bigint, result_bytes bigint, read_rows bigint, read_bytes bigint, affected_rows bigint, affected_bytes bigint, memory_bytes bigint, shuffle_bytes bigint, cpu_time_ms bigint, physical_reads bigint, pid integer, application_name text, engine_type text[], client_addr text, table_write text, table_read text[], session_id text, session_start timestamp with time zone, trans_id text, command_id text, optimization_cost integer, start_query_cost integer, get_next_cost integer, extended_cost text, plan text, statistics text, visualization_info text, query_detail text, query_extinfo text[] ); INSERT INTO query_log_download SELECT usename, status, query_id, datname, command_tag, duration, message, query_start, query_date, query, result_rows, result_bytes, read_rows, read_bytes, affected_rows, affected_bytes, memory_bytes, shuffle_bytes, cpu_time_ms, physical_reads, pid, application_name, engine_type, client_addr, table_write, table_read, session_id, session_start, trans_id, command_id, optimization_cost, start_query_cost, get_next_cost, extended_cost, plan, statistics, visualization_info, query_detail, query_extinfo FROM hologres.hg_query_log where query_start >= '2022-08-03' and query_start < '2022-08-04';
- 示例二:导出至MaxCompute外部表。
- 在MaxCompute侧使用如下命令创建接收数据的表。
CREATE TABLE if NOT EXISTS mc_holo_query_log ( username STRING COMMENT '查询的用户名' ,status STRING COMMENT '查询的最终状态,成功或失败' ,query_id STRING COMMENT '查询ID' ,datname STRING COMMENT '查询的数据库名' ,command_tag STRING COMMENT '查询的类型' ,duration BIGINT COMMENT '查询的耗时(ms)' ,message STRING COMMENT '报错的信息' ,query STRING COMMENT '查询的文本内容' ,read_rows BIGINT COMMENT '查询读取的行数' ,read_bytes BIGINT COMMENT '查询读取的字节数' ,memory_bytes BIGINT COMMENT '单节点峰值内存消耗(非精确)' ,shuffle_bytes BIGINT COMMENT '数据Shuffle估计字节数(非精确)' ,cpu_time_ms BIGINT COMMENT '总的CPU时间(毫秒,非精确)' ,physical_reads BIGINT COMMENT '物理读的次数' ,application_name STRING COMMENT '查询应用类型' ,engine_type ARRAY<STRING> COMMENT '查询用到的引擎' ,table_write STRING COMMENT 'SQL改写的表' ,table_read ARRAY<STRING> COMMENT 'SQL读取的表' ,plan STRING COMMENT '查询对应的plan' ,optimization_cost BIGINT COMMENT '查询执行计划的耗时' ,start_query_cost BIGINT COMMENT '查询启动耗时' ,get_next_cost BIGINT COMMENT '查询执行耗时' ,extended_cost STRING COMMENT '查询的其他详细耗时' ,query_detail STRING COMMENT '查询的其他扩展信息(JSON格式存储)' ,query_extinfo ARRAY<STRING> COMMENT '查询的其他扩展信息(ARRAY格式存储)' ,query_start STRING COMMENT '查询开始时间' ,query_date STRING COMMENT '查询开始日期' ) COMMENT 'hologres instance query log daily' PARTITIONED BY ( ds STRING COMMENT 'stat date' ) LIFECYCLE 365; ALTER TABLE mc_holo_query_log ADD PARTITION (ds=20220803);
- 在Hologres侧使用如下命令将慢Query日志导出至MaxCompute外部表。
IMPORT FOREIGN SCHEMA project_name LIMIT TO (mc_holo_query_log) FROM SERVER odps_server INTO public; INSERT INTO mc_holo_query_log SELECT usename as username, status, query_id, datname, command_tag, duration, message, query, read_rows, read_bytes, memory_bytes, shuffle_bytes, cpu_time_ms, physical_reads, application_name, engine_type, table_write, table_read, plan, optimization_cost, start_query_cost, get_next_cost, extended_cost, query_detail, query_extinfo, query_start, query_date ,'20220803' from hologres.hg_query_log where query_start >= '2022-08-03' and query_start < '2022-08-04';
- 在MaxCompute侧使用如下命令创建接收数据的表。
配置项
- log_min_duration_statement
- 函数说明该配置项记录Query耗时,系统默认记录大于100ms的Query,查询结果仅展示1s及以上的Query,也可以通过修改该配置项,修改默认展示时间(展示时间最小可设置为100ms)。打开该配置项可以方便地跟踪需要优化的查询。如果某个语句的执行时间大于或者等于该毫秒数,慢Query日志会记录该语句、执行时间以及其它信息。该参数取值设置为-1则表示不记录任何查询。说明 只支持超级用户(Superuser)修改该配置项。
- 使用示例
- 设置当前DB记录大于10s的Query,需要Superuser设置。
ALTER DATABASE dbname SET log_min_duration_statement = '10s';
- 设置当前Session记录大于10s的Query,普通用户可以执行。
SET log_min_duration_statement = '10s';
- 设置当前DB记录大于10s的Query,需要Superuser设置。
- 函数说明
- log_min_duration_query_stats
- 函数说明该配置项记录Query执行时统计信息,系统默认将记录大于10s的Query执行时的统计信息,打开这个选项主要用来跟踪需要优化的查询。如果某个语句的执行时间大于或者等于该数值,慢Query日志会记录该语句执行时的统计信息,包括Query在各个执行环节的执行信息。该参数取值设置为-1则表示关闭对query stats信息的记录。该信息存储量较高,记录较多时会降低查询分析慢Query日志的速度。因此,可以在排查具体问题时设置小于10s,否则不建议调整为更小的值。说明 支持普通用户根据业务情况修改该配置项。
- 使用示例
- 设置当前DB记录大于10s的Query执行时的统计信息,需要Superuser设置。
ALTER DATABASE dbname SET log_min_duration_query_stats = '10s';
- 设置当前Session记录大于10s的Query执行时的统计信息,普通用户可以执行。
SET log_min_duration_query_stats = '10s';
- 设置当前DB记录大于10s的Query执行时的统计信息,需要Superuser设置。
- 函数说明
- log_min_duration_query_plan
- 函数说明该配置项记录Query的执行计划信息,系统将会默认展示大于等于10s的慢Query日志的执行计划。如果某个语句的执行时间大于或者等于该数值,慢Query日志会记录该语句的执行计划。执行计划一般情况下可以即时地通过explain得到,无需记录。该参数取值设置为-1则表示关闭对Query执行计划的记录。说明 支持普通用户根据业务情况修改该配置项。
- 使用示例
- 设置当前DB记录大于10s的Query日志的执行计划,需要Superuser设置。
ALTER DATABASE dbname SET log_min_duration_query_plan = '10s';
- 设置当前Session记录大于10s的Query日志的执行计划,普通用户可以执行。
SET log_min_duration_query_plan = '10s';
- 设置当前DB记录大于10s的Query日志的执行计划,需要Superuser设置。
- 函数说明
常见问题
- 问题现象:
在Hologres V1.1版本中,查看慢Query日志,无法显示查询行数、返回行数等信息。
- 可能原因:
慢Query日志采集不完整。
- 解决方法:在Hologres V1.1.36至V1.1.49版本可以通过如下GUC参数使其显示完整。在HologresV1.1.49及以上版本可直接显示。说明 如果您的Hologres实例版本低于 V1.1.36,请您使用自助升级或通过搜索(钉钉群号:32314975)加入实时数仓Hologres交流群申请升级实例。
db_name为数据库名称。--(建议)数据库级别,一个db设置一次即可。 alter databse <db_name> set hg_experimental_force_sync_collect_execution_statistics = on; --session级别 set hg_experimental_force_sync_collect_execution_statistics = on;