Percona Server moved to https://jira.percona.com/projects/PS

percona_slow_query_log_rate fails sporadically

Bug #1497942 reported by Yura Sorokin
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
Percona Server moved to https://jira.percona.com/projects/PS 5.6.27-75.0
5.5
Fix Released
Low
Yura Sorokin
Percona Server moved to https://jira.percona.com/projects/PS 5.5.46-37.5
5.6
Fix Released
Low
Yura Sorokin
Percona Server moved to https://jira.percona.com/projects/PS 5.6.27-75.0

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
------------

Revision history for this message
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).

Revision history for this message
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

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.