好用工具:慢SQL分析pt-query-digest

pt-query-digest

pt-query-digest 属于 Percona Toolkit 的一个工具,也是使用较多的一个;用于分析slow log,也可以分析MySQL的 binary log 、 general log 日志。

本文通过pt-query-digest实现慢sql的分析,优化sql

一,安装percona-toolkit

下载:https://www.percona.com/doc/percona-toolkit/2.2/installation.html

安装在/usr/local/percona-toolkit目录下

wget percona.com/get/percona-toolkit.tar.gz
tar zxf percona-toolkit.tar.gz
cd percona-toolkit-3.3.1/
perl Makefile.PL PREFIX=/usr/local/percona-toolkit
make && make install
  1. MySQL开启慢查询日志并设置慢查询时间
mysql> show variables like '%slow_query_log%';
+---------------------------+-------------------------------+
| Variable_name             | Value                         |
+---------------------------+-------------------------------+
| slow_query_log            | ON                            |
| slow_query_log_file       | /var/lib/mysql/mysql-slow.log |
+---------------------------+-------------------------------+
-- 超过一秒的记录到日志中
mysql>  set global long_query_time=1;

开启慢查询之后,在程序运行一段时间之后,可以拿到记录的日志

  1. 使用命令直接分析慢查询日志

    直接拿到的mysql-slow.log看着没有条理,不容易分析

    使用命令分析并生成slow_report.log : pt-query-digest slow.log > slow_report.log

    然后我们可以导出这个文件,查看其中内容

二,分析慢查询日志

文件中总共包含三部分:总体统计,sql统计,单个sql的统计

1. 总体统计
# 85.8s user time, 990ms system time, 30.71M rss, 193.21M vsz
# Current date: Mon May 10 11:47:39 2021
# Hostname: xxxx.xxx-xxx.com
# Files: /var/lib/mysql/mysql-slow.log
# Overall: 87.23k total, 73 unique, 0.05 QPS, 0.37x concurrency __________
# Time range: 2021-04-16T03:15:31 to 2021-05-07T08:38:15

# 属性            总计       最小    最大    平均      95%  标准     中等

# Attribute       total     min     max     avg     95%  stddev  median
# ============    ======= ======= ======= ======= ======= ======= =======
# Exec time       676605s    2s    905s      8s     23s     12s      4s
# Lock time       242s       0      1s     3ms     4ms    17ms   839us
# Rows sent       8.90M       0  15.53k  107.02  400.73  616.06    8.91
# Rows examine    7.13G       0   8.94M  85.77k  46.68k 412.27k   2.38k
# Query size      161.99M     6  24.91k   1.90k   1.96k  682.67   1.96k
2. sql统计汇总
# Profile
# Rank Query ID                            Response time    Calls R/Call  
# ==== =================================== ================ ===== ======= 
#    1 0x8EBD7078F62A82A7C578540C76F46BC4  602766.9262 8... 75091  8.0272 13.94 SELECT xxxx
#    2 0x40A63F5C50A2324033DB9FCAA2719C4E  18044.3571  2.7%  4131  4.3680  3.07 SELECT xxxx
#    3 0xFB8F32AE0EFAA83C665B91B6E5862D2F  16215.4058  2.4%  2335  6.9445  6.22 SELECT xxxx 
#    4 0x2CF3802FA98AFCE8DA5C85F6E8424DCE  12951.3375  1.9%  2390  5.4190  6.56 SELECT xxxx
#    5 0x56A24EC2EC1FFDB2F49A123C34D5E0BD   8612.3662  1.3%   479 17.9799 31... SELECT xxxx
#    6 0x6D73ABA4D5097101273AA5ADB2259759   8328.1423  1.2%   858  9.7065 12.72 SELECT xxxx
#    7 0x75A04B6CA2CBDE5EB7A27A7FC15FFCC1   3864.3549  0.6%   615  6.2835  5.72 SELECT xxxx
#    8 0x886F3B1A59BD9900A6688314B0A3E4E0   3050.7563  0.5%   614  4.9687  2.93 SELECT xxxx
#    9 0xE6AA1C4FE828263924B7C26F5160BD60    680.7256  0.1%   171  3.9809  1.06 SELECT xxxx
#    10 .............
Rank: 排名
Query ID: 语句ID(去掉多余空格和文本字符,计算hash值)
Response time: 总的响应时间和 该查询在本次分析中总的时间占比
Calls: 执行次数
R/Call: 平均每次执行的响应时间
3. 单个sql的统计
# Query 1: 0.04 QPS, 0.33x concurrency, ID 0x8EBD7078F62A82A7C578540C76F46BC4 at byte 66396962
# This item is included in the report because it matches --limit.
# Scores: V/M = 13.94
# Time range: 2021-04-16T03:15:31 to 2021-05-07T08:38:15
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         86   75091
# Exec time     89 602767s      2s    281s      8s     23s     11s      4s
# Lock time     64    156s   352us   730ms     2ms     4ms    10ms   839us
# Rows sent      6 554.55k       0      31    7.56   16.81    5.75    5.75
# Rows examine   4 294.12M     110  77.33k   4.01k  10.29k   5.80k   2.38k
# Query size    89 145.64M   1.98k   1.99k   1.99k   1.96k    0.00   1.96k
# Tables
#   设计到的表
# EXPLAIN /*!50100 PARTITIONS*/
#       具体执行的sql语句
SELECT
    hg.group_id,
    MAX( ham.app_message_id ) latest_message,
    COALESCE ( hgrf.last_read_message_id, 0 ) last_read_message_id,
    SUM(
    CASE
            WHEN app_message_id > COALESCE ( last_read_message_id, 0 ) 
            AND ham.receiver_type = 'USER' THEN
                1 ELSE 0 
            END 
            ) unread_message_count 
        FROM
            h_group hg
            INNER JOIN h_message hm ON hm.group_id = hg.group_id
            INNER JOIN h_app_message ham ON ham.message_id = hm.message_id 
            AND ham.user_id = 2084
            LEFT JOIN h_group_read_flag hgrf ON hg.group_id = hgrf.group_id 
            AND hgrf.user_id = ham.user_id 
            AND hgrf.user_type = 0 
        WHERE
            ham.deleted = 0 
            AND hm.send_flag = 1 
        GROUP BY
        hg.group_id,
    hgrf.last_read_message_id

通过以上日志我们可以看出哪些sql执行较慢,哪些sql执行次数较多,然后根据不同的业务需求去分析有问题的sql进行优化,例如:

对于执行慢的sql:

  • 使用explain查询执行计划,确认索引是否正常使用

  • 关联表太多,是否使用冗余字段减少没必要的表关联

  • 查询条件复杂,查询数据量较多,是否可以在业务层分多次查询(有时候多次并不比一次慢)

对于执行频率高的sql:

  • 数据尝试使用缓存,较少数据库的查询

三,实际案例分析

SQL分析:执行次数75091,总时间耗费602767s,平均单次8s,最大一次281s,最少也是2s

a. 首先根据SQL 去优化,研究很久SQL没有优化空间

调试很久,索引都是正常使用,时间始终在2s左右,如果某个用户未读数量大,那花费时间更长

b. 根据业务逻辑拆解SQL, 减少数据量,减少表关联

场景描述和分析:

公司每天会有不定量的推文推送到每个用户,app_message 会存储用户和消息的关联( count=消息数x用户数)

总共4张表:

app_message(用户消息关联表, 主要字段:app_message_id,message_id,user_id),数据量1千万

message(消息表,主要字段:message_id,group_id) 数据量近2百万

h_group(频道表,主要字段:group_id) 每条推文都有所属的频道,数据量较少

h_group_read_flag(用户频道最新已读表,主要字段:last_read_message_id,group_id,user_id) 存储用户每个频道最新已读消息记录 (last_read_message_id=app_message_id),数据量较少

每次用户打开APP都会通过这4个表关联查询用户的未读数量以及最新的消息

解决分析:

b. 1: 首先h_group 只是用来关联group_id ,可以在h_app_message 中冗余group_id字段,去掉h_group表的关联;

b. 2: h_message的send_flag是撤回推文是0,否则是1(没有这个关联即可去除h_message表)在撤回推文之后就把h_app_message中相关数据删除,这样h_message也可以不用使用

b. 3: 最后主要是h_app_message表,数量级较大,然后减少数量(将跨度较远的数据按年归档处理)

公众号:Java质变之路

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 217,826评论 6 506
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,968评论 3 395
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 164,234评论 0 354
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 58,562评论 1 293
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 67,611评论 6 392
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 51,482评论 1 302
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,271评论 3 418
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 39,166评论 0 276
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,608评论 1 314
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,814评论 3 336
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,926评论 1 348
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,644评论 5 346
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,249评论 3 329
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,866评论 0 22
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,991评论 1 269
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 48,063评论 3 370
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,871评论 2 354

推荐阅读更多精彩内容