percona_slow_query_log_rate fails sporadically

Bug #1497942 reported by Yura Sorokin on 2015-09-21
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
Low
Yura Sorokin
5.5
Fix Released
Low
Yura Sorokin
5.6
Fix Released
Low
Yura Sorokin

Bug Description

percona_slow_query_log_rate fails sporadically in Jenkins both on 5.5 and 5.6

_StringException: Text attachment: traceback
------------
Comment:

Logfile:
CURRENT_TEST: main.percona_slow_query_log_rate
--- /mnt/workspace/percona-server-5.5-param/BUILD_TYPE/debug/Host/ubuntu-trusty-64bit/mysql-test/r/percona_slow_query_log_rate.result 2015-09-17 09:58:45.800584524 +0300
+++ /mnt/workspace/percona-server-5.5-param/BUILD_TYPE/debug/Host/ubuntu-trusty-64bit/mysql-test/r/percona_slow_query_log_rate.reject 2015-09-17 10:49:48.453922438 +0300
@@ -24,7 +24,7 @@
 connection_three
 [log_stop.inc] percona.slow_extended.log_slow_rate_limit_1
 [log_grep.inc] file: percona.slow_extended.log_slow_rate_limit_1 pattern:
-[log_grep.inc] sum: 2
+[log_grep.inc] sum: 1
 [log_grep.inc] zero: 2
 SET GLOBAL debug="+d,seed_slow_log_random";
 SET GLOBAL log_slow_rate_type='query';

mysqltest: Result content mismatch
------------

Yura Sorokin (yura-sorokin) wrote :

The problem turned out to be with disabling slow query log from one connection while other ones executing "SELECT 'something_xxx'", although already sent the result back to the client, have not written these statements to the slog
yet.

In other words, when the thread executing "SELECT 'connection_xxx'" pauses somewhere in "dispatch_command()" (sql_parse.cc) after "thd->protocol->end_statement()" but before "log_slow_statement()", the other thread executes "SET GLOBAL slow_query_log=0" and therefore closes slow query log file. When the first thread resumes, and executes "log_slow_statement()", nothing happens as the slow query log file is already closed.

The fix could be in executing one dummy statement in each "SELECT" connection after the while loop to make sure that these statements are 100% processed (including writing to the slow query log).

Yura Sorokin (yura-sorokin) wrote :

It turned out that

--disconnect connection_one
--disconnect connection_two
--disconnect connection_three

followed by

--source include/wait_until_count_sessions.inc

can serve as the dummy statements from the previous comment.

Therefore, all we need to do to fix this test is to make sure that slow query log is disabled after closing connections
--disconnect connection_one
--disconnect connection_two
--disconnect connection_three
--source include/wait_until_count_sessions.inc
--source include/log_stop.inc

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

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers