Percona-Tookit工具包之pt-table-usage
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
扫码关注我们
微信号：SRE实战
拒绝背锅 运筹帷幄
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.
SRE实战 互联网时代守护先锋，助力企业售后服务体系运筹帷幄！一键直达领取阿里云限量特价优惠。 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.k\G 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.
更多精彩
