菜单

mysql之数据库优化入门,shell脚本分析mysql慢查询日志

2019年8月31日 - 4166m金沙
mysql之数据库优化入门,shell脚本分析mysql慢查询日志

shell脚本分析mysql慢查询日志(slowlog)

使用percona公司的pt-query-digest分析慢查询日志,分析、统计的结果的比较清晰

#!/bin/sh


slowlog_path=/root/slow_query_log
everyslow=/tmp/everydayslow
##需要下载pt-query-digest
pt_digest=/root/pt-query-digest

start_string=$(grep `date --date="0 days ago" +%y%m%d` ${slowlog_path}|head -1)
start_pos=$(grep -n `date --date="0 days ago" +%y%m%d` ${slowlog_path}|head -1|awk -F: '{print $1}')
end_pos=$(grep -n `date --date="0 days ago" +%y%m%d` ${slowlog_path}|tail -1|awk -F: '{print $1}')
print_linecnt=$(expr ${end_pos} - ${start_pos})

##start_string如果不为空,则分析日志
if [ -z "${start_string}" ];
then exit 1
else
grep -i "${start_string}" -A ${print_linecnt} ${slowlog_path} > ${everyslow}
/usr/bin/perl ${pt_digest} ${everyslow} > /tmp/anaslowlog_`date +%Y-%m-%d`
fi

 

使用percona公司的pt-query-digest分析慢查询日志,分析、统计的结果的比较清晰
#!/bin/shslowlog_path=/root/…

开启慢查询日志:

进入mysql,输入以下语句

查看是否开启了慢查询日志:

show variables like ‘slow_query_log’;

show variables like ‘%log’;                                  
 查看与log有关的配置

设置慢查询日志存放的位置(默认):

set global slow_query_log_file =
‘/home/mysql/sql_log/mysql-slow.log’

将没有使用索引的查询展现出来:

set global log_queries_not_using_indexes=on; 

设定慢查询的最小时限(1s):

set global long_query_time=1;                          

打开慢查询日志:

set global slow_query_log=on;

图片 1

pt-query-digest(percona toolkit)小解,ptquerydigest

pt-query-digest可以通过logs, processlist,
和tcpdump来分析MySQL的查询相关信息,基本语法如下:

pt-query-digest [OPTIONS] [FILES] [DSN]

 

pt-query-digest是一种用于分析MySQL查询的简单易用的工具,没有之一。它可以分析MySQL慢日志,general
LOG和二进制日志的查询。
(二进制日志必须首先转换为文本,通过mysqlbinlog工具)。它也可以使用SHOW
PROCESSLIST和来自tcpdump的MySQL协议数据。默认情况下,该工具报告哪个查询最慢,因此最重要的是进行优化。可以通过使用–group-by,–filter和–embedded-attributes等参数来创建更自定义的报告。
pt-query-digest主要有以下几个功能: (1)使用slow.log来生成统计信息:

pt-query-digest slow.log

 

(2)从processlist的方式分析生成报告:

pt-query-digest --processlist h=host1

 

(3)通过tcppdump抓包分析慢查询:

tcpdump -s 65535 -x -nn -q -tttt -i any -c 1000 port 3306 > mysql.tcp.txt
pt-query-digest --type tcpdump mysql.tcp.txt

 

(4)将慢日志查询分析到另一台主机:

pt-query-digest --review h=host2 --no-report slow.log

 

下面看一下主要参数: –type
默认为slowlog,参数值可以设置为binlog,genlog,slowlog,tcpdump,rawlog等。
–processlist 通过processlist分析MySQL的满日志查询 –create-review-table
当使用–review参数把分析结果输出到表中时,如果没有表就自动创建。
–create-history-table
当使用–history参数把分析结果输出到表中时,如果没有表就自动创建。
–filter 对输入的慢查询按指定的字符串进行匹配过滤后再进行分析
–limit限制输出结果百分比或数量,默认值是20,即将最慢的20条语句输出,如果是50%则按总响应时间占比从大到小排序,输出到总和达到50%位置截止。
–host MySQL服务器地址 –user mysql用户名 –password mysql用户密码
–history
将分析结果保存到表中,分析结果比较详细,下次再使用–history时,如果存在相同的语句,且查询所在的时间区间和历史表中的不同,则会记录到数据表中,可以通过查询同一CHECKSUM来比较某类型查询的历史变化。
–review
将分析结果保存到表中,这个分析只是对查询条件进行参数化,一个类型的查询一条记录,比较简单。当下次使用–review时,如果存在相同的语句分析,就不会记录到数据表中。
–output 分析结果输出类型,值可以是report(标准分析报告)、slowlog(Mysql
slow log)、json、json-anon,一般使用report,以便于阅读。 –since
从什么时间开始分析,值为字符串,可以是指定的某个”yyyy-mm-dd
[hh:mm:ss]”格式的时间点,也可以是简单的一个时间值:s(秒)、h(小时)、m(分钟)、d(天),如12h就表示从12小时前开始统计。
–until 截止时间,配合—since可以分析一段时间内的慢查询。
下面看一下默认的输出报表相关的信息: (1)数据统计信息

# 2291.9s user time, 6.4s system time, 41.68M rss, 193.36M vsz
# Current date: Mon Jun 19 11:19:51 2017
# Hostname: mxqmongodb2
# Files: /home/mysql/db3306/log/slowlog_343306.log
# Overall: 6.72M total, 140 unique, 16.12 QPS, 0.69x concurrency _________
# Time range: 2017-06-13T14:34:41 to 2017-06-18T10:22:04
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 287519s 1us 20s 43ms 148ms 339ms 214us
# Lock time 151259s 0 20s 23ms 144us 319ms 47us
# Rows sent 5.40M 0 1000 0.84 0.99 6.58 0.99
# Rows examine 388.33M 0 3.72k 60.59 5.75 388.16 0.99
# Query size 692.26M 6 799 108.02 202.40 69.96 80.10

 

以上包含信息Hostname主机名,Overall总查询,unique单独查询,分析时间段Time
range, Attribute部分和第三部分是一样的,放到最好分析
(2)慢查询SQL统计结果和开销统计

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ================= ======= ====== ===== =========
# 1 0x255C57D761A899A9 146053.6926 50.8% 75972 1.9225 2.93 UPDATE warehouse
# 2 0x813031B8BBC3B329 94038.9621 32.7% 242741 0.3874 0.23 COMMIT
# 3 0xA0352AA54FDD5DF2 10125.5055 3.5% 75892 0.1334 0.43 UPDATE order_line
# 4 0xE5E8C12332AD11C5 5660.5113 2.0% 75977 0.0745 0.83 SELECT district
# 5 0xBD195A4F9D50914F 3634.6219 1.3% 757760 0.0048 1.01 SELECT stock
# 6 0xF078A9E73D7A8520 3431.3527 1.2% 75874 0.0452 0.81 UPDATE district
# 7 0x9577D48F480A1260 2307.4342 0.8% 50255 0.0459 1.25 SELECT customer
# 8 0xFFDA79BA14F0A223 2158.4731 0.8% 75977 0.0284 0.54 SELECT customer warehouse
# 9 0x5E61FF668A8E8456 1838.4440 0.6% 1507614 0.0012 0.74 SELECT stock
# 10 0x10BEBFE721A275F6 1671.8274 0.6% 757751 0.0022 0.52 INSERT order_line
# 11 0x8B2716B5B486F6AA 1658.5984 0.6% 75871 0.0219 0.75 INSERT history
# 12 0xBF40A4C7016F2BAE 1504.7939 0.5% 758569 0.0020 0.77 SELECT item
# 13 0x37AEB73B59EFC119 1470.5951 0.5% 2838 0.5182 0.27 INSERT SELECT tpcc._stock_new tpcc.stock
# 15 0x26C4F579BF19956D 1030.4416 0.4% 1982 0.5199 0.28 INSERT SELECT tpcc.__stock_new tpcc.stock
# 22 0xD80B7970DBF2419C 493.0831 0.2% 947 0.5207 0.28 INSERT SELECT tpcc.__stock_new tpcc.stock
# 23 0xDE7EA4E363CAD006 488.2134 0.2% 943 0.5177 0.25 INSERT SELECT tpcc.__stock_new tpcc.stock
# 25 0x985B012461683472 470.6418 0.2% 907 0.5189 0.25 INSERT SELECT tpcc.__stock_new tpcc.stock
# MISC 0xMISC 9482.0467 3.3% 2182254 0.0043 0.0 <123 ITEMS>

 

其中信息包含了Response: 总的响应时间,time:
该查询在本次分析中总的时间占比。calls:
执行次数,即本次分析总共有多少条这种类型的查询语句。R/Call:
平均每次执行的响应时间。Item : SQL操作表。
(3)第三部分,每个SQL的详细信息

# Query 1: 1.14 QPS, 2.19x concurrency, ID 0x255C57D761A899A9 at byte 1782619576
# This item is included in the report because it matches --limit.
# Scores: V/M = 2.93
# Time range: 2017-06-13T14:34:42 to 2017-06-14T09:05:56
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 1 75972
# Exec time 50 146054s 160us 20s 2s 7s 2s 1s
# Lock time 94 142872s 39us 20s 2s 7s 2s 992ms
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 74.19k 1 1 1 1 0 1
# Query size 0 4.05M 53 57 55.88 56.92 0.82 54.21
# String:
# Hosts 127.0.0.1
# Users root
# Query_time distribution
# 1us
# 10us
# 100us ######################
# 1ms ##
# 10ms ###
# 100ms ##################################
# 1s ################################################################
# 10s+ ##
# Tables
# SHOW TABLE STATUS LIKE 'warehouse'\G
# SHOW CREATE TABLE `warehouse`\G
UPDATE warehouse SET w_ytd = w_ytd + 3651 WHERE w_id = 4\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select w_ytd = w_ytd + 3651 from warehouse where w_id = 4\G

 

Query
1,就是按照开销来说排名第一的查询,第一行是表的列标题。百分比是整个分析运行的总和的百分比,total是指定指标的实际值。例如,在这种情况下,我们可以看到查询执行了75972次,占文件中查询总数的50%。
min,max和avg列是不言自明的。
95%的列显示了第95个百分点;值的95%小于或等于该值。标准偏差显示了数值是如何紧密分组的。标准偏差和中位数都是从第95个百分点计算出来的,舍弃极大值最小值。
下面我们看一下常规的用法: 1:分析慢日志 默认报表

[[email protected] bin]# ./pt-query-digest /home/mysql/db3306/log/slowlog_343306.log >/home/sa/slowlog_343306.log

 

按照时间来切分,一般情况我们会分析一天的慢日志:

[[email protected] bin]# ./pt-query-digest --since=24h /home/mysql/db3306/log/slowlog_343306.log >/home/sa/slowlog_343306_24.log

 

而且我们可以设置过滤条天通过–filter参数,更好生成我们想要的报表。
例如只查询select:–filter ‘$event->{arg} =~
m/^select/i’,只查询某个用户:–filter ‘($event->{user} || “”) =~
m/^dba/i’ ,全表扫描等:–filter ‘(($event->{Full_scan} || “”) eq
“yes”) ||(($event->{Full_join} || “”) eq “yes”)’ 
2:保存分析结果到表文件:

[[email protected] bin]# ./pt-query-digest --user=root --password=123456 --port=3306 --review h=172.16.16.35,D=test,t=query_report /home/mysql/db3306/log/slowlog_343306.log

 

看一下结果样式

mysql> select * from query_report limit 1\G
*************************** 1. row ***************************
checksum: 1206612749604517366
fingerprint: insert into order_line (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_quantity, ol_amount, ol_dist_info) values(?+)
sample: INSERT INTO order_line (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_quantity, ol_amount, ol_dist_info) VALUES (3730, 6, 10, 1, 6657, 10, 8, 62.41910171508789, 'N3F5fAhga7U51tlXr8AEgZdi')
first_seen: 2017-06-13 14:34:42
last_seen: 2017-06-14 09:05:54
reviewed_by: NULL
reviewed_on: NULL
comments: NULL
1 row in set (0.00 sec)

 

3:分析binlog(要先使用mysqlbinlog将binlog转换)

[[email protected] log]# mysqlbinlog mysql-bin.000012 >/home/sa/mysql-bin_000012.log
[[email protected] bin]# ./pt-query-digest --type=binlog /home/sa/mysql-bin_000012.log >/home/sa/mysql-bin_000012_report.log

 

这个测试的时候还是有点小迷茫的,因为打印的结果并不是我要的,难道是因为我的binlog格式是ROW?保留下来,后面在测试。
4:分析general log 加上–type=genlog 即可,没有验证。。。。。。
5:tcpdump抓包分析 我们先要开启压力测试:

[[email protected] tpcc-mysql]# ./tpcc_start -h127.0.0.1 -P3306 -d tpcc -u root -p123456 -w 10 -c 10 -r 10 -l 3000

 

连续测试三十分钟,提供我们的抓取数据:

[[email protected] log]# tcpdump -s 65535 -x -nn -q -tttt -i any -c 10000 port 3306 >/home/sa/mysql.tcp.txt
[[email protected] bin]# ./pt-query-digest --type=tcpdump /home/sa/mysql.tcp.txt >/home/sa/mysql.tcp_repot.txt

 

看一下效果:

[[email protected] sa]# cat mysql.tcp_repot.txt

# 4.2s user time, 50ms system time, 27.65M rss, 179.15M vsz
# Current date: Tue Jun 20 17:08:40 2017
# Hostname: mxqmongodb2
# Files: /home/sa/mysql.tcp.txt
# Overall: 155 total, 3 unique, 9.76 QPS, 4.52x concurrency ______________
# Time range: 2017-06-20 17:06:19.850032 to 17:06:35.731291
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 72s 63us 2s 463ms 1s 352ms 393ms
# Rows affecte 25 0 15 0.16 0.99 1.18 0
# Query size 956 6 30 6.17 5.75 1.85 5.75
# Warning coun 1 0 1 0.01 0 0.08 0

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== =========
# 1 0x813031B8BBC3B329 69.9077 97.4% 153 0.4569 0.25 COMMIT
# MISC 0xMISC 1.8904 2.6% 2 0.9452 0.0 <2 ITEMS>

# Query 1: 9.63 QPS, 4.40x concurrency, ID 0x813031B8BBC3B329 at byte 10100332
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.25
# Time range: 2017-06-20 17:06:19.850032 to 17:06:35.731291
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 98 153
# Exec time 97 70s 63us 2s 457ms 1s 336ms 393ms
# Rows affecte 100 25 0 15 0.16 0.99 1.19 0
# Query size 96 918 6 6 6 6 0 6
# Warning coun 100 1 0 1 0.01 0 0.08 0
# String:
# Hosts 127.0.0.1
# Query_time distribution
# 1us
# 10us #
# 100us ####
# 1ms #
# 10ms #
# 100ms ################################################################
# 1s ##########
# 10s+
commit\G

 

toolkit)小解,ptquerydigest pt-query-digest可以通过logs, processlist,
和tcpdump来分析MySQL的查询相关信息,基本语法如下: pt-qu…

慢查询日志分析工具:

mysqldumpslow(mysql自带)

列出参数信息:

mysqldumpslow -h

用例(分析前3条日志):

mysqldumpslow -t 3 /home/mysql/sql_log/mysql-slow.log | more

图片 2

pt-query-digest

下载:https://www.percona.com/doc/percona-toolkit/2.2/pt-query-digest.html\#downloading

wget percona.com/get/pt-query-digest

pt-query-digest /home/mysql/sql_log/mysql-slow.log | more

图片 3

图片 4

图片 5

图片 6

相关文章

发表评论

电子邮件地址不会被公开。 必填项已用*标注

网站地图xml地图