慢Query日志查看与分析

当Hologres实例出现响应或查询速度变慢时,您可以查看与分析慢Query日志快速定位问题所在。慢Query的查看与分析可以帮助您对系统中发生的慢Query或失败Query进行识别、诊断和分析,并进一步采取优化措施,以提高系统整体性能。本文为您介绍在Hologres中如何查看慢Query日志并分析。

版本说明

Hologres版本号

功能

说明

V0.10

新增慢Query日志查看与分析功能。

  • 该功能仅Hologres V0.10及以上版本支持,请在Hologres管理控制台的实例详情页查看当前实例版本,如果您的实例是V0.10以下版本,请您使用自助升级或加入Hologres钉钉交流群反馈,详情请参见如何获取更多的在线支持?

  • Hologres V0.10版本的FAILED Query日志,不显示内存、读盘、读取量、CPU时间、query_stats等运行时的统计信息。

V2.2.7

优化log_min_duration_statement参数默认值

慢Query日志记录所有的DDL语句、所有执行失败的SQL语句以及执行时间大于log_min_duration_statement的SQL语句(例如INSERT、SELECT、UPDATE、DELETE等)。

从Hologres V2.2.7版本开始,将log_min_duration_statement默认值由1s优化至100ms,无需您再手动修改。若您的实例是V2.2.7以下版本,可使用log_min_duration_statement进行手动修改,支持最小修改为100ms。

使用限制

在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。

  • 失败:FAILED。

查询的最终状态,成功(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

查询的类型。

包括:

  • DML类:COPY/DELETE/INSERT/SELECT/UPDATE等

  • DDL类:ALTER TABLE/BEGIN/COMMENT/COMMIT/CREATE FOREIGN TABLE/CREATE TABLE/DROP FOREIGN TABLE/DROP TABLE/IMPORT FOREIGN SCHEMA/ROLLBACK/TRUNCATE TABLE

  • 其他:CALL/CREATE EXTENSION/EXPLAIN/GRANT/SECURITY LABEL/等

聚合周期内,同聚合主键第一个Query的查询的类型。

duration

integer

查询的耗时(ms)。

duration代表SQL的总耗时时间,包含:

  • Optimization Cost:生成执行计划的耗时,耗时较高通常是因为SQL较复杂。

  • Start Query Cost:Query启动时间,耗时较高通常是因为在等锁或者等待资源。

  • Get Result Cost:Query执行时间,耗时较高通常是因为计算量太大,执行时间较长,可根据业务情况优化SQL。

  • 其他耗时:可以通过extend_cost字段进一步查看,通常包括如下耗时:

    • build_dag : 构建执行引擎所需的计算DAG图的耗时,如访问外部表,这一步会获取外部表元数据,耗时较高通常是因为访问外部表元数据耗时长。

    • prepare_reqs : 准备发往执行引擎请求的耗时,包括准备运行的组件、获取各个分片的地址等,耗时较高通常是因为向内部服务获取分片地址耗时长。

系统默认只展示大于1s的DML和所有DDL,可以通过GUC参数log_min_duration_statement修改采集时间,使用详情请参见配置项

聚合周期内,同聚合主键所有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

查询应用类型。

其中常见的应用类型如下:

  • 阿里云Flink(VVR版):{client_version}_ververica-connector-hologres。

  • 开源Flink:{client_version}_hologres-connector-flink。

  • DataWorks数据集成离线同步读取Hologres:datax_{jobId}。

  • DataWorks数据集成离线同步写入Hologres:{client_version}_datax_{jobId}。

  • DataWorks数据集成实时同步:{client_version}_streamx_{jobId}。

  • Holoweb:holoweb。

  • 在MaxCompute中通过外部表的方式访问Hologres:MaxCompute。

  • Auto Analyze发起的SQL,用于定期更新统计信息:AutoAnalyze。

  • Quick BI:QuickBI_public_{version}。

  • DataWorks调度Hologres任务:{client_version}_dwscheduler_{tenant_id}_{scheduler_id}_{scheduler_task_id}_{bizdate}_{cyctime}_{scheduler_alisa_id},其中:

    • client_version:JDBC驱动版本。

    • scheduler_id:从环境变量${SKYNET_ID}获取,如果为空,则设置为-

    • scheduler_task_id:从环境变量${SKYNET_TASKID}获取,如果为空,则设置为-

    • scheduler_alisa_id:从环境变量${ALISA_TASK_ID}获取,不会为空。

    • bizdate:从环境变量${SKYNET_BIZDATE}获取,如果为空,则设置为-

    • cyctime:从环境变量${SKYNET_CYCTIME}获取,如果为空,则设置为-

    • tenant_id:从环境变量${SKYNET_TENANT_ID}获取,不会为空。

  • 数据保护伞:dsg。

其余应用建议业务上在连接Hologres时,连接串上显式指定application_name

查询应用类型。

engine_type

text[]

查询用到的引擎。

包含如下引擎类型:

  • HQE:Hologres的原生自研引擎,大多数查询通过HQE实现,HQE执行效率较高。

  • PQE:PostgreSQL引擎,出现PQE则有SQL算子在PQE执行,一般是含有HQE未原生支持的算子或表达式,可根据优化查询性能改写函数方法,让其走HQE,提高执行效率。

  • SDK:Fixed Plan的执行引擎,可以高效的执行点读、点写、PrefixScan等偏Serving类型的SQL,详情请参见Fixed Plan加速SQL执行

    说明

    从Hologres V2.2版本开始,SDK执行引擎正式更名为FixedQE。

  • PG:Frontend本地计算,一般是读取系统表的元数据查询,不会读取用户表数据,仅占用极少数系统资源。但需要注意的是,DDL也是用PostgreSQL引擎。

聚合周期内,同聚合主键第一个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三个耗时之外的其他耗时,可以通过extend_cost字段进一步查看,通常包括如下耗时。

  • build_dag:构建执行引擎所需的计算DAG图的耗时,如访问外部表,这一步会获取外部表元数据,耗时较高通常是因为访问外部表元数据耗时长。

  • prepare_reqs:准备发往执行引擎请求的耗时,包括准备运行的组件、获取各个分片的地址等,耗时较高通常是因为向内部服务获取分片地址耗时长。

  • serverless_allocated_cores:申请的Serverless资源量(单位:CU),仅Serverless Query有该字段。

  • serverless_allocated_workers:申请的Serverless资源Worker数(单位:个),仅Serverless Query有该字段。

  • serverless_resource_used_time_ms:实际使用Serverless资源执行Query的时长,不包含资源等待排队时长。单位:毫秒(ms)。

聚合周期内,同聚合主键第一个Query的其他详细耗时。

plan

text

查询对应的执行计划。

执行计划长度上限是102400个字符,超过可能会被截断,可以通过GUC参数log_min_duration_query_plan修改长度上限,使用详情请参见配置项

聚合周期内,同聚合主键第一个Query的查询对应的执行计划。

statistics

text

查询对应的执行统计信息。

统计信息长度上限是102400个字符,超过可能会被截断,可以通过GUC参数log_min_duration_query_stats修改长度上限,使用详情请参见配置项

聚合周期内,同聚合主键第一个Query的查询对应的执行统计信息。

visualization_info

text

查询Plan可视化信息。

聚合周期内,同聚合主键第一个Query的查询Plan可视化信息。

query_detail

text

查询的其他扩展信息(JSON格式存储)。

说明

扩展信息长度上限是10240个字符,超过可能会被截断。

聚合周期内,同聚合主键第一个Query的查询的其他扩展信息。

query_extinfo

text[]

  • serverless_computing:仅使用Serverless资源执行的Query有该字段。

  • 查询的其他扩展信息(ARRAY格式存储),自V2.0.29版本开始,query_extinfo字段会采集账户的AccessKey ID,用于辅助判断账户归属人。

说明

本地账号登录、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命令查看。

  1. 登录HoloWeb控制台,详情请参见连接HoloWeb并执行查询

  2. 单击顶部导航栏的诊断与优化

  3. 在左侧导航栏单击历史慢Query

  4. 历史慢Query页面顶部,编辑查询条件。

    参数说明请参见历史慢Query

  5. 单击查询,在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总查询数

  • 查询每个用户的慢Query情况

  • 查询某个慢Query的具体信息

  • 查询最近10分钟消耗比较高的Query

  • 查看最近3小时内每小时的Query访问量和数据读取总量

  • 查看与昨天同一时间对比过去3小时的数据访问量情况

  • 查询最近10分钟Query各阶段耗时比较高的Query

  • 查询最先失败的Query

  • 查询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外部表。

    1. 在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);
    2. 在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的最短耗时,系统默认采集大于100ms的Query,但是查询时默认仅展示大于1s的Query,如需修改默认的展示时间,可以通过该配置项控制。需要注意的是:

    • 修改此配置项仅对新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';

log_min_duration_query_stats

  • 配置项说明

  • 该配置项记录Query执行时的统计信息,系统默认记录大于10s的Query执行时的统计信息,需要注意的是:

    • 修改此配置项仅对新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';

log_min_duration_query_plan

  • 配置项说明

  • 该配置项记录Query的执行计划信息,系统将会默认展示大于等于10s的慢Query日志的执行计划,需要注意:

    • 修改此配置项仅对新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';

常见问题

  • 问题现象:

    在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管理