Summary of mysqldumpslow usage
Origin: MySQL in the generated environment has the problem of slow query. In order to analyze slow query, open slow query log and analyze the log.
In order to avoid misoperation in the production environment, copy the record of slow query log back to their own computer for analysis.
The results are as follows:
[root@dras-test local]#mysqldumpslow -a -s t -t 2 /opt/slow_query_log.txt
Reading mysql slow query log from /opt/slow_query_log.txt
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), LibSvr[LibSvr]@[10.1.202.57]
# Schema: information_schema Last_errno: 0 Killed: 0
# Query_time: 11.257168 Lock_time: 0.000141 Rows_sent: 366777 Rows_examined: 366777 Rows_affected: 0
# Bytes_sent: 43251512
SET timestamp=1492111317;
SELECT * FROM `INNODB_BUFFER_PAGE_LRU`
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), LibSvr[LibSvr]@[10.1.122.132]
# Schema: el Last_errno: 0 Killed: 0
# Query_time: 4.471143 Lock_time: 0.000097 Rows_sent: 1 Rows_examined: 8018065 Rows_affected: 0
# Bytes_sent: 1098
SET timestamp=1490682921;
SELECT `UserID`,`FileName`,`AdjunctGuid`,`LiteratureGuid`,`NoteGuid`,`AdjunctType`,`Md5`,`ID`,`ServerModifyTime`,`FileSize` FROM `el_user_adjunct_info` WHERE (`AdjunctGuid` = '4528cef4139846678cddf0d00170af9f.caj')
The problem arises. The students who carefully look at it have already seen that the statistics of Time, Lock and Rows are all 0.
mysqldumpslow is a perl script that uses regular expressions to match log files line by line, extracts matched values after matching, and then replaces the empty whole behavior.
s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;After separate testing, this expression is no problem and can be matched correctly. But in mysqldumpslow, the matching is not successful. After some searches and comparisons, it is found that the format of the log copied from the production environment is inconsistent with the format to be parsed in mysqldumpslow. There are more than one line in the log.
18 # User@Host: LibSvr[LibSvr] @ [10.1.122.131] Id: 10
19 # Schema: el Last_errno: 0 Killed: 0
20 # Query_time: 5.993656 Lock_time: 0.000078 Rows_sent: 1 Rows_examined: 8018014 Rows_affected: 0
21 # Bytes_sent: 1086
22 SET timestamp=1490682881;
23 SELECT `UserID`,`FileName`,`AdjunctGuid`,`LiteratureGuid`,`NoteGuid`,`AdjunctType`,`Md5`,`ID`,`ServerModifyTime`,`FileSize` FROM `el_user_adjunct_info` WHERE (`AdjunctGuid` = 'dbf1fc940ddd452d8d2af439438a cb07.caj');Among them, line 19 is extra, and mysqldumpslow is matched and replaced by empty, so the wrong line is matched when matching line by line.
The script is then modified to add matches and substitutions for line 19:
105 s/^#? Schema: \w+ Last_errno: \d+ Killed: \d+.*\n//;
106
107 s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;On the top of the expression that matches the Query_time: line, add line 105 to match the Schema line and replace it with empty.
Then the analysis, finally normal.
Cause of the problem: The generated environment is inconsistent with my local version of MySQL, and the format of the generated logs is different.
The mysqldumpslow syntax is simple:
[root@dras-test local]# mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]
Parse and summarize the MySQL slow query log. Options are
--verbose verbose
--debug debug
--help write this text to standard output
-v verbose
-d debug
-s ORDER what to sort by (al, at, ar, c, l, r, t), 'at' is default
al: average lock time
ar: average rows sent
at: average query time
c: count
l: lock time
r: rows sent
t: query time
-r reverse the sort order (largest last instead of first)
-t NUM just show the top n queries
-a don't abstract all numbers to N and strings to 'S'
-n NUM abstract numbers with at least n digits within names
-g PATTERN grep: only consider stmts that include this string
-h HOSTNAME hostname of db server for *-slow.log filename (can be wildcard),
default is '*', i.e. match all
-i NAME name of server instance (if using mysql.server startup script)
-l don't subtract lock time from total timeExamples:
mysqldumpslow -s r -t 10 /database/mysql/slow-log.txt The top 10 queries returned to the recordset are obtained. mysqldumpslow -s t -t 10 -g "left join" /database/mysql/slow-log.txt Get the first 10 query statements with left join in time order. mysqldumpslow -a -s t -t 2 /opt/slow_query_log.txt - a parameter, indicating that similar SQL statements are not merged, displaying numbers and strings in specific SQL statements.
The correct results are as follows:
[root@dras-test local]# mysqldumpslow -a -s t -t 2 /opt/slow_query_log.txt
Reading mysql slow query log from /opt/slow_query_log.txt
Count: 60 Time=903.45s (54206s) Lock=0.00s (0s) Rows=13271072.8 (796264367), LibSvr[LibSvr]@2hosts
SELECT * FROM `el_user_litera_info`
Count: 60 Time=335.23s (20113s) Lock=0.00s (0s) Rows=17128739.1 (1027724344), LibSvr[LibSvr]@2hosts
SELECT * FROM `el_user_category_litera`
[root@dras-test local]# mysqldumpslow -a -s t -t 5 /opt/slow_query_log.txt
Reading mysql slow query log from /opt/slow_query_log.txt
Count: 60 Time=903.45s (54206s) Lock=0.00s (0s) Rows=13271072.8 (796264367), LibSvr[LibSvr]@2hosts
SELECT * FROM `el_user_litera_info`
Count: 60 Time=335.23s (20113s) Lock=0.00s (0s) Rows=17128739.1 (1027724344), LibSvr[LibSvr]@2hosts
SELECT * FROM `el_user_category_litera`
Count: 60 Time=277.45s (16646s) Lock=0.00s (0s) Rows=13271097.1 (796265825), LibSvr[LibSvr]@2hosts
SELECT * FROM `el_user_litera_reader_info`
Count: 60 Time=153.27s (9196s) Lock=0.00s (0s) Rows=8943019.9 (536581195), LibSvr[LibSvr]@2hosts
SELECT * FROM `el_user_adjunct_info`
Count: 60 Time=91.95s (5516s) Lock=0.00s (0s) Rows=2036609.1 (122196547), LibSvr[LibSvr]@2hosts
SELECT * FROM `el_user_note_content`