MDEV-18333 Slow_queries count doesn't increase when slow_query_log is turned off

mysql-test/r/log_slow.result

@@ -76,3 +76,40 @@ set @@log_slow_filter=default;
 set @@log_slow_verbosity=default;
 set global log_output= default;
 truncate mysql.slow_log;
+#
+# MDEV-18333 Slow_queries count doesn't increase when slow_query_log is turned off
+#
+SET SESSION slow_query_log=OFF;
+SET GLOBAL slow_query_log=OFF;
+SET long_query_time=0.1;
+# Although this query is disallowed by slow_query_log, it should still increment Slow_queries
+SELECT VARIABLE_VALUE INTO @global_slow_queries
+FROM INFORMATION_SCHEMA.GLOBAL_STATUS
+WHERE VARIABLE_NAME='SLOW_QUERIES';
+SELECT sleep(0.2) INTO @tmp FROM DUAL;
+SELECT
+CAST(VARIABLE_VALUE AS UNSIGNED)-@global_slow_queries AS Slow_queries_increment
+FROM
+INFORMATION_SCHEMA.GLOBAL_STATUS
+WHERE
+VARIABLE_NAME='SLOW_QUERIES';
+Slow_queries_increment
+1
+# Although this query is disallowed by log_slow_filter, it should still increment Slow_queries
+SET log_slow_filter=filesort;
+SELECT sleep(0.2) INTO @tmp FROM DUAL;
+SELECT VARIABLE_VALUE INTO @global_slow_queries
+FROM INFORMATION_SCHEMA.GLOBAL_STATUS
+WHERE VARIABLE_NAME='SLOW_QUERIES';
+SELECT sleep(0.2) INTO @tmp FROM DUAL;
+SELECT
+CAST(VARIABLE_VALUE AS UNSIGNED)-@global_slow_queries AS Slow_queries_increment
+FROM
+INFORMATION_SCHEMA.GLOBAL_STATUS
+WHERE
+VARIABLE_NAME='SLOW_QUERIES';
+Slow_queries_increment
+1
+SET log_slow_filter=DEFAULT;
+SET @@long_query_time=default;
+SET GLOBAL slow_query_log= @org_slow_query_log;

mysql-test/t/log_slow.test

@@ -58,3 +58,43 @@ set @@log_slow_filter=default;
 set @@log_slow_verbosity=default;
 set global log_output= default;
 truncate mysql.slow_log;
+
+--echo #
+--echo # MDEV-18333 Slow_queries count doesn't increase when slow_query_log is turned off
+--echo #
+
+SET SESSION slow_query_log=OFF;
+SET GLOBAL slow_query_log=OFF;
+SET long_query_time=0.1;
+
+--echo # Although this query is disallowed by slow_query_log, it should still increment Slow_queries
+
+SELECT VARIABLE_VALUE INTO @global_slow_queries
+  FROM INFORMATION_SCHEMA.GLOBAL_STATUS
+  WHERE VARIABLE_NAME='SLOW_QUERIES';
+SELECT sleep(0.2) INTO @tmp FROM DUAL;
+SELECT
+    CAST(VARIABLE_VALUE AS UNSIGNED)-@global_slow_queries AS Slow_queries_increment
+  FROM
+    INFORMATION_SCHEMA.GLOBAL_STATUS
+  WHERE
+    VARIABLE_NAME='SLOW_QUERIES';
+
+--echo # Although this query is disallowed by log_slow_filter, it should still increment Slow_queries
+
+SET log_slow_filter=filesort;
+SELECT sleep(0.2) INTO @tmp FROM DUAL;
+SELECT VARIABLE_VALUE INTO @global_slow_queries
+  FROM INFORMATION_SCHEMA.GLOBAL_STATUS
+  WHERE VARIABLE_NAME='SLOW_QUERIES';
+SELECT sleep(0.2) INTO @tmp FROM DUAL;
+SELECT
+    CAST(VARIABLE_VALUE AS UNSIGNED)-@global_slow_queries AS Slow_queries_increment
+  FROM
+    INFORMATION_SCHEMA.GLOBAL_STATUS
+  WHERE
+    VARIABLE_NAME='SLOW_QUERIES';
+SET log_slow_filter=DEFAULT;
+
+SET @@long_query_time=default;
+SET GLOBAL slow_query_log= @org_slow_query_log;

sql/log_event.cc

@@ -4528,7 +4528,7 @@ int Query_log_event::do_apply_event(rpl_group_info *rgi,
            thd->variables.sql_log_slow= opt_log_slow_slave_statements;
          }
 
-        thd->enable_slow_log= thd->variables.sql_log_slow;
+        thd->enable_slow_log= true;
         mysql_parse(thd, thd->query(), thd->query_length(), &parser_state);
         /* Finalize server status flags after executing a statement. */
         thd->update_server_status();

sql/sql_admin.cc

@@ -1246,7 +1246,6 @@ bool Sql_cmd_analyze_table::execute(THD *thd)
                          FALSE, UINT_MAX, FALSE))
     goto error;
   WSREP_TO_ISOLATION_BEGIN_WRTCHK(NULL, NULL, first_table);
-  thd->enable_slow_log= opt_log_slow_admin_statements;
   res= mysql_admin_table(thd, first_table, &m_lex->check_opt,
                          "analyze", lock_type, 1, 0, 0, 0,
                          &handler::ha_analyze, 0);
@@ -1278,8 +1277,6 @@ bool Sql_cmd_check_table::execute(THD *thd)
   if (check_table_access(thd, SELECT_ACL, first_table,
                          TRUE, UINT_MAX, FALSE))
     goto error; /* purecov: inspected */
-  thd->enable_slow_log= opt_log_slow_admin_statements;
-
   res= mysql_admin_table(thd, first_table, &m_lex->check_opt, "check",
                          lock_type, 0, 0, HA_OPEN_FOR_REPAIR, 0,
                          &handler::ha_check, &view_check);
@@ -1303,7 +1300,6 @@ bool Sql_cmd_optimize_table::execute(THD *thd)
                          FALSE, UINT_MAX, FALSE))
     goto error; /* purecov: inspected */
   WSREP_TO_ISOLATION_BEGIN_WRTCHK(NULL, NULL, first_table);
-  thd->enable_slow_log= opt_log_slow_admin_statements;
   res= (specialflag & SPECIAL_NO_NEW_FUNC) ?
     mysql_recreate_table(thd, first_table, true) :
     mysql_admin_table(thd, first_table, &m_lex->check_opt,
@@ -1336,7 +1332,6 @@ bool Sql_cmd_repair_table::execute(THD *thd)
   if (check_table_access(thd, SELECT_ACL | INSERT_ACL, first_table,
                          FALSE, UINT_MAX, FALSE))
     goto error; /* purecov: inspected */
-  thd->enable_slow_log= opt_log_slow_admin_statements;
   WSREP_TO_ISOLATION_BEGIN_WRTCHK(NULL, NULL, first_table);
   res= mysql_admin_table(thd, first_table, &m_lex->check_opt, "repair",
                          TL_WRITE, 1,

sql/sql_admin.h

@@ -28,7 +28,7 @@ int reassign_keycache_tables(THD* thd, KEY_CACHE *src_cache,
 /**
   Sql_cmd_analyze_table represents the ANALYZE TABLE statement.
 */
-class Sql_cmd_analyze_table : public Sql_cmd
+class Sql_cmd_analyze_table : public Sql_cmd_admin
 {
 public:
   /**
@@ -53,7 +53,7 @@ public:
 /**
   Sql_cmd_check_table represents the CHECK TABLE statement.
 */
-class Sql_cmd_check_table : public Sql_cmd
+class Sql_cmd_check_table : public Sql_cmd_admin
 {
 public:
   /**
@@ -77,7 +77,7 @@ public:
 /**
   Sql_cmd_optimize_table represents the OPTIMIZE TABLE statement.
 */
-class Sql_cmd_optimize_table : public Sql_cmd
+class Sql_cmd_optimize_table : public Sql_cmd_admin
 {
 public:
   /**
@@ -102,7 +102,7 @@ public:
 /**
   Sql_cmd_repair_table represents the REPAIR TABLE statement.
 */
-class Sql_cmd_repair_table : public Sql_cmd
+class Sql_cmd_repair_table : public Sql_cmd_admin
 {
 public:
   /**

sql/sql_alter.cc

@@ -302,8 +302,6 @@ bool Sql_cmd_alter_table::execute(THD *thd)
                         "INDEX DIRECTORY");
   create_info.data_file_name= create_info.index_file_name= NULL;
 
-  thd->enable_slow_log= opt_log_slow_admin_statements;
-
 #ifdef WITH_WSREP
   TABLE *find_temporary_table(THD *thd, const TABLE_LIST *tl);
 
@@ -352,8 +350,6 @@ bool Sql_cmd_discard_import_tablespace::execute(THD *thd)
   if (check_grant(thd, ALTER_ACL, table_list, false, UINT_MAX, false))
     return true;
 
-  thd->enable_slow_log= opt_log_slow_admin_statements;
-
   /*
     Check if we attempt to alter mysql.slow_log or
     mysql.general_log table and return an error if

sql/sql_alter.h

@@ -363,7 +363,7 @@ private:
   statements.
   @todo move Alter_info and other ALTER generic structures from Lex here.
 */
-class Sql_cmd_common_alter_table : public Sql_cmd
+class Sql_cmd_common_alter_table : public Sql_cmd_admin
 {
 protected:
   /**

sql/sql_cmd.h

@@ -145,6 +145,8 @@ public:
   */
   virtual bool execute(THD *thd) = 0;
 
+  virtual bool log_slow_enabled_statement(const THD *thd) const;
+
 protected:
   Sql_cmd()
   {}
@@ -161,4 +163,17 @@ protected:
   }
 };
 
+
+class Sql_cmd_admin: public Sql_cmd
+{
+public:
+  Sql_cmd_admin()
+  {}
+  ~Sql_cmd_admin()
+  {}
+  bool log_slow_enabled_statement(const THD *thd) const;
+};
+
+
+
 #endif // SQL_CMD_INCLUDED

sql/sql_lex.cc

@@ -4719,6 +4719,20 @@ bool LEX::is_partition_management() const
            alter_info.flags ==  Alter_info::ALTER_REORGANIZE_PARTITION));
 }
 
+
+bool Sql_cmd::log_slow_enabled_statement(const THD *thd) const
+{
+  return global_system_variables.sql_log_slow && thd->variables.sql_log_slow;
+}
+
+
+bool Sql_cmd_admin::log_slow_enabled_statement(const THD *thd) const
+{
+  return opt_log_slow_admin_statements &&
+         Sql_cmd::log_slow_enabled_statement(thd);
+}
+
+
 #ifdef MYSQL_SERVER
 uint binlog_unsafe_map[256];
 

sql/sql_parse.cc

@@ -1308,7 +1308,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd,
     Commands which always take a long time are logged into
     the slow log only if opt_log_slow_admin_statements is set.
   */
-  thd->enable_slow_log= thd->variables.sql_log_slow;
+  thd->enable_slow_log= true;
   thd->query_plan_flags= QPLAN_INIT;
   thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */
   thd->reset_kill_query();
@@ -2013,6 +2013,31 @@ bool dispatch_command(enum enum_server_command command, THD *thd,
 }
 
 
+static bool log_slow_enabled_statement(const THD *thd)
+{
+  /*
+    TODO-10.4: Add classes Sql_cmd_create_index and Sql_cmd_drop_index
+    for symmetry with other admin commands, so these statements can be
+    handled by this command:
+  */
+  if (thd->lex->m_sql_cmd)
+    return thd->lex->m_sql_cmd->log_slow_enabled_statement(thd);
+
+  /*
+    Currently CREATE INDEX or DROP INDEX cause a full table rebuild
+    and thus classify as slow administrative statements just like
+    ALTER TABLE.
+  */
+  if ((thd->lex->sql_command == SQLCOM_CREATE_INDEX ||
+       thd->lex->sql_command == SQLCOM_DROP_INDEX) &&
+      !opt_log_slow_admin_statements)
+    return true;
+
+  return global_system_variables.sql_log_slow &&
+         thd->variables.sql_log_slow;
+}
+
+
 /*
   @note
     This function must call delete_explain_query().
@@ -2029,12 +2054,17 @@ void log_slow_statement(THD *thd)
   if (unlikely(thd->in_sub_stmt))
     goto end;                           // Don't set time for sub stmt
 
+  /*
+    Skip both long_query_count increment and logging if the current
+    statement forces slow log suppression (e.g. an SP statement).
 
-  /* Follow the slow log filter configuration. */ 
+    Note, we don't check for global_system_variables.sql_log_slow here.
-  if (!thd->enable_slow_log || !global_system_variables.sql_log_slow ||
+    According to the manual, the "Slow_queries" status variable does not require
-      (thd->variables.log_slow_filter
+    sql_log_slow to be ON. So even if sql_log_slow is OFF, we still need to
-        && !(thd->variables.log_slow_filter & thd->query_plan_flags)))
+    continue and increment long_query_count (and skip only logging, see below):
-    goto end; 
+  */
+  if (!thd->enable_slow_log)
+    goto end; // E.g. SP statement
 
   if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
        ((thd->server_status &
@@ -2044,6 +2074,10 @@ void log_slow_statement(THD *thd)
       thd->get_examined_row_count() >= thd->variables.min_examined_row_limit)
   {
     thd->status_var.long_query_count++;
+
+    if (!log_slow_enabled_statement(thd))
+      goto end;
+
     /*
       If rate limiting of slow log writes is enabled, decide whether to log
       this query to the log or not.
@@ -2052,6 +2086,14 @@ void log_slow_statement(THD *thd)
         (global_query_id % thd->variables.log_slow_rate_limit) != 0)
       goto end;
 
+    /*
+      Follow the slow log filter configuration:
+      skip logging if the current statement matches the filter.
+    */
+    if (thd->variables.log_slow_filter &&
+        !(thd->variables.log_slow_filter & thd->query_plan_flags))
+      goto end;
+
     THD_STAGE_INFO(thd, stage_logging_slow_query);
     slow_log_print(thd, thd->query(), thd->query_length(), 
                    thd->utime_after_query);
@@ -3527,12 +3569,6 @@ end_with_restore_list:
     if (check_one_table_access(thd, INDEX_ACL, all_tables))
       goto error; /* purecov: inspected */
     WSREP_TO_ISOLATION_BEGIN(first_table->db, first_table->table_name, NULL)
-    /*
-      Currently CREATE INDEX or DROP INDEX cause a full table rebuild
-      and thus classify as slow administrative statements just like
-      ALTER TABLE.
-    */
-    thd->enable_slow_log&= opt_log_slow_admin_statements;
     thd->query_plan_flags|= QPLAN_ADMIN;
 
     bzero((char*) &create_info, sizeof(create_info));

sql/sql_partition_admin.cc

@@ -89,7 +89,6 @@ bool Sql_cmd_alter_table_exchange_partition::execute(THD *thd)
   /* Not allowed with EXCHANGE PARTITION */
   DBUG_ASSERT(!create_info.data_file_name && !create_info.index_file_name);
 
-  thd->enable_slow_log= opt_log_slow_admin_statements;
   DBUG_RETURN(exchange_partition(thd, first_table, &alter_info));
 }