long_query_time was an integer in MySQL 5.0, so one second became the conventional slow-query threshold and stayed there out of habit. It has taken a float since 5.1. On a page issuing forty queries, nothing is ever going to take a second — the queries worth finding are the ones at two hundred milliseconds, eight times over.
SET GLOBAL slow_query_log = 1;
SET GLOBAL slow_query_log_file = '/var/log/mysql/slow.log';
SET GLOBAL long_query_time = 0.2;
-- the global only applies to connections opened after it changes
SET SESSION long_query_time = 0.2;
-- and in my.cnf, or it is gone at the next restart
-- [mysqld]
-- slow_query_log = 1
-- long_query_time = 0.2
-- log_queries_not_using_indexes = 0The session copy is the detail that wastes an evening: long_query_time is a session variable with a global default, so setting the global changes nothing for connections that are already open. An application using persistent connections, or a connection pool that has been up since the last deploy, will keep logging at the old threshold and the change appears to have done nothing. Two things are worth knowing about what the log records. The timer covers execution only, so a query that spent four seconds blocked behind another one is logged at its own runtime — Lock_time in the entry is the half that explains the discrepancy. And log_queries_not_using_indexes is better left off: on any schema with small lookup tables it fills the file with full scans that are entirely correct choices, and the noise is what stops people reading the log at all.