2

I wish to analyze some read-write contentions problems on a very huge table where writes are very fast, less than 1ms in most case. The point is that the contention makes those write queries sometimes wait for the lock for a long time, i.e. hundreds of milliseconds. But the query itself remains very fast so it's not selected as a "slow query", which threshold is actually 10ms.

The only way to gather the information I need is to put à 0ms threshold so I can capture all queries, but it's not sustainable for more than 10mn on our production environment, where it would produce about 200MB of logs per minute.

In fact I can't understand why MySQL don't include the lock time, added to the execution time, for the slow query log selection process. At least, I wish there were an option for that.

Am I missing something ?

1
  • Which engine? Which version? The "locks" in MyISAM are rather different than in InnoDB.
    – Rick James
    Oct 17, 2018 at 23:08

1 Answer 1

4

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.

3
  • Thanks for the spent time. Concerning the SHOW PROCESS LIST, I won't implement such a thing because I want to catch many 1ms queries waiting 10-100ms for a write lock. So I'd had to run it say a hundred times per second, and I guess that's not an option.
    – Tom Desp
    Feb 5, 2014 at 17:56
  • Concerning the intuition part :), experience has led me to think that real production environment optimization is almost as important a design optimization. And MyISAM table locks are a real running issue that'd have deserved specific monitoring tools.
    – Tom Desp
    Feb 5, 2014 at 18:03
  • Sure, real environment optimization is an important pursuit, but what I mean is that my intuitive conclusion was that this isn't the purpose of the slow query log... it's for finding bad queries, not overloaded environments. Your application can tell how long queries take. The slow query log can tell you which ones are most likely to need attention because of their intrinsic design without regard to external factors. Also, don't use MyISAM. :) Feb 5, 2014 at 18:13

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.