Episode 3 – Slow Query Log
April 6th, 2007
Podcast: Play in new window | Download
One of the best features of MySQL is the fact that you can
have a log of all queries that take longer than n seconds.
Activating the Log
To activate this log start MySQL with the –log-slow-queries[=file_name] option, or add the previous option to your my.cnf or my.ini and restart the server:
[mysqld]
...
log-slow-queries[=file_name]
You can specify a file name for the slow-query-log or it will be called host_name-slow.log. By default the log is in the data directory, unless you specify an absolute path with the file name.
By default a slow query is one that takes 10 seconds. You can change that by specifying long_query_time in either during startup or in the my.cnf or my.ini file.
[mysqld]
...
log-slow-queries
long_query_time=8
Viewing the Log
The log is in text format and can easily be viewed by any text editor and looks like this:
# Time: 070116 5:16:35
# User@Host: nvusr[nvusr] @ app01 [10.30.5.226]
# Query_time: 21 Lock_time: 0 Rows_sent: 20 Rows_examined: 4078677
SELECT ectransactions.*, interchanges.interchange_datetime as transaction_datetime, interchanges.partner_name, interchanges.direction, functional_groups.functional_group_control_numb, fo_name, functional_organization_qualid, partner_name, partner_qualid, interchanges.interchange_control_number, operators.name as operator_name, trading_participants.name as client_name FROM ectransactions left join functional_groups ON ectransactions.functional_group_id=functional_groups.id left join interchanges ON ectransactions.interchange_id=interchanges.id left join trading_participants ON ectransactions.trading_participant_id=trading_participants.id left join operators ON ectransactions.operator_id=operators.id ORDER BY client_name asc, transaction_datetime desc LIMIT 0, 20;
However, its a lot more readable with the mysqldumpslow command, whose output looks like this:
Count: 1 Time=24.00s (24s) Lock=0.00s (0s) Rows=20.0 (20), nvusr[nvusr]@tqapp02
SELECT ectransactions.*, interchanges.interchange_datetime as transaction_datetime, interchanges.partner_name, interchanges.direction, functional_groups.functional_group_control_numb, fo_name, functional_organization_qualid, partner_name, partner_qualid, interchanges.interchange_control_number, operators.name as operator_name, trading_participants.name as client_name FROM ectransactions left join functional_groups ON ectransactions.functional_group_id=functional_groups.id left join interchanges ON ectransactions.interchange_id=interchanges.id left join trading_participants ON ectransactions.trading_participant_id=trading_participants.id left join operators ON ectransactions.operator_id=operators.id ORDER BY transaction_datetime asc, description desc LIMIT N, N
Count: 2 Time=22.00s (44s) Lock=0.00s (0s) Rows=20.0 (40), nvusr[nvusr]@2hosts
SELECT ectransactions.*, interchanges.interchange_datetime as transaction_datetime, interchanges.partner_name, interchanges.direction, functional_groups.functional_group_control_numb, fo_name, functional_organization_qualid, partner_name, partner_qualid, interchanges.interchange_control_number, operators.name as operator_name, trading_participants.name as client_name FROM ectransactions left join functional_groups ON ectransactions.functional_group_id=functional_groups.id left join interchanges ON ectransactions.interchange_id=interchanges.id left join trading_participants ON ectransactions.trading_participant_id=trading_participants.id left join operators ON ectransactions.operator_id=operators.id ORDER BY client_name asc, transaction_datetime desc LIMIT N, N
I Want More!
You can also have MySQL add all queries that don’t use indexes into the slow-query-log. Add –log-queries-not-using-indexes during startup or in the my.cnf or my.ini file.
Bye! Thanks for all the fish!