Preface
Performance issues are what DBA most concerned thing.There`re always a lot of SQL queries which maybe not using appropriated indexes cause bad perfoemance.Whenever that happens,we have to do some performance diagnosis immediately.In most scenarios,we will do that relies on slow log,but it`s not enough or efficient I`m afraid.What`s the better way then?Another tool of percona called “pt-query-digest” can solve these kind of issues.
Introduce
pt-query-digest is a tool focus on log analysis.It is supported to analyze slow log,general log,binlog and so on in different ways.You can also use it to analyze logs and simultaneously put these informations into tables on remote host(server) that you specified.That`s really convenient and flexible for us DBA to work efficiently in performance tuning.
Procedure
Usage
1 Usage: pt-query-digest [OPTIONS] [FILES] [DSN]
Parameters introduce
1 --limit -- Limit the output conents by count(defualt 20) or percentage(default 50%). 2 --type -- Indicate a type(default "slowlog",else value is "genlog","binlog","tcpdump",etc.) you want to anaylze. 3 --processlist -- Analyze from "show processlist" result from specific host(need to input DSN). 4 --create-history-table -- Create a table to record infomation if use "--history"(default "true"). 5 --create-review-table -- Create a table to record infomation if use "--review"(default "true"). 6 --history -- Save query metrics(such as query time) into a given table which can be checked incremental difference later. 7 --review -- Save query classes into a given table for later review.It don`t report same kind of class. 8 --output -- Specify the format of query result(default "report"). 9 --since -- Give a specific time with time format of beginning. 10 --until -- Give a specific time with time format of end. 11 --group-by -- According to the atrribute of envents to group by(default "figerprint",else value is "tables"&"distill"). 12 --order-by -- According to the atrribute of envents to sort by(default "Query_time:sum").
Examples
Make sure the slow log is enabled.
1 (root@localhost mysql3306.sock)[(none)]09:37:19>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 | 9 | slow_query_log_file | slow.log | 10 +---------------------------+----------+ 11 5 rows in set (0.00 sec) 12 13 (root@localhost mysql3306.sock)[(none)]09:37:22>show variables like `%long_query_time%`; 14 +-----------------+----------+ 15 | Variable_name | Value | 16 +-----------------+----------+ 17 | long_query_time | 1.000000 | 18 +-----------------+----------+ 19 1 row in set (0.00 sec) 20 21 (root@localhost mysql3306.sock)[(none)]09:37:25>show variables like `%log_output%`; 22 +---------------+-------+ 23 | Variable_name | Value | 24 +---------------+-------+ 25 | log_output | FILE | 26 +---------------+-------+ 27 1 row in set (0.00 sec)
Execute a slow query.
1 (root@localhost mysql3306.sock)[(none)]09:41:37>select sleep(60); 2 +-----------+ 3 | sleep(60) | 4 +-----------+ 5 | 0 | 6 +-----------+ 7 1 row in set (1 min 0.01 sec)
Check slow log for information of above slow query.
1 [root@zlm2 09:43:12 /data/mysql/mysql3306/data] 2 #cat slow.log 3 4 # Time: 2018-06-23T07:42:52.891778Z 5 # User@Host: root[root] @ localhost [] Id: 7 6 # Query_time: 60.001239 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 7 SET timestamp=1529739772; 8 select sleep(60);
Use pt-query-digest analyze slow log file for more details.
1 [root@zlm2 09:42:24 ~] 2 #pt-query-digest /data/mysql/mysql3306/data/slow.log 3 4 # No events processed. -- Only if the slow query has finished,there will be a result of report. 5 6 [root@zlm2 09:42:34 ~] 7 #pt-query-digest /data/mysql/mysql3306/data/slow.log 8 9 # 180ms user time, 0 system time, 25.59M rss, 221.68M vsz 10 # Current date: Sat Jun 23 09:43:28 2018 11 # Hostname: zlm2 12 # Files: /data/mysql/mysql3306/data/slow.log 13 # Overall: 1 total, 1 unique, 0 QPS, 0x concurrency ______________________ 14 # Time range: all events occurred at 2018-06-23T07:42:52 15 # Attribute total min max avg 95% stddev median 16 # ============ ======= ======= ======= ======= ======= ======= ======= 17 # Exec time 60s 60s 60s 60s 60s 0 60s 18 # Lock time 0 0 0 0 0 0 0 19 # Rows sent 1 1 1 1 1 0 1 20 # Rows examine 0 0 0 0 0 0 0 21 # Query size 16 16 16 16 16 0 16 22 23 # Profile 24 # Rank Query ID Response time Calls R/Call V/M Item 25 # ==== ================== ============== ===== ======= ===== ====== 26 # 1 0xF9A57DD5A41825CA 60.0012 100.0% 1 60.0012 0.00 SELECT 27 28 # Query 1: 0 QPS, 0x concurrency, ID 0xF9A57DD5A41825CA at byte 0 ________ 29 # This item is included in the report because it matches --limit. 30 # Scores: V/M = 0.00 31 # Time range: all events occurred at 2018-06-23T07:42:52 32 # Attribute pct total min max avg 95% stddev median 33 # ============ === ======= ======= ======= ======= ======= ======= ======= 34 # Count 100 1 35 # Exec time 100 60s 60s 60s 60s 60s 0 60s 36 # Lock time 0 0 0 0 0 0 0 0 37 # Rows sent 100 1 1 1 1 1 0 1 38 # Rows examine 0 0 0 0 0 0 0 0 39 # Query size 100 16 16 16 16 16 0 16 40 # String: 41 # Hosts localhost 42 # Users root 43 # Query_time distribution 44 # 1us 45 # 10us 46 # 100us 47 # 1ms 48 # 10ms 49 # 100ms 50 # 1s 51 # 10s+ ################################################################ 52 # EXPLAIN /*!50100 PARTITIONS*/ 53 select sleep(60)G 54 55 ###All the meaning of above is self-explanatory,you can check official document for details.###
Other expamples
1.Analyze general log.
1 pt-query-digest --type=genlog /path/zlm2.log > report1.log
2.Analyze binlog.
1 mysqlbinlog -vv --base64-output=decode-rows /path/mysql-bin.000010 > mysql-bin000010.sql 2 pt-query-digest --type=binlog /path/mysql-bin000001.sql > report2.log
3.Analyze rawlog(It`s a general txt file which contains SQL statement).
1 echo "select sleep(10);">rawlog.log pt-query-digest --type=rawlog rawlog.log > report3.log
4.Analyze processlist(DSN is indispensable).
1 pt-query-digest --processlist h=192.168.1.101,P=3306,u=repl,p=repl4slave > report4.log -- If connection failed,it will try every second.
5.Analyze tcpdump.
1 tcpdump -s 65535 -x -nn -q -tttt -i any -c 1000 port 3306 > tcpdump.log 2 pt-query-digest --type=tcpdump tcpdump.log > report5.log
6.Analyze slow log since last 24 hours.
1 pt-query-digest --since=24h slow.log > report6.log
7.Analyze slow log since time until time.
1 pt-query-digest --since `2018-06-23 08:30:00` --until `2018-06-23 10:30:00` slow.log > report7.log
8.Analyze slow log into view table(“query_review” table will be created if not specify “-t”) of remote host.
1 pt-query-digest --review h=192.168.1.102,P=3306,u=repl,p=repl4slave,D=zlm,t=query_review slow.log > report8.log
9.Analyze slow log into history table(“query_history” table will be created like above) of remote host.
1 pt-query-digest --review h=192.168.1.102,P=3306,u=repl,p=repl4slave,D=zlm,t=query_history slow.log > report9.log
Summay
- There`re still some advanced useages I`ve not demonstrated such as “–group-by”,”–order-by” and “–filter”,etc.
- pt-query-digest is extraordinarily useful when doing performance diagnosis by different ways.
- It`s recommended to analyze logs on another node(maybe slave) instead of master to reduce consumption of CPU,Memory,IO,etc.
- pt-query-digest can help you to find out the specific slow quries.Afterwards you can use MySQL profiling(“set profiling=1;” then “show profiles;”) to survey the perticular resources which are tremendously consumed.