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

pt-table-usage [OPTIONS] [FILES]

Common parameter

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

Example

 

Print table usage relevant with constant query(insert,update).

//Create a test table.
(zlm@192.168.1.101 3306)[zlm]>create table test_table_usage(
    -> id int,
    -> name char(10)
    -> ) engine=innodb;
Query OK, 0 rows affected (0.02 sec)

[root@zlm2 03:07:22 ~]
#pt-table-usage --query='insert into zlm.test_table_usage values(1,'zlm');'
Query_id: 0x4467805469FEF40B.1 //The
INSERT zlm.test_table_usage
SELECT DUAL //When specifying the constant value,it will print "DUAL" after "SELECT".

[root@zlm2 03:08:24 ~]
#pt-table-usage --query='update zlm.test_table_usage set id=2 where name='zlm';'
Query_id: 0xB2EE79AD4DA99C2B.1
UPDATE zlm.test_table_usage
SELECT DUAL //When specifying the constant value,it will print "DUAL" after "SELECT".
WHERE zlm.test_table_usage //There's a condition in query statment.It will be printed here.

(zlm@192.168.1.101 3306)[zlm]>select * from test_table_usage;
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).

[root@zlm2 03:09:27 ~]
#pt-table-usage --query='select t1.id,t1.pad from sbtest1 as t1 join sbtest2 as t2 where t1.pad=t2.pad;'
Query_id: 0x016CE309DD3D9FA3.1
SELECT sbtest1 //This time,it shows the specific table name which your query data in.
TLIST sbtest1 //"TLIST" means full table scan will be used in the above query.
TLIST sbtest2
WHERE sbtest1

[root@zlm2 03:10:05 ~]
#pt-table-usage --query='select t1.id,t2.pad from sbtest1 as t1 join sbtest2 as t2 where t1.pad=t2.pad;'
Query_id: 0x016CE309DD3D9FA3.1
SELECT sbtest1
SELECT sbtest2 //Have you seen the difference?The column "pad" belongs to the table "sbtest2" in the query,So there comes the line.
TLIST sbtest1 //"TLIST" means full table scan will be used in the above query either.
TLIST sbtest2
WHERE sbtest1

Print table usage according to the slow log file.

 

(zlm@192.168.1.101 3306)[sysbench]>show variables like '%slow%';
+---------------------------+----------+
| Variable_name             | Value    |
+---------------------------+----------+
| log_slow_admin_statements | OFF      |
| log_slow_slave_statements | ON       |
| slow_launch_time          | 2        |
| slow_query_log            | ON       | //Make sure the slow log is functional.
| slow_query_log_file       | slow.log |
+---------------------------+----------+
5 rows in set (0.00 sec)

(zlm@192.168.1.101 3306)[sysbench]>show variables like 'long_query%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 | //Check out the threashold of slow log.
+-----------------+----------+
1 row in set (0.00 sec)

(zlm@192.168.1.101 3306)[sysbench]>set long_query_time=0;
Query OK, 0 rows affected (0.00 sec)

(zlm@192.168.1.101 3306)[sysbench]>show variables like 'long_query%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.000000 | //Let the slow log record every SQL statement.
+-----------------+----------+
1 row in set (0.00 sec)

(zlm@192.168.1.101 3306)[sysbench]>show tables;
+--------------------+
| Tables_in_sysbench |
+--------------------+
| sbtest1            |
| sbtest2            |
+--------------------+
2 rows in set (0.00 sec)

(zlm@192.168.1.101 3306)[sysbench]>select count(*) from sbtest1; //Query 1.
+----------+
| count(*) |
+----------+
|    10000 |
+----------+
1 row in set (0.00 sec)

(zlm@192.168.1.101 3306)[sysbench]>select count(*) from sbtest2; //Query 2.
+----------+
| count(*) |
+----------+
|    10000 |
+----------+
1 row in set (0.00 sec)

(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.
Killed //The mysql client is killed,because the query time is too long.

[root@zlm2 03:29:39 ~]
#ps aux|grep mysql
mysql     3745  1.5  3.0 1110204 31156 pts/0   Sl   03:05   0:21 mysqld --defaults-file=/data/mysql/mysql3306/my.cnf
root      3971  0.0  0.0 112640   960 pts/0    S+   03:30   0:00 grep --color=auto mysql

[root@zlm2 03:30:09 ~]

//Slow log shows the details.
[root@zlm2 03:30:26 /data/mysql/mysql3306/data]
#tail -f slow.log 

# Time: 2018-07-26T03:28:30.313395+01:00
# User@Host: zlm[zlm] @ zlm2 [192.168.1.101]  Id:     3
# Query_time: 0.000170  Lock_time: 0.000070 Rows_sent: 2  Rows_examined: 2
SET timestamp=1532568510;
show tables;
# Time: 2018-07-26T03:28:43.141016+01:00
# User@Host: zlm[zlm] @ zlm2 [192.168.1.101]  Id:     3
# Query_time: 0.002259  Lock_time: 0.000061 Rows_sent: 1  Rows_examined: 10000
SET timestamp=1532568523;
select count(*) from sbtest1; //Query 1.
# Time: 2018-07-26T03:28:57.593601+01:00
# User@Host: zlm[zlm] @ zlm2 [192.168.1.101]  Id:     3
# Query_time: 0.001549  Lock_time: 0.000060 Rows_sent: 1  Rows_examined: 10000
SET timestamp=1532568537;
select count(*) from sbtest2; //Query 2.
# Time: 2018-07-26T03:29:39.471206+01:00
# User@Host: zlm[zlm] @ zlm2 [192.168.1.101]  Id:     3
# Query_time: 33.401928  Lock_time: 0.000084 Rows_sent: 14560434  Rows_examined: 15931628 //Too many rows are examinted.It's a cartesian join.
SET timestamp=1532568579;
select t1.id,t2.pad from sbtest1 as t1 join sbtest2 as t2 where t1.k<t2.k; //Query 3.

//Let's see what will show in pt-table-usage.
[root@zlm2 03:18:31 ~]
#pt-table-usage /data/mysql/mysql3306/data/slow.log
Query_id: 0x999ECD050D719733.1 //Query 1.
SELECT sbtest1

Query_id: 0x999ECD050D719733.1 //Query 2.
SELECT sbtest2

Query_id: 0x923C5317557357E2.1 //Query 3.
SELECT sbtest1
SELECT sbtest2
JOIN sbtest1
JOIN sbtest2 //No "WHERE" condition instructions after this line(Is that because of the killing operation?I'm not sure about it).

//Let's check out the execution plan.
(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;
+----+-------------+-------+------------+-------+---------------+------+---------+------+------+----------+------------------------------------------------+
| id | select_type | table | partitions | type  | possible_keys | key  | key_len | ref  | rows | filtered | Extra                                          |
+----+-------------+-------+------------+-------+---------------+------+---------+------+------+----------+------------------------------------------------+
|  1 | SIMPLE      | t1    | NULL       | index | k_1           | k_1  | 4       | NULL | 9936 |   100.00 | Using index                                    |
|  1 | SIMPLE      | t2    | NULL       | ALL   | k_2           | NULL | NULL    | NULL | 9936 |    33.33 | Range checked for each record (index map: 0x2) |
+----+-------------+-------+------------+-------+---------------+------+---------+------+------+----------+------------------------------------------------+
2 rows in set, 1 warning (0.00 sec)

(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
*************************** 1. row ***************************
EXPLAIN: {
  "query_block": {
    "select_id": 1,
    "cost_info": {
      "query_cost": "19747226.04" //It's really an amazingly tremendous cost of the query.No wonder why it was killed.
    },
    "nested_loop": [
      {
        "table": {
          "table_name": "t1",
          "access_type": "index",
          "possible_keys": [
            "k_1"
          ],
          "key": "k_1",
          "used_key_parts": [
            "k"
          ],
          "key_length": "4",
          "rows_examined_per_scan": 9936,
          "rows_produced_per_join": 9936,
          "filtered": "100.00",
          "using_index": true,
          "cost_info": {
            "read_cost": "161.00",
            "eval_cost": "1987.20",
            "prefix_cost": "2148.20",
            "data_read_per_join": "5M"
          },
          "used_columns": [
            "id",
            "k"
          ]
        }
      },
      {
        "table": {
          "table_name": "t2",
          "access_type": "ALL",
          "possible_keys": [
            "k_2"
          ],
          "rows_examined_per_scan": 9936,
          "rows_produced_per_join": 32904740,
          "filtered": "33.33",
          "range_checked_for_each_record": "index map: 0x2",
          "cost_info": {
            "read_cost": "258.64",
            "eval_cost": "6580948.13",
            "prefix_cost": "19747226.04",
            "data_read_per_join": "16G" //What a big size!
          },
          "used_columns": [
            "k",
            "pad"
          ]
        }
      }
    ]
  }
}
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.