Query Profiling Tools — Part 1, mysqlsla

The “sla” in mysqlsla stands for “statement log analyzer”. This does a much better job than mysqldumpslow of analyzing your slow query log. In fact, you can sort by many different parameters — by sheer number of times the query shows up in the slow query log, by the total or average query time, by the lock time, etc. This is really good for weeding out pesky entries in the slow query log that you do not care about. In this case, our client was using log-queries-not-using-indexes, so there was a lot of junk in the slow query log as well (for instance, every time a mysqldump backup was run, the slow query log got plenty of entries). In this case, I’m using –slow to read the slow query log at the filename specified, –flat to flatten all the text to lowercase (basically case-insensitive matching) and –sort at to sort by “average time”.

> ./mysqlsla --flat --slow ~mysql/var/mysql-slow.log --sort at
Reading slow log '~mysql/var/mysql-slow.log'.
33274 total queries, 658 unique.
Sorting by 'at'.
__ 001 _______________________________________________________________________

Count         : 107 (0%)

Time          : 2343 s total, 21 s avg, 0 s to 68 s max

95% of Time   : 2011 s total, 19 s avg, 0 s to 44 s max

Lock Time     : 0 s total, 0 s avg, 0 s to 0 s max

Rows sent     : 125069 avg, 1816 to 238794 max

Rows examined : 125069 avg, 1816 to 238794 max

User          : foo@localhost/ (18%)

Database      : testdb

select /*!N sql_no_cache */ * from `sessions`;

This is just a backup query, so I’m not worried about it.

__ 002 _______________________________________________________________________
Count         : 1 (0%)
Time          : 12 s total, 12 s avg, 12 s to 12 s max
Lock Time     : 0 s total, 0 s avg, 0 s to 0 s max
Rows sent     : 25150 avg, 25150 to 25150 max
Rows examined : 708891 avg, 708891 to 708891 max
User          : root@localhost/127.0.0.1 (19%)
Database      : Unknown
select month(created_at), event_type, from events group by N, N, N;

This query was only run once, and by root, so it was probably done by hand. I can filter for only the users I want using the –only-users foo,bar,baz option to mysqlsla. In fact, I think I will do that, and I can even use mysqlsla to generate EXPLAINs for me right inline using the –explain option.

> ./mysqlsla --flat --slow ~mysql/var/mysql-slow.log  --sort at --explain --only-users foo --user <user> --password <password> --databases testdb
Only users: foo
Reading slow log '/~mysql/var/mysql-slow.log'.6110 total queries, 137 unique.

Databases for Unknown: testdb
Sorting by 'at'.
__ 001 _______________________________________________________________________
Count         : 105 (1%)
Time          : 2323 s total, 22 s avg, 17 s to 68 s max
95% of Time   : 1991 s total, 20 s avg, 17 s to 44 s max
Lock Time     : 0 s total, 0 s avg, 0 s to 0 s max
Rows sent     : 127153 avg, 16734 to 238794 max
Rows examined : 127153 avg, 16734 to 238794 max
User          : foo@localhost/ (100%)
Database      : testdb
Rows (EXPLAIN): 238794 produced, 238794 read
EXPLAIN       :
id: 1
select_type: SIMPLE
table: sessions
type: ALL
possible_keys:
key:
key_len:
ref:
rows: 238794
Extra:select /*!N sql_no_cache */ * from `sessions`;

__ 002 _______________________________________________________________________
Count         : 1 (0%)
Time          : 1 s total, 1 s avg, 1 s to 1 s max
Lock Time     : 0 s total, 0 s avg, 0 s to 0 s max
Rows sent     : 1 avg, 1 to 1 max
Rows examined : 587326 avg, 587326 to 587326 max
User          : foo@localhost/ (100%)
Database      : testdb
Rows (EXPLAIN): 803857 produced, 803857 read
EXPLAIN       :
id: 1
select_type: SIMPLE
table: events
type: ALL
possible_keys:
key:
key_len:
ref:
rows: 803857
Extra: Using where
select count(*) from events where event_type='S' order by created_at desc;

This was only run once, but if it were run more often, I could definitely justify having an index on created_at. Or, if the table has an AUTO_INCREMENT primary key and is InnoDB, I would suggest ordering by the primary key desc instead of the created_at field — assuming that created_at is a timestamp of when the record was created.

__ 003 _______________________________________________________________________
Count         : 4 (0%)
Time          : 4 s total, 1 s avg, 1 s to 1 s max
95% of Time   : 3 s total, 1 s avg, 1 s to 1 s max
Lock Time     : 0 s total, 0 s avg, 0 s to 0 s max
Rows sent     : 155 avg, 0 to 318 max
Rows examined : 727275 avg, 727274 to 727276 max
User          : foo@localhost/ (100%)
Database      : testdb
Rows (EXPLAIN): 803857 produced, 803857 read
EXPLAIN       :
id: 1
select_type: SIMPLE
table: user_events
type: ALL
possible_keys: events_created_at_index
key:
key_len:
ref:
rows: 803857
Extra: Using where

select * from events where event_type='S' and created_at > 'S';

In this case, I would look to see what the selectivity of the event_type is, and perhaps the query would benefit from having an index on event_type. Again, if the table is InnoDB, we can get a sense of whether or not we can use ORDER BY on an existing AUTO_INCREMENT primary key.

__ 004 _______________________________________________________________________
Count         : 1 (0%)
Time          : 1 s total, 1 s avg, 1 s to 1 s max
Lock Time     : 0 s total, 0 s avg, 0 s to 0 s max
Rows sent     : 11803 avg, 11803 to 11803 max
Rows examined : 810555 avg, 810555 to 810555 max
User          : foo@localhost/ (100%)
Database      : testdb
Rows (EXPLAIN): 803857 produced, 803857 read
EXPLAIN       :
id: 1
select_type: SIMPLE
table: events
type: ALL
possible_keys:
key:
key_len:
ref:
rows: 803857
Extra: Using where; Using temporary; Using filesort
select * from events where event_type='S' group by item_id;

Again, this table could use some indexes. Also, note the count of 1 again, though it is coming from the right user. But if we saw this over and over, we certainly could put an index. I’d play around here, because there might be merit in an index using one or both event_type or item_id. As well, I see a lot of “select *” in the slow queries, which in general is a bad idea, and I would meet with the developers to see what they really need from the query.It also worries me that I do not see any complex join-type queries — this is good, in the sense that if they exist they are not slow. But given that this is the same client as in the previous installment of this series, I can surmise that there are not a lot of joins, period, and I can work with the developers to make better queries.

I have only shown up to 4 queries here, but mysqlsla shows you 10 by default. Much like the Maatkit overview, I have only shown the very basic functionality, and the learning curve is very low. In fact, mysqlsla is simply a perl script, so it has a lower footprint and is easier to “install”! I recommend installing both, though.