MySQL 慢日志分析

 1 [mysqld]
 2 basedir=/application/mysql
 3 datadir=/application/mysql/data
 4 socket=/tmp/mysql.sock
 5 log-error=/var/log/mysql.log
 6 log-bin=/data/mysql/mysql-bin
 7 server-id=6
 8 port=3306
 9 secure-file-priv=/tmp
10 binlog_format=row
11 slow_query_log=1
12 slow_query_log_file=/data/mysql/slow.log
13 long_query_time=0.05
14 log_queries_not_using_indexes
15 [client]
16 socket=/tmp/mysql.sock

  1 #-------------------------------------------------------------------------------
  2 #
  3 # 模拟slow日志分析
  4 # 通过percona-toolkit-3.0.10_x86_64.tar.gz
  5 # Author：nod
  6 # Date:18-08-05
  7 #-------------------------------------------------------------------------------
  8 
  9 #-------------------------------------------------------------------------------
 10 # 模拟环境数据
 11 #-------------------------------------------------------------------------------
 12 mysql> use world;
 13 Database changed
 14 
 15 mysql> create table t1 select * from city;
 16 Query OK, 4079 rows affected (0.24 sec)
 17 Records: 4079  Duplicates: 0  Warnings: 0
 18 
 19 mysql> insert into t1 select * from t1;
 20 Query OK, 4079 rows affected (0.76 sec)
 21 Records: 4079  Duplicates: 0  Warnings: 0
 22 
 23 mysql> insert into t1 select * from t1;
 24 Query OK, 8158 rows affected (0.15 sec)
 25 Records: 8158  Duplicates: 0  Warnings: 0
 26 
 27 mysql> insert into t1 select * from t1;
 28 Query OK, 16316 rows affected (0.29 sec)
 29 Records: 16316  Duplicates: 0  Warnings: 0
 30 
 31 mysql> insert into t1 select * from t1;
 32 Query OK, 32632 rows affected (0.36 sec)
 33 Records: 32632  Duplicates: 0  Warnings: 0
 34 
 35 mysql> insert into t1 select * from t1;
 36 Query OK, 65264 rows affected (0.64 sec)
 37 Records: 65264  Duplicates: 0  Warnings: 0
 38 
 39 mysql> insert into t1 select * from t1;
 40 Query OK, 130528 rows affected (1.98 sec)
 41 Records: 130528  Duplicates: 0  Warnings: 0
 42 
 43 mysql> insert into t1 select * from t1;
 44 Query OK, 261056 rows affected (3.20 sec)
 45 Records: 261056  Duplicates: 0  Warnings: 0
 46 
 47 mysql> insert into t1 select * from t1;
 48 Query OK, 522112 rows affected (6.63 sec)
 49 Records: 522112  Duplicates: 0  Warnings: 0
 50 
 51 mysql> insert into t1 select * from t1;
 52 Query OK, 1044224 rows affected (25.21 sec)
 53 Records: 1044224  Duplicates: 0  Warnings: 0
 54 
 55 mysql> insert into t1 select * from t1;
 56 Query OK, 2088448 rows affected (40.06 sec)
 57 Records: 2088448  Duplicates: 0  Warnings: 0
 58 
 59 mysql> select count(*) from t1;
 60 +----------+
 61 | count(*) |
 62 +----------+
 63 |  4176896 |
 64 +----------+
 65 1 row in set (1.79 sec)
 66 
 67 mysql> delete from t1 where id>2000;
 68 Query OK, 2128896 rows affected (26.41 sec)
 69 
 70 mysql> select count(*) from t1;
 71 +----------+
 72 | count(*) |
 73 +----------+
 74 |  2048000 |
 75 +----------+
 76 1 row in set (11.60 sec)
 77 
 78 #-------------------------------------------------------------------------------
 79 # 安装 percona-toolkit-3.0.10_x86_64.tar.gz 
 80 #-------------------------------------------------------------------------------
 81 
 82 yum install -y   perl-Time-HiRes
 83 cd /server/tools/
 84 tar xf percona-toolkit-3.0.10_x86_64.tar.gz 
 85 pwd
 86 /server/tools/percona-toolkit-3.0.10/bin
 87 
 88 
 89 #-------------------------------------------------------------------------------
 90 # 分析slowlog
 91 #-------------------------------------------------------------------------------
 92 [root@db01 bin]# ./pt-query-digest /data/mysql/slow.log 
 93 
 94 # 130ms user time, 10ms system time, 20.77M rss, 169.70M vsz
 95 # Current date: Sun Aug  5 13:07:02 2018
 96 # Hostname: db01
 97 # Files: /data/mysql/slow.log
 98 # Overall: 21 total, 7 unique, 0.01 QPS, 0.05x concurrency _______________
 99 # Time range: 2018-08-05 12:24:28 to 13:06:55
100 # Attribute          total     min     max     avg     95%  stddev  median
101 # ============     ======= ======= ======= ======= ======= ======= =======
102 # Exec time           120s   936us     40s      6s     25s     11s   356ms
103 # Lock time           37ms       0    32ms     2ms   348us     7ms   176us
104 # Rows sent              3       0       1    0.14    0.99    0.35       0
105 # Rows examine      17.90M       0   3.98M 872.95k   3.86M   1.37M  31.59k
106 # Query size           608      16      34   28.95   30.19    4.17   30.19
107 
108 # Profile
109 # Rank Query ID           Response time Calls R/Call  V/M   Item
110 # ==== ================== ============= ===== ======= ===== ==============
111 #    1 0xD990BC7C09F20BDA 79.3335 66.2%    13  6.1026 21.42 INSERT SELECT t?
112 #    2 0x6F6EB4D37DDD5C23 26.4109 22.0%     1 26.4109  0.00 DELETE t?
113 #    3 0x0EBF4AD96B6F67E7 13.4005 11.2%     3  4.4668  5.59 SELECT t?
114 # MISC 0xMISC              0.6675  0.6%     4  0.1669   0.0 <4 ITEMS>
115 
116 # Query 1: 0.01 QPS, 0.03x concurrency, ID 0xD990BC7C09F20BDA at byte 3738
117 # This item is included in the report because it matches --limit.
118 # Scores: V/M = 21.42
119 # Time range: 2018-08-05 12:25:20 to 13:04:52
120 # Attribute    pct   total     min     max     avg     95%  stddev  median
121 # ============ === ======= ======= ======= ======= ======= ======= =======
122 # Count         61      13
123 # Exec time     66     79s     8ms     40s      6s     25s     11s   690ms
124 # Lock time      7     3ms   169us   360us   209us   273us    56us   167us
125 # Rows sent      0       0       0       0       0       0       0       0
126 # Rows examine  44   7.97M   3.98k   3.98M 627.85k   1.95M   1.09M  93.20k
127 # Query size    66     403      31      31      31      31       0      31
128 # String:
129 # Databases    world
130 # Hosts        localhost
131 # Users        root
132 # Query_time distribution
133 #   1us
134 #  10us
135 # 100us
136 #   1ms  ######################################
137 #  10ms
138 # 100ms  ################################################################
139 #    1s  ######################################
140 #  10s+  #########################
141 # Tables
142 #    SHOW TABLE STATUS FROM `world` LIKE ‘t1‘\G
143 #    SHOW CREATE TABLE `world`.`t1`\G
144 insert into t1 select * from t1\G
145 
146 # Query 2: 0 QPS, 0x concurrency, ID 0x6F6EB4D37DDD5C23 at byte 4159 _____
147 # This item is included in the report because it matches --limit.
148 # Scores: V/M = 0.00
149 # Time range: all events occurred at 2018-08-05 13:06:30
150 # Attribute    pct   total     min     max     avg     95%  stddev  median
151 # ============ === ======= ======= ======= ======= ======= ======= =======
152 # Count          4       1
153 # Exec time     22     26s     26s     26s     26s     26s       0     26s
154 # Lock time      0   302us   302us   302us   302us   302us       0   302us
155 # Rows sent      0       0       0       0       0       0       0       0
156 # Rows examine  22   3.98M   3.98M   3.98M   3.98M   3.98M       0   3.98M
157 # Query size     4      28      28      28      28      28       0      28
158 # String:
159 # Databases    world
160 # Hosts        localhost
161 # Users        root
162 # Query_time distribution
163 #   1us
164 #  10us
165 # 100us
166 #   1ms
167 #  10ms
168 # 100ms
169 #    1s
170 #  10s+  ################################################################
171 # Tables
172 #    SHOW TABLE STATUS FROM `world` LIKE ‘t1‘\G
173 #    SHOW CREATE TABLE `world`.`t1`\G
174 delete from t1 where id>2000\G
175 # Converted for EXPLAIN
176 # EXPLAIN /*!50100 PARTITIONS*/
177 select * from  t1 where id>2000\G
178 
179 # Query 3: 0.00 QPS, 0.01x concurrency, ID 0x0EBF4AD96B6F67E7 at byte 4371
180 # This item is included in the report because it matches --limit.
181 # Scores: V/M = 5.59
182 # Time range: 2018-08-05 12:25:43 to 13:06:55
183 # Attribute    pct   total     min     max     avg     95%  stddev  median
184 # ============ === ======= ======= ======= ======= ======= ======= =======
185 # Count         14       3
186 # Exec time     11     13s     3ms     12s      4s     11s      5s      2s
187 # Lock time      1   507us    92us   277us   169us   273us    78us   131us
188 # Rows sent    100       3       1       1       1       1       0       1
189 # Rows examine  33   5.94M   3.98k   3.98M   1.98M   3.86M   1.58M   1.95M
190 # Query size    11      69      23      23      23      23       0      23
191 # String:
192 # Databases    world
193 # Hosts        localhost
194 # Users        root
195 # Query_time distribution
196 #   1us
197 #  10us
198 # 100us
199 #   1ms  ################################################################
200 #  10ms
201 # 100ms
202 #    1s  ################################################################
203 #  10s+  ################################################################
204 # Tables
205 #    SHOW TABLE STATUS FROM `world` LIKE ‘t1‘\G
206 #    SHOW CREATE TABLE `world`.`t1`\G
207 # EXPLAIN /*!50100 PARTITIONS*/
208 select count(*) from t1\G