diff options
author | Alexander Barkov <bar@mariadb.com> | 2019-02-27 13:14:31 +0400 |
---|---|---|
committer | Alexander Barkov <bar@mariadb.com> | 2019-03-04 13:49:15 +0400 |
commit | 19df45a705a48f5c8c21af0814cb5be7d816977b (patch) | |
tree | f4c4f13df3ff1bad07639e2e1be2ddc386b796bc | |
parent | f2e1451740d417f1c9ea8626d937fbcacc91bb55 (diff) | |
download | mariadb-git-19df45a705a48f5c8c21af0814cb5be7d816977b.tar.gz |
MDEV-18333 Slow_queries count doesn't increase when slow_query_log is turned off
-rw-r--r-- | mysql-test/r/log_slow.result | 37 | ||||
-rw-r--r-- | mysql-test/t/log_slow.test | 40 | ||||
-rw-r--r-- | sql/log_event.cc | 2 | ||||
-rw-r--r-- | sql/sql_admin.cc | 5 | ||||
-rw-r--r-- | sql/sql_admin.h | 8 | ||||
-rw-r--r-- | sql/sql_alter.cc | 4 | ||||
-rw-r--r-- | sql/sql_alter.h | 2 | ||||
-rw-r--r-- | sql/sql_cmd.h | 15 | ||||
-rw-r--r-- | sql/sql_lex.cc | 14 | ||||
-rw-r--r-- | sql/sql_parse.cc | 62 | ||||
-rw-r--r-- | sql/sql_partition_admin.cc | 1 |
11 files changed, 161 insertions, 29 deletions
diff --git a/mysql-test/r/log_slow.result b/mysql-test/r/log_slow.result index 02e04cfbb2d..c50130a7b7a 100644 --- a/mysql-test/r/log_slow.result +++ b/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; diff --git a/mysql-test/t/log_slow.test b/mysql-test/t/log_slow.test index 56e35bd5a20..edb1865b5ae 100644 --- a/mysql-test/t/log_slow.test +++ b/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; diff --git a/sql/log_event.cc b/sql/log_event.cc index 1b372778b88..bb373a4ed84 100644 --- a/sql/log_event.cc +++ b/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(); diff --git a/sql/sql_admin.cc b/sql/sql_admin.cc index b8881f8f108..cbc9780d507 100644 --- a/sql/sql_admin.cc +++ b/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, diff --git a/sql/sql_admin.h b/sql/sql_admin.h index 96594fad0cb..ce7308434c5 100644 --- a/sql/sql_admin.h +++ b/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: /** diff --git a/sql/sql_alter.cc b/sql/sql_alter.cc index 758489ddcfb..243cf4c790f 100644 --- a/sql/sql_alter.cc +++ b/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 diff --git a/sql/sql_alter.h b/sql/sql_alter.h index a4505f1d6c1..74dd8b0e5d8 100644 --- a/sql/sql_alter.h +++ b/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: /** diff --git a/sql/sql_cmd.h b/sql/sql_cmd.h index 904578134b4..9cb2a728f41 100644 --- a/sql/sql_cmd.h +++ b/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 diff --git a/sql/sql_lex.cc b/sql/sql_lex.cc index c5aaa8e3cca..7c330151545 100644 --- a/sql/sql_lex.cc +++ b/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]; diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc index 3f6ce8356ce..b6ad9fa2be3 100644 --- a/sql/sql_parse.cc +++ b/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,13 +2054,18 @@ 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). + + Note, we don't check for global_system_variables.sql_log_slow here. + According to the manual, the "Slow_queries" status variable does not require + sql_log_slow to be ON. So even if sql_log_slow is OFF, we still need to + continue and increment long_query_count (and skip only logging, see below): + */ + if (!thd->enable_slow_log) + goto end; // E.g. SP statement - /* Follow the slow log filter configuration. */ - if (!thd->enable_slow_log || !global_system_variables.sql_log_slow || - (thd->variables.log_slow_filter - && !(thd->variables.log_slow_filter & thd->query_plan_flags))) - goto end; - if (((thd->server_status & SERVER_QUERY_WAS_SLOW) || ((thd->server_status & (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) && @@ -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)); diff --git a/sql/sql_partition_admin.cc b/sql/sql_partition_admin.cc index 1ac9e748d42..d2fdee934ce 100644 --- a/sql/sql_partition_admin.cc +++ b/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)); } |