log_slow_statement called unconditionally

[Raghavendra D Prabhu]

log_slow_statement(thd) is called unconditionally in many places except like sp_instr_stmt::execute which uses like

      if (!res && unlikely(thd->enable_slow_log))
        log_slow_statement(thd);

Ideally, if opt_slow_log is set to 0, this function shouldn't be
called at all. (There should be no need to set long_query_time to
be set to 0 or other things).

This was noticed when, on an instance, where slow_query_log was
set to 0, the status variable Slow_queries was jumping quite
rapidly (I also noticed that in init_slave_thread
thd->enable_slow_log is set to TRUE by default)

[Laurynas Biveinis (laurynas-biveinis)]

Raghu -

Please read the source of log_slow_statement(). It is not an issue that the function itself is called, because it is there where the decision to slow-log or not a given query is made, it just quits early if needed.

The status variable Slow_queries jumping rapidly is another issue that should be investigated. It is only bumped in log_slow_statement() right before slow_log_print() call.

thd->enable_slow_log = TRUE in init_slave_thread is benign.

[Alexey Kopytov (akopytov)]

There still seems to be a problem. log_slow_statement() is almost no-op in the upstream server if thd->enable_slow_log is FALSE.

In Percona Server we do a bunch of other things there before checking thd->enable_slow_log:

1. slow_log_filter_checks
2. checking if query_response_time is enabled and calling query_response_time_collect() if it is (which I believe should be done before slow_log_filter_checks, but that is a separate issue)
3. copying a number of global values to session vars depending on opt_slow_query_log_use_global_control
4. log_slow_rate_limit checks

So the question is whether we really want to do 1, 3 and 4 unconditionally, i.e. even if thd->enable_slow_log is FALSE. It looks like we don't?

[Alexey Kopytov (akopytov)]

And there's something suspicious with Slow_queries accounting. From the code indeed looks like Slow_queries are incremented regardless of the opt_slow_log value.

The only thing the manual says about Slow_queries is: "The number of queries that have taken more than long_query_time seconds. See Section 5.2.5, “The Slow Query Log”. "

However there are no references to Slow_queries in that section.

So technically incrementing Slow_queries for every query that has taken more than long_query_time seconds even if slow log is disabled does not contradict the manual. But it looks confusing and would qualify for a upstream documentation bug.

[Laurynas Biveinis (laurynas-biveinis)]

I was too quick in my reading of log_slow_statement(). Yes, it does a bunch of stuff without bothering to check thd->enable_slow_log first and response time distribution collection is misplaced. Also the slow_log_filter_check happens before the corresponding variable is copied from global to session var.

Re. slow_queries, I'd log an upstream doc bug first. It could have been intended to have a variable to count the queries with runtime > long_query_time independently of the slow query logging?

[Raghavendra D Prabhu (raghavendra-prabhu)]

a) Regarding slow query accounting and opt_slow_log, it indeed looks
like it is an I/O option with accounting possible even when it is
turned off. I will file a documentation bug for this.

b)
Now, regarding thd->enable_slow_log, yes, the upstream one
checks only that variable before proceeding and checks it twice
for sp_instr_stmt::execute.

c)
Regarding slave threads, compared to upstream, I see

- thd->enable_slow_log= opt_log_slow_slave_statements;
- thd->write_to_slow_log= opt_log_slow_slave_statements;
+ thd->enable_slow_log= TRUE;

with this, opt_log_slow_slave_statements is only checked in
slow_log_print; which means for slave threads, the whole function log_slow_statement
is called because compared to upstream, it (it being thd->enable_slow_log) is TRUE till then due to https://code.launchpad.net/~laurynas-biveinis/percona-server/slow-log-fixes-5.5/+merge/144058

Following are missing from PS source:

 sql/log_event.cc do_apply_event 3484 thd->enable_slow_log= opt_log_slow_slave_statements;
 sql/slave.cc init_slave_thread 2082 thd->enable_slow_log= opt_log_slow_slave_statements;

 I can report c) as a separate bug if required.

[Laurynas Biveinis (laurynas-biveinis)]

Raghu -

Thanks, please report a bug re. c).

[Raghavendra D Prabhu (raghavendra-prabhu)]

Reported the documentation bug here -- http://bugs.mysql.com/bug.php?id=68833

[Laurynas Biveinis (laurynas-biveinis)]

See bug 1163232.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1344