Mysql – Anemometer – query on analysing the slow logs

Ah, I should have checked that first:

log_queries_not_using_indexes has been turned on, so a whole number of queries has been logged because they were not using indexes.

Apparently, a query "not using indexes" is not marked in any way in the slow query log, so one has to guess whether an entry has been logged because of an execution time exceeding the long_query_time threshold or because of indexes.

Confirming what you already know, for future reference:

"The time to acquire the initial locks is not counted as execution time."

^{— http://dev.mysql.com/doc/refman/5.6/en/slow-query-log.html}

It stands to reason, at least to me, that a "slow query" is best defined as a query that is poorly-optimized and takes longer than it should even when run in isolation. It follows from that, that queries which only coincidentally take a long time to run because of circumstances unrelated to the query itself -- such as waiting for table locks -- should not be included in the slow query log.

I base this on two things: intuition, since the slow query log can also "log_queries_not_using_indexes" -- which is presumably also intended to catch bad optimization before the data set grows to the point that the queries actually turn into "slow" queries... and the fact that it doesn't seem to have been designed that way just because it was easier to implement or for any architectural limitation.

In sql/sql_class.h:

void update_server_status()
  {
    ulonglong end_utime_of_query= current_utime();
    if (end_utime_of_query > utime_after_lock + variables.long_query_time)
      server_status|= SERVER_QUERY_WAS_SLOW;
  }

If utime_after_lock were replaced with start_utime ... that should drive the behavior you are expecting. YMMV, but that's what it looks like from here, from a brief look into the source code.

Alternately, you could write a script in your favorite language to hold a connection to the server and execute SHOW PROCESSLIST every "n" seconds. The script would "remember" what each thread's Time value was from iteration to iteration, and could report execution times to you with the granularity of the polling interval when it found interesting patterns. When it sees an interesting query, it could switch to SHOW FULL PROCESSLIST to get the entire body of the query.

I would poll my servers for their processlist (not "full") at 1 second intervals -- yes, in production -- and display the number of threads and the current longest-running query on my real-time status dashboard and have never seen evidence of an ill-effect from this.