Percona-Tookit工具包之pt-table-usage

aaron8219發表於2018-07-22
 
Preface
 
    There always be some table join operations in our SQL statement.Although we can know details of table join information from explain opertion by json format.Whatif you are not using MySQL 5.7?Is there a tool which can tell us how the tables are used in join operations?
    
Introduce
 
    pt-table-usage is simply used to anaylyze how the queries use tables.It can indicate the data flow by the contexts in which table appear.We can either get these information from query statement directly(using “–query” option) or from a log file(It should be slow log format) insetead.
 
Procedure
 
Usage
1 pt-table-usage [OPTIONS] [FILES]

 

Common parameter
1 --constant-data-value //Specify the table to print as the source for constant data(default "DUAL").
2 --continue-on-error //It won`t stop when getting errors(default "yes").
3 --create-table-definitions //Specify a file to read definitions in it.
4 --explain-extended //Specify a server to avoid ambiguous names of columns and tables.
5 --id-attribute //Specify a format to identify each event(default query ID).
6 --progress //Specify the way to print progress(default time,30s).
7 --query //Speicy reading from a qeury instead of log file.

 

Example
 
Print table usage relevant with constant query(insert,update).
 1 //Create a test table.
 2 (zlm@192.168.1.101 3306)[zlm]>create table test_table_usage(
 3     -> id int,
 4     -> name char(10)
 5     -> ) engine=innodb;
 6 Query OK, 0 rows affected (0.02 sec)
 7 
 8 [root@zlm2 03:07:22 ~]
 9 #pt-table-usage --query=`insert into zlm.test_table_usage values(1,`zlm`);`
10 Query_id: 0x4467805469FEF40B.1 //The
11 INSERT zlm.test_table_usage
12 SELECT DUAL //When specifying the constant value,it will print "DUAL" after "SELECT".
13 
14 [root@zlm2 03:08:24 ~]
15 #pt-table-usage --query=`update zlm.test_table_usage set id=2 where name=`zlm`;`
16 Query_id: 0xB2EE79AD4DA99C2B.1
17 UPDATE zlm.test_table_usage
18 SELECT DUAL //When specifying the constant value,it will print "DUAL" after "SELECT".
19 WHERE zlm.test_table_usage //There`s a condition in query statment.It will be printed here.
20 
21 (zlm@192.168.1.101 3306)[zlm]>select * from test_table_usage;
22 Empty set (0.00 sec) //There`re no records changed at all in the test table.Because those two queries are just query operations which won`t be really executed.

 

Print table usage relevant with query(select).
 1 [root@zlm2 03:09:27 ~]
 2 #pt-table-usage --query=`select t1.id,t1.pad from sbtest1 as t1 join sbtest2 as t2 where t1.pad=t2.pad;`
 3 Query_id: 0x016CE309DD3D9FA3.1
 4 SELECT sbtest1 //This time,it shows the specific table name which your query data in.
 5 TLIST sbtest1 //"TLIST" means full table scan will be used in the above query.
 6 TLIST sbtest2
 7 WHERE sbtest1
 8 
 9 [root@zlm2 03:10:05 ~]
10 #pt-table-usage --query=`select t1.id,t2.pad from sbtest1 as t1 join sbtest2 as t2 where t1.pad=t2.pad;`
11 Query_id: 0x016CE309DD3D9FA3.1
12 SELECT sbtest1
13 SELECT sbtest2 //Have you seen the difference?The column "pad" belongs to the table "sbtest2" in the query,So there comes the line.
14 TLIST sbtest1 //"TLIST" means full table scan will be used in the above query either.
15 TLIST sbtest2
16 WHERE sbtest1

 

Print table usage according to the slow log file.
 
  1 (zlm@192.168.1.101 3306)[sysbench]>show variables like `%slow%`;
  2 +---------------------------+----------+
  3 | Variable_name             | Value    |
  4 +---------------------------+----------+
  5 | log_slow_admin_statements | OFF      |
  6 | log_slow_slave_statements | ON       |
  7 | slow_launch_time          | 2        |
  8 | slow_query_log            | ON       | //Make sure the slow log is functional.
  9 | slow_query_log_file       | slow.log |
 10 +---------------------------+----------+
 11 5 rows in set (0.00 sec)
 12 
 13 (zlm@192.168.1.101 3306)[sysbench]>show variables like `long_query%`;
 14 +-----------------+----------+
 15 | Variable_name   | Value    |
 16 +-----------------+----------+
 17 | long_query_time | 1.000000 | //Check out the threashold of slow log.
 18 +-----------------+----------+
 19 1 row in set (0.00 sec)
 20 
 21 (zlm@192.168.1.101 3306)[sysbench]>set long_query_time=0;
 22 Query OK, 0 rows affected (0.00 sec)
 23 
 24 (zlm@192.168.1.101 3306)[sysbench]>show variables like `long_query%`;
 25 +-----------------+----------+
 26 | Variable_name   | Value    |
 27 +-----------------+----------+
 28 | long_query_time | 0.000000 | //Let the slow log record every SQL statement.
 29 +-----------------+----------+
 30 1 row in set (0.00 sec)
 31 
 32 (zlm@192.168.1.101 3306)[sysbench]>show tables;
 33 +--------------------+
 34 | Tables_in_sysbench |
 35 +--------------------+
 36 | sbtest1            |
 37 | sbtest2            |
 38 +--------------------+
 39 2 rows in set (0.00 sec)
 40 
 41 (zlm@192.168.1.101 3306)[sysbench]>select count(*) from sbtest1; //Query 1.
 42 +----------+
 43 | count(*) |
 44 +----------+
 45 |    10000 |
 46 +----------+
 47 1 row in set (0.00 sec)
 48 
 49 (zlm@192.168.1.101 3306)[sysbench]>select count(*) from sbtest2; //Query 2.
 50 +----------+
 51 | count(*) |
 52 +----------+
 53 |    10000 |
 54 +----------+
 55 1 row in set (0.00 sec)
 56 
 57 (zlm@192.168.1.101 3306)[sysbench]>select t1.id,t2.pad from sbtest1 as t1 join sbtest2 as t2 where t1.k<t2.k; //Query 3.
 58 Killed //The mysql client is killed,because the query time is too long.
 59 
 60 [root@zlm2 03:29:39 ~]
 61 #ps aux|grep mysql
 62 mysql     3745  1.5  3.0 1110204 31156 pts/0   Sl   03:05   0:21 mysqld --defaults-file=/data/mysql/mysql3306/my.cnf
 63 root      3971  0.0  0.0 112640   960 pts/0    S+   03:30   0:00 grep --color=auto mysql
 64 
 65 [root@zlm2 03:30:09 ~]
 66 
 67 //Slow log shows the details.
 68 [root@zlm2 03:30:26 /data/mysql/mysql3306/data]
 69 #tail -f slow.log 
 70 
 71 # Time: 2018-07-26T03:28:30.313395+01:00
 72 # User@Host: zlm[zlm] @ zlm2 [192.168.1.101]  Id:     3
 73 # Query_time: 0.000170  Lock_time: 0.000070 Rows_sent: 2  Rows_examined: 2
 74 SET timestamp=1532568510;
 75 show tables;
 76 # Time: 2018-07-26T03:28:43.141016+01:00
 77 # User@Host: zlm[zlm] @ zlm2 [192.168.1.101]  Id:     3
 78 # Query_time: 0.002259  Lock_time: 0.000061 Rows_sent: 1  Rows_examined: 10000
 79 SET timestamp=1532568523;
 80 select count(*) from sbtest1; //Query 1.
 81 # Time: 2018-07-26T03:28:57.593601+01:00
 82 # User@Host: zlm[zlm] @ zlm2 [192.168.1.101]  Id:     3
 83 # Query_time: 0.001549  Lock_time: 0.000060 Rows_sent: 1  Rows_examined: 10000
 84 SET timestamp=1532568537;
 85 select count(*) from sbtest2; //Query 2.
 86 # Time: 2018-07-26T03:29:39.471206+01:00
 87 # User@Host: zlm[zlm] @ zlm2 [192.168.1.101]  Id:     3
 88 # Query_time: 33.401928  Lock_time: 0.000084 Rows_sent: 14560434  Rows_examined: 15931628 //Too many rows are examinted.It`s a cartesian join.
 89 SET timestamp=1532568579;
 90 select t1.id,t2.pad from sbtest1 as t1 join sbtest2 as t2 where t1.k<t2.k; //Query 3.
 91 
 92 //Let`s see what will show in pt-table-usage.
 93 [root@zlm2 03:18:31 ~]
 94 #pt-table-usage /data/mysql/mysql3306/data/slow.log
 95 Query_id: 0x999ECD050D719733.1 //Query 1.
 96 SELECT sbtest1
 97 
 98 Query_id: 0x999ECD050D719733.1 //Query 2.
 99 SELECT sbtest2
100 
101 Query_id: 0x923C5317557357E2.1 //Query 3.
102 SELECT sbtest1
103 SELECT sbtest2
104 JOIN sbtest1
105 JOIN sbtest2 //No "WHERE" condition instructions after this line(Is that because of the killing operation?I`m not sure about it).
106 
107 //Let`s check out the execution plan.
108 (zlm@192.168.1.101 3306)[sysbench]>explain select t1.id,t2.pad from sbtest1 as t1 join sbtest2 as t2 where t1.k<t2.k;
109 +----+-------------+-------+------------+-------+---------------+------+---------+------+------+----------+------------------------------------------------+
110 | id | select_type | table | partitions | type  | possible_keys | key  | key_len | ref  | rows | filtered | Extra                                          |
111 +----+-------------+-------+------------+-------+---------------+------+---------+------+------+----------+------------------------------------------------+
112 |  1 | SIMPLE      | t1    | NULL       | index | k_1           | k_1  | 4       | NULL | 9936 |   100.00 | Using index                                    |
113 |  1 | SIMPLE      | t2    | NULL       | ALL   | k_2           | NULL | NULL    | NULL | 9936 |    33.33 | Range checked for each record (index map: 0x2) |
114 +----+-------------+-------+------------+-------+---------------+------+---------+------+------+----------+------------------------------------------------+
115 2 rows in set, 1 warning (0.00 sec)
116 
117 (zlm@192.168.1.101 3306)[sysbench]>explain format=json select t1.id,t2.pad from sbtest1 as t1 join sbtest2 as t2 where t1.k<t2.kG
118 *************************** 1. row ***************************
119 EXPLAIN: {
120   "query_block": {
121     "select_id": 1,
122     "cost_info": {
123       "query_cost": "19747226.04" //It`s really an amazingly tremendous cost of the query.No wonder why it was killed.
124     },
125     "nested_loop": [
126       {
127         "table": {
128           "table_name": "t1",
129           "access_type": "index",
130           "possible_keys": [
131             "k_1"
132           ],
133           "key": "k_1",
134           "used_key_parts": [
135             "k"
136           ],
137           "key_length": "4",
138           "rows_examined_per_scan": 9936,
139           "rows_produced_per_join": 9936,
140           "filtered": "100.00",
141           "using_index": true,
142           "cost_info": {
143             "read_cost": "161.00",
144             "eval_cost": "1987.20",
145             "prefix_cost": "2148.20",
146             "data_read_per_join": "5M"
147           },
148           "used_columns": [
149             "id",
150             "k"
151           ]
152         }
153       },
154       {
155         "table": {
156           "table_name": "t2",
157           "access_type": "ALL",
158           "possible_keys": [
159             "k_2"
160           ],
161           "rows_examined_per_scan": 9936,
162           "rows_produced_per_join": 32904740,
163           "filtered": "33.33",
164           "range_checked_for_each_record": "index map: 0x2",
165           "cost_info": {
166             "read_cost": "258.64",
167             "eval_cost": "6580948.13",
168             "prefix_cost": "19747226.04",
169             "data_read_per_join": "16G" //What a big size!
170           },
171           "used_columns": [
172             "k",
173             "pad"
174           ]
175         }
176       }
177     ]
178   }
179 }
180 1 row in set, 1 warning (0.00 sec)

 

Summary
  • It`s very simple to use pt-table-usage,there`re only several options of it.
  • pt-table-usage can be used in either a query statement by specifying “–query” or a log file such as slow log by specifying the path of it.
  • If your MySQL version is below 5.7,you can consider using pt-table-usage to analyze the join information of tables in queries.

 

相關文章