当Hologres实例出现响应或查询速度变慢时,您可以查看与分析慢Query日志快速定位问题所在。慢Query的查看与分析可以帮助您对系统中发生的慢Query或失败Query进行识别、诊断和分析,并进一步采取优化措施,以提高系统整体性能。本文为您介绍在Hologres中如何查看慢Query日志并分析。
版本说明
Hologres版本号 | 功能 | 说明 |
V0.10 | 新增慢Query日志查看与分析功能。 |
|
V2.2.7 | 优化log_min_duration_statement参数默认值 | 慢Query日志记录所有的DDL语句、所有执行失败的SQL语句以及执行时间大于 从Hologres V2.2.7版本开始,将 |
使用限制
在Hologres中查询慢Query日志,具体限制如下:
慢Query日志默认保留一个月的数据,但是HoloWeb仅支持查最近7天的数据,如果需要查询一个月内的数据请使用SQL进行查询。
为了保证系统稳定性,避免流量超载,单次查询最多返回10000条慢Query日志。慢Query日志中的部分字段有长度限制,详情请参见
query_log
表字段说明。慢Query日志属于Hologres的元仓系统,慢Query日志查询失败不会影响实例中的业务Query运行,故慢Query日志的稳定性不在产品的SLA保护范围内。
查看query_log表
Hologres的慢Query查询日志存储于hologres.hg_query_log系统表中,其中:
在实例升级至V0.10版本后,将会默认采集执行时间大于100 ms的慢DML Query以及所有的DDL操作。
自V3.0.2版本开始,支持在原有的hologres.hg_query_log中,使用聚合方式记录执行时间小于100 ms的DML和查询的记录。
系统会将执行时间小于100 ms,成功且有指纹的Query(DQL和DML)操作进行聚合记录。
聚合的主要列为:server_addr、usename、datname、warehouse_id、application_name、digest。
每个连接每分钟会汇总一次后上报。
hologres.hg_query_log系统表,包含的字段信息介绍如下。
字段 | 字段类型 | 100 ms以上DML和DQL明细记录含义说明 | 100 ms以下DML和DQL聚合记录含义说明 |
usename | text | 查询的用户名。 | 查询的用户名。 |
status | text | 查询的最终状态,成功或失败。
| 查询的最终状态,成功(SUCCESS),聚合数据仅记录成功的记录。 |
query_id | text | Query的ID,代表Query的唯一性。 失败的Query一定会有query_id,成功的Query不一定会有。 | 聚合周期内,同聚合主键第一个Query的Query ID。 |
digest | text | SQL指纹编码。 对于SELECT、INSERT、DELETE、UPDATE类型的Query,系统会计算一个MD5哈希值作为该Query的SQL指纹。SQL指纹采集和计算规则详情,请参见SQL指纹。 说明 从Hologres V2.2版本开始,新增digest列以展示SQL指纹编码。若您的实例为V2.1或以下版本,可联系Hologres技术支持升级实例。 | SQL指纹编码。 |
datname | text | 查询的数据库名称。 | 查询的数据库名称。 |
command_tag | text | 查询的类型。 包括:
| 聚合周期内,同聚合主键第一个Query的查询的类型。 |
duration | integer | 查询的耗时(ms)。
系统默认只展示大于1s的DML和所有DDL,可以通过GUC参数 | 聚合周期内,同聚合主键所有Query的查询耗时的平均值。 |
message | text | 报错的信息。 | 空。 |
query_start | timestamptz | 查询开始时间。 | 聚合周期内,同聚合主键第一个Query的查询开始时间。 |
query_date | text | 查询开始日期。 | 聚合周期内,同聚合主键第一个Query的查询开始日期。 |
query | text | 查询的文本内容。 Query的长度上限是51200个字符,超过可能会被截断。 | 聚合周期内,同聚合主键第一个Query的查询的文本内容。 |
result_rows | bigint | 返回的行数。 如果是INSERT命令,则返回插入的行数。 | 聚合周期内,同聚合主键所有Query的result_rows的平均值。 |
result_bytes | bigint | 返回的字节数。 | 聚合周期内,同聚合主键所有Query的result_bytes的平均值。 |
read_rows | bigint | 读取的数据行数。 非精确值。如果使用了Bitmap索引,跟实际的扫描行数有差别。 | 聚合周期内,同聚合主键所有Query的read_rows的平均值。 |
read_bytes | bigint | 读取的字节数。 | 聚合周期内,同聚合主键所有Query的read_bytes的平均值。 |
affected_rows | bigint | DML影响的行数。 | 聚合周期内,同聚合主键所有Query的affected_rows的平均值。 |
affected_bytes | bigint | DML影响的字节数。 | 聚合周期内,同聚合主键所有Query的affected_bytes的平均值。 |
memory_bytes | bigint | 各节点上使用的内存峰值的累加值(非精确)。 代表Query在所有运行节点上使用的内存峰值的累加值。粗略地体现Query的数据读取量。 | 聚合周期内,同聚合主键所有Query的memory_bytes的平均值。 |
shuffle_bytes | bigint | 数据Shuffle估计字节数(非精确)。 粗略地体现数据在网络中的传输量。 | 聚合周期内,同聚合主键所有Query的shuffle_bytes的平均值。 |
cpu_time_ms | bigint | 总的CPU时间,单位:毫秒(ms),非精确。 体现所有计算任务所耗费的CPU时间,是多个CPU Core计算时间的累加,粗略地体现复杂度。 | 聚合周期内,同聚合主键所有Query的cpu_time_ms的平均值 |
physical_reads | bigint | 物理读的次数。 反映从磁盘读取Record Batch的次数,粗略地体现内存缓存未命中数量。 | 聚合周期内,同聚合主键所有Query的physical_reads的平均值。 |
pid | integer | 查询服务进程ID。 | 聚合周期内,同聚合主键第一个Query的查询服务进程ID。 |
application_name | text | 查询应用类型。 其中常见的应用类型如下:
其余应用建议业务上在连接Hologres时,连接串上显式指定 | 查询应用类型。 |
engine_type | text[] | 查询用到的引擎。 包含如下引擎类型:
| 聚合周期内,同聚合主键第一个Query的查询用到的引擎。 |
client_addr | text | Query的来源地址。 代表应用的出口IP,不一定是真实的应用IP。 | 聚合周期内,同聚合主键第一个Query的Query的来源地址。 |
table_write | text | SQL写入的表。 | 聚合周期内,同聚合主键第一个Query的SQL写入的表。 |
table_read | text[] | SQL读取的表。 | 聚合周期内,同聚合主键第一个Query的SQL读取的表。 |
session_id | text | Session ID。 | 聚合周期内,同聚合主键第一个Query的Session ID。 |
session_start | timestamptz | Session开启时间。 代表连接开始建立的时间。 | 聚合周期内,同聚合主键所有Query的Session开启时间。 |
command_id | text | 命令或语句编号ID。 | 聚合周期内,同聚合主键所有Query的命令或语句编号ID。 |
optimization_cost | integer | 查询执行计划的耗时。 耗时较高通常情况是SQL较复杂。 | 聚合周期内,同聚合主键所有Query的查询执行计划的耗时。 |
start_query_cost | integer | 查询启动耗时。 耗时较高通常是因为在等锁或者等待资源。 | 聚合周期内,同聚合主键所有Query的查询启动耗时。 |
get_next_cost | integer | 查询执行耗时。 耗时较高通常是因为计算量太大,执行时间较长,可根据业务情况优化SQL。 | 聚合周期内,同聚合主键所有Query的查询执行耗时。 |
extended_cost | text | 查询的其他详细耗时。 除optimization_cost 、start_query_cost 、get_next_cost三个耗时之外的其他耗时,可以通过
| 聚合周期内,同聚合主键第一个Query的其他详细耗时。 |
plan | text | 查询对应的执行计划。 执行计划长度上限是102400个字符,超过可能会被截断,可以通过GUC参数 | 聚合周期内,同聚合主键第一个Query的查询对应的执行计划。 |
statistics | text | 查询对应的执行统计信息。 统计信息长度上限是102400个字符,超过可能会被截断,可以通过GUC参数 | 聚合周期内,同聚合主键第一个Query的查询对应的执行统计信息。 |
visualization_info | text | 查询Plan可视化信息。 | 聚合周期内,同聚合主键第一个Query的查询Plan可视化信息。 |
query_detail | text | 查询的其他扩展信息(JSON格式存储)。 说明 扩展信息长度上限是10240个字符,超过可能会被截断。 | 聚合周期内,同聚合主键第一个Query的查询的其他扩展信息。 |
query_extinfo | text[] |
说明 本地账号登录、SLR登录、STS登录不会记录AccessKey ID。若使用临时账号登录,仅记录临时AccessKey ID。 | 聚合周期内,同聚合主键第一个Query的其他扩展信息。 |
calls | INT | 因为明细记录无聚合行为,所以为1。 | 表示在聚合周期内,相同聚合主键的查询数量。 |
agg_stats | JSONB | 空。 | 记录在聚合周期内,相同聚合主键的查询的duration、memory_bytes、cpu_time_ms、physical_reads、optimization_cost、start_query_cost、get_next_cost等数值字段的MIN、MAX、AVG等统计值。 |
calls、agg_stats字段为V3.0.2版本新增字段。
授予查看权限
慢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权限模型
查看本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日志。
当前HoloWeb支持查看最多七天的历史慢Query日志。
仅支持Superuser账号查看,普通有权限的账号请使用SQL命令查看。
登录HoloWeb控制台,详情请参见连接HoloWeb并执行查询。
单击顶部导航栏的诊断与优化。
在左侧导航栏单击历史慢Query。
在历史慢Query页面顶部,编辑查询条件。
参数说明请参见历史慢Query。
单击查询,在Query趋势分析和Query列表区域展示查询结果。
Query趋势分析
Query趋势分析通过可视化的方式展示近期慢Query、失败Query发生的趋势,可以重点监控慢Query发生频率较高的阶段,更好的定位问题高发期并集中解决问题。
Query列表
Query列表可视化展示慢Query、失败Query的详细信息,参数说明请参见历史慢Query。也可以单击自定义列选择Query列表需要展示的列信息。
SQL指纹
自Hologres V2.2版本起,存放慢Query查询日志的系统表hologres.hg_query_log中,新增digest列以展示SQL指纹。对于SELECT/INSERT/DELETE/UPDATE类型的Query,系统会计算一个MD5哈希值作为该Query的SQL指纹,以帮助业务进一步Query归类分析。
SQL指纹的采集和计算规则如下:
默认仅采集SELECT、INSERT、DELETE以及UPDATE四种类型Query的指纹。
对于
INSERT
语句,以常量方式插入表时,SQL指纹不受插入数据量的影响。SQL指纹计算时,对SQL语句字母大小写的处理规则和Hologres在查询时SQL语句字母大小写规则保持一致。
SQL指纹计算时,会忽略查询中所有空白符(如空格、换行、制表符等)的影响,只考虑SQL语句内的结构信息。
SQL指纹计算时,会忽略查询中具体的常数值对于指纹的影响。
示例:查询
SELECT * FROM t WHERE a > 1;
与查询SELECT * FROM t WHERE a > 2;
所对应的SQL指纹是一致的。对于Query中的数组常量,SQL指纹的计算不受数组中元素个数的影响。
示例:查询
SELECT * FROM t WHERE a IN (1, 2);
和查询SELECT * FROM t WHERE a IN (3, 4, 5);
的SQL指纹是相同的。SQL指纹计算时,会考虑数据库名称,并自动补全每张表的模式(Schema)属性,以表名和表的属性共同区分不同查询中的表。
示例:对于查询
SELECT * FROM t;
和查询SELECT * FROM public.t;
而言,只有当表t
位于public
模式并且两个查询对应同一张表时,其SQL指纹才相同。
诊断Query
您可以通过查询hologres.hg_query_log表,获取慢Query日志。如下将为您介绍进行Query日志诊断常用的固定SQL语句。主要包括:
查询query_log总查询数(默认为近1个月内的数据)。
SELECT count(*) FROM hologres.hg_query_log;
执行结果如下,表示近1个月内总共执行了44个耗时大于指定阈值的Query。
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的具体信息。
SELECT * FROM hologres.hg_query_log WHERE query_id = '13001450118416xxxx';
执行结果如下,更多关于各参数的说明,请参见查看query_log表。
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)
查看昨日新增的Query数量。
统计昨日新增的Query总量。
SELECT COUNT(1) FROM ( SELECT DISTINCT t1.digest FROM hologres.hg_query_log t1 WHERE t1.query_start >= CURRENT_DATE - INTERVAL '1 day' AND t1.query_start < CURRENT_DATE AND NOT EXISTS ( SELECT 1 FROM hologres.hg_query_log t2 WHERE t2.digest = t1.digest AND t2.query_start < CURRENT_DATE - INTERVAL '1 day') AND digest IS NOT NULL ) AS a;
执行结果如下,表示昨日新增Query总量为10个。
count ------- 10 (1 row)
按照查询的类型(command_tag)分组统计昨日新增的Query数量。
SELECT a.command_tag, COUNT(1) FROM ( SELECT DISTINCT t1.digest, t1.command_tag FROM hologres.hg_query_log t1 WHERE t1.query_start >= CURRENT_DATE - INTERVAL '1 day' AND t1.query_start < CURRENT_DATE AND NOT EXISTS ( SELECT 1 FROM hologres.hg_query_log t2 WHERE t2.digest = t1.digest AND t2.query_start < CURRENT_DATE - INTERVAL '1 day') AND t1.digest IS NOT NULL) AS a GROUP BY 1 ORDER BY 2 DESC;
执行结果如下,表示昨日新增8个
INSERT
和2个SELECT
类型的Query。command_tag | count ------------+-------- INSERT | 8 SELECT | 2 (2 rows)
查看昨日新增的Query明细。
SELECT a.usename, a.status, a.query_id, a.digest, a.datname, a.command_tag, a.query, a.cpu_time_ms, a.memory_bytes FROM ( SELECT DISTINCT t1.usename, t1.status, t1.query_id, t1.digest, t1.datname, t1.command_tag, t1.query, t1.cpu_time_ms, t1.memory_bytes FROM hologres.hg_query_log t1 WHERE t1.query_start >= CURRENT_DATE - INTERVAL '1 day' AND t1.query_start < CURRENT_DATE AND NOT EXISTS ( SELECT 1 FROM hologres.hg_query_log t2 WHERE t2.digest = t1.digest AND t2.query_start < CURRENT_DATE - INTERVAL '1 day' ) AND t1.digest IS NOT NULL ) AS a;
执行结果如下:
usename |status |query_id |digest |datname|command_tag |query |cpu_time_ms |memory_bytes -----------------+--------+--------------------+------------------------------------+-------+-------------+-----------------------------------+--------------+-------------- 111111111111xxxx |SUCCESS |100100425827776xxxx |md58cf93d91c36c6bc9998add971458ba1a |dbname |INSERT |INSERT INTO xxx SELECT * FROM xxx | 1748| 898808596 111111111111xxxx |SUCCESS |100100425827965xxxx |md5f7e87e2c9e0b3d9eddcd6b3bc7f04b3b |dbname |INSERT |INSERT INTO xxx SELECT * FROM xxx | 59891| 6819529886 111111111111xxxx |SUCCESS |100100425829654xxxx |md55612dc09d2d81074fd5deed1aa3eca9b |dbname |INSERT |INSERT INTO xxx SELECT * FROM xxx | 3| 2100039 111111111111xxxx |SUCCESS |100100425829664xxxx |md58d3bf67fbdf2247559bc916586d40011 |dbname |INSERT |INSERT INTO xxx SELECT * FROM xxx | 10729| 2052861937 111111111111xxxx |SUCCESS |100100425830099xxxx |md503bd45d6b2d7701c2617d079b4d55a10 |dbname |INSERT |INSERT INTO xxx SELECT * FROM xxx | 2196| 897948034 111111111111xxxx |SUCCESS |100100425830186xxxx |md5c62169eaf3ea3a0c59bdc834a8141ac4 |dbname |INSERT |INSERT INTO xxx SELECT * FROM xxx | 5268| 1734305972 111111111111xxxx |SUCCESS |100100425830448xxxx |md59aa0c73b24c9c9eba0b34c8fdfc23bb0 |dbname |INSERT |INSERT INTO xxx SELECT * FROM xxx | 2| 2098402 111111111111xxxx |SUCCESS |100100425830459xxxx |md57d22c1d37b68984e9472f11a4c9fd04e |dbname |INSERT |INSERT INTO xxx SELECT * FROM xxx | 113| 76201984 111111111111xxxx |SUCCESS |100100525468694xxxx |md5ac7d6556fae123e9ea9527d8f1c94b1c |dbname |SELECT |SELECT * FROM xxx limit 200 | 6| 1048576 111111111111xxxx |SUCCESS |100101025538840xxxx |md547d09cdad4d5b5da74abaf08cba79ca0 |dbname |SELECT |SELECT * FROM xxx limit 200 |\N |\N (10 rows)
查看昨日新增的Query趋势(按小时展示)。
SELECT to_char(a.query_start, 'HH24') AS query_start_hour, a.command_tag, COUNT(1) FROM ( SELECT DISTINCT t1.query_start, t1.digest, t1.command_tag FROM hologres.hg_query_log t1 WHERE t1.query_start >= CURRENT_DATE - INTERVAL '1 day' AND t1.query_start < CURRENT_DATE AND NOT EXISTS ( SELECT 1 FROM hologres.hg_query_log t2 WHERE t2.digest = t1.digest AND t2.query_start < CURRENT_DATE - INTERVAL '1 day' ) AND t1.digest IS NOT NULL ) AS a GROUP BY 1, 2 ORDER BY 3 DESC;
执行结果如下,表示在昨日的11时、13时、21时分别新增了1个SELECT、1个SELECT、8个INSERT类型的Query。
query_start_hour |command_tag |count ------------------+-------------+----- 21 |INSERT | 8 11 |SELECT | 1 13 |SELECT | 1 (3 rows)
归类慢Query的次数。
SELECT digest, command_tag, count(1) FROM hologres.hg_query_log WHERE query_start >= CURRENT_DATE - INTERVAL '1 day' AND query_start < CURRENT_DATE GROUP BY 1,2 ORDER BY 3 DESC;
查询过去1天CPU平均耗时前十的Query。
SELECT digest, avg(cpu_time_ms) FROM hologres.hg_query_log WHERE query_start >= CURRENT_DATE - INTERVAL '1 day' AND query_start < CURRENT_DATE AND digest IS NOT NULL AND usename != 'system' AND cpu_time_ms IS NOT NULL GROUP BY 1 ORDER BY 2 DESC LIMIT 10;
查看过去一周内存(memory_bytes)平均消耗量前十的Query。
SELECT digest, avg(memory_bytes) FROM hologres.hg_query_log WHERE query_start >= CURRENT_DATE - INTERVAL '7 day' AND query_start < CURRENT_DATE AND digest IS NOT NULL AND memory_bytes IS NOT NULL GROUP BY 1 ORDER BY 2 DESC LIMIT 10;
查看最近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';
配置项
为了实现针对性地记录目标Query,Hologres有如下配置项可供选择。
log_min_duration_statement
配置项说明
修改此配置项仅对新Query生效,对于已经采集的Query,则按照原默认值展示。
只有超级用户(Superuser)可以改变这个设置。
设置为
-1
将则表示不记录任何查询。为正数时,最小值支持设置为100ms。使用示例
设置在慢Query日志中所有运行时间等于或者超过
250ms
的SQL语句可以被查询出来:-- DB级别设置,需要superuser设置 ALTER DATABASE dbname SET log_min_duration_statement = '250ms'; -- 当前Session级别设置,普通用户可以执行 SET log_min_duration_statement = '250ms';
该配置项记录慢Query的最短耗时,系统默认采集大于100ms的Query,但是查询时默认仅展示大于1s的Query,如需修改默认的展示时间,可以通过该配置项控制。需要注意的是:
log_min_duration_query_stats
配置项说明
修改此配置项仅对新Query生效,已被记录的Query按照原默认值展示。
设置为
-1
则关闭对Query统计信息的记录。此信息存储量较高,记录较多会降低查询分析慢Query日志的速度,因此可以在排查具体问题时设置小于10s,否则不建议调整为更小的值。
使用示例
设置记录大于20s的Query执行时的统计信息:
--DB级别设置,需要superuser设置 ALTER DATABASE dbname SET log_min_duration_query_stats = '20s'; -- 当前Session级别设置,普通用户可以执行 SET log_min_duration_query_stats = '20s';
该配置项记录Query执行时的统计信息,系统默认记录大于10s的Query执行时的统计信息,需要注意的是:
log_min_duration_query_plan
配置项说明
修改此配置项仅对新Query生效,已被记录的Query按照原默认值展示。
如果某个语句的执行时间大于或者等于设定的毫秒数,那么在慢Query日志上记录该语句的执行计划。
执行计划一般情况下可以即时地通过
explain
得到,无需特别记录。设置为
-1
则关闭对Query执行计划的记录。使用示例
设置记录大于10s的Query日志的执行计划:
-- DB级别设置,需要superuser设置 ALTER DATABASE dbname SET log_min_duration_query_plan = '10s'; -- 当前Session设置,普通用户可以执行 SET log_min_duration_query_plan = '10s';
该配置项记录Query的执行计划信息,系统将会默认展示大于等于10s的慢Query日志的执行计划,需要注意:
常见问题
问题现象:
在Hologres V1.1版本中,查看慢Query日志,无法显示查询行数、返回行数等信息。
可能原因:
慢Query日志采集不完整。
解决方法:
在Hologres V1.1.36至V1.1.49版本可以通过如下GUC参数使其显示完整。在HologresV1.1.49及以上版本可直接显示。
说明如果您的Hologres实例版本低于 V1.1.36,请您使用自助升级或加入Hologres钉钉交流群反馈,详情请参见如何获取更多的在线支持?。
--(建议)数据库级别,一个db设置一次即可。 ALTER databse <db_name> SET hg_experimental_force_sync_collect_execution_statistics = ON; --session级别 SET hg_experimental_force_sync_collect_execution_statistics = ON;
db_name为数据库名称。
相关文档
对实例中的Query进行诊断和管理,请参见Query管理。