mysql 5.7: Why are 38% of queries missing from the slow query log?

Question

Sporadically we're seeing thousands of queries per second reported by show global status like "Queries" but don't see them in the slow query log with everything enabled, so we can't see what these queries are.

Here are (what I think are) the relevant global variables if I want to see everything in the slow query log:

log_queries_not_using_indexes   ON
log_slow_admin_statements   ON
log_slow_slave_statements   ON
log_throttle_queries_not_using_indexes  0
long_query_time 0.000000
min_examined_row_limit  0
slow_launch_time    2
slow_query_log  ON
slow_query_log_file /tmp/slow.log

Over a 5min period, mysql global status variable Questions reports 90433 queries, but there are only 56479 queries in the slow log. Where are the missing 33954 (38%) queries?

I enable the log with a enableLog.pl script that sets up the above variables for 5 minutes, then reverts them to their original values:

# mysql --login-path=cm -Ee 'show  global status like "Queries"' && rm -rf /tmp/slow.log && ./enableLog.pl --duration 5m /tmp/slow.log && mysql --login-path=cm -Ee 'show  global status like "Queries"'
*************************** 1. row ***************************
Variable_name: Queries
        Value: 73570440
11:41:51: logging for 00:05:00 until 11:46:51
... ending
*************************** 1. row ***************************
Variable_name: Queries
        Value: 73660873

# perl -E 'say 73660873-73570440'
90433

# grep '^# Time: ' /tmp/slow.log | wc -l
56479

# perl -E 'say 90433-56479'
33954

# perl -E 'say +(90433-56479)/90433'
0.375460285515243

While enableLog.pl is running here are the (relevant) global variables:

# mysql --login-path=cm -e 'show global variables;' | egrep '^(slow_|log_|min_)'
log_bin OFF
log_bin_basename    
log_bin_index   
log_bin_trust_function_creators OFF
log_bin_use_v1_row_events   OFF
log_builtin_as_identified_by_password   OFF
log_error   /var/log/mysql/error.log
log_error_verbosity 3
log_output  FILE
log_queries_not_using_indexes   ON
log_slave_updates   OFF
log_slow_admin_statements   ON
log_slow_slave_statements   ON
log_syslog  OFF
log_syslog_facility daemon
log_syslog_include_pid  ON
log_syslog_tag  
log_throttle_queries_not_using_indexes  0
log_timestamps  UTC
log_warnings    2
long_query_time 0.000000
min_examined_row_limit  0
slow_launch_time    2
slow_query_log  ON
slow_query_log_file /tmp/slow.log

# mysql --version
mysql  Ver 14.14 Distrib 5.7.9, for Linux (x86_64) using  EditLine wrapper

Also, they aren't query cache hits:

# mysql --login-path=cm -e 'SHOW GLOBAL STATUS LIKE "Qcache_hits";'
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Qcache_hits   | 0     |
+---------------+-------+

Bill Karwin · Accepted Answer · 2018-01-18T00:00:09.213

Note that changes to global variables are not inherited by existing sessions.

Sessions make a copy of global variables when the session starts, and the session does not re-copy global variables during the session's lifetime. So if sessions are relatively long-lived, some won't have "heard" that they should log their slow queries. The only way to ensure that all sessions heed the new global settings is to make them re-connect and start new sessions.

Some other answers have suggested enabling the general query log, but this won't help if sessions are long-lived and don't know about changes to the global config options. The general query log won't be enabled for those sessions either.

Percona Server implemented a config option slow_query_log_use_global_control to make sessions use the global option for certain query-log options. But this feature is not in stock MySQL.

I implemented a script similar to your enableLog.pl. It's here:

Interesting. I bet that is it. I'll test tomorrow. If that is it, that does make slow log control much less useful. Especially because the long-running sessions presumably need to be restarted again when the slow-logging ends... And restarting processes in bulk is likely to change the traffic patterns that one is trying to debug... :-( — Peter V. Mørch, Jan 18 '18 at 00:19
Unless you can make each session set its own session-level options. Otherwise, yes, that's why Percona implemented the extra options. — Bill Karwin, Jan 18 '18 at 00:21

score 1 · Answer 2 · answered Jan 17 '18 at 12:50

1

From the manual:

The server does not write queries handled by the query cache to the slow query log, nor queries that would not benefit from the presence of an index because the table has zero rows or one row.

Check how many queries were served by the query cache with

SHOW STATUS LIKE 'Qcache%';

Look for Qcache_hits. You can also check the GLOBAL value.

read more about the query cache here

answered Jan 17 '18 at 12:50

fancyPants

50,732
33
89
96

Ah, sorry, I forgot to put that in the original post: `Qcache_hits` is 0 – Peter V. Mørch Jan 17 '18 at 14:23
The global value? Or have you looked at the session value? The way I described it in my answer is the session value. Depending on how you test it, this is probably 0, yes. What about the second part of the sentence in the manual? – fancyPants Jan 17 '18 at 14:50
I tried both global and session values of `Qcache-hits`. Both == 0. I was assuming, but cannot confirm, that the last part of the sentence refered to `log_queries_not_using_indexes` that they wouldn't be logged. In addition, I have tested that at least some queries against tables with exactly one row _indeed are_ logged in the slow.log with these settings whether such tables have indexes or not. – Peter V. Mørch Jan 17 '18 at 15:22
What on earth are trying to accomplish anyway? Why would you want to have all queries in the slow log? If you want all queries, there's the general log. If you want to diagnose them like the slow-query-log, pt-query-digest can do that. – fancyPants Jan 17 '18 at 15:23
I want to see what these remaining 33954 queries are. I really have no idea. No tool can do that if they aren't in the log. – Peter V. Mørch Jan 17 '18 at 15:55

score 0 · Answer 3 · answered Jan 17 '18 at 22:40

When you want to know, turn on BOTH the slow query log, as described AND the General Log in the same script. It will be real easy to compare side by side to see what the General Log is doing that is 'missing' in the slow query log.

Remember turn OFF the General Log at the end of your session to avoid filling your storage device.

mysql 5.7: Why are 38% of queries missing from the slow query log?

3 Answers3