[MDEV-7352] main.kill_processlist-6619 fails sporadically in buildbot - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Minor
Resolution: Fixed
Affects Version/s: 10.0(EOL)
Fix Version/s: 10.0.16
Component/s: Tests
Labels:
- buildbot
- tests

Description

http://buildbot.askmonty.org/buildbot/builders/kvm-deb-trusty-x86/builds/635/steps/test_4/logs/stdio

main.kill_processlist-6619               w4 [ fail ]

        Test ended at 2014-12-19 09:24:08

CURRENT_TEST: main.kill_processlist-6619

--- /usr/share/mysql/mysql-test/r/kill_processlist-6619.result	2014-12-19 07:30:49.000000000 +0000

+++ /run/shm/var/4/log/kill_processlist-6619.reject	2014-12-19 09:24:08.017590004 +0000

@@ -10,5 +10,5 @@

 ERROR 70100: Query execution was interrupted

 SHOW PROCESSLIST;

 Id	User	Host	db	Command	Time	State	Info	Progress

-#	root	#	test	Sleep	#	#	NULL	0.000

+#	root	#	test	Query	#	#	KILL QUERY 1638	0.000

 #	root	#	test	Query	#	#	SHOW PROCESSLIST	0.000

mysqltest: Result length mismatch

Happened twice in a few months, so it's very rare.

Attachments

Issue Links

relates to

MDEV-7069 Fix buildbot failures in main server trees

Closed

Activity

Ascending order - Click to sort in descending order

Elena Stepanova created issue - 2014-12-19 19:35

Elena Stepanova made changes - 2014-12-19 19:35

Field	Original Value	New Value
Link		This issue relates to ~~MDEV-7069~~ [ ~~MDEV-7069~~ ]

Kristian Nielsen added a comment - 2015-01-23 14:41

This patch makes the failure easy to reproduce:

=== modified file 'mysql-test/r/kill_processlist-6619.result'

--- mysql-test/r/kill_processlist-6619.result	2015-01-19 13:07:41 +0000

+++ mysql-test/r/kill_processlist-6619.result	2015-01-23 12:23:34 +0000

@@ -3,6 +3,8 @@ SHOW PROCESSLIST;

 Id	User	Host	db	Command	Time	State	Info	Progress

 #	root	#	test	Sleep	#	#	NULL	0.000

 #	root	#	test	Query	#	#	SHOW PROCESSLIST	0.000

+SET @old_dbug= @@debug_dbug;

+SET debug_dbug="+d,inject_knielsen";

 SET DEBUG_SYNC='before_execute_sql_command WAIT_FOR go';

 SHOW PROCESSLIST;

 connection default;

@@ -10,6 +12,8 @@ KILL QUERY con_id;

 SET DEBUG_SYNC='now SIGNAL go';

 connection con1;

 ERROR 70100: Query execution was interrupted

+SET debug_dbug= @old_dbug;

+SET DEBUG_SYNC='reset';

 SHOW PROCESSLIST;

 Id	User	Host	db	Command	Time	State	Info	Progress

 #	root	#	test	Sleep	#	#	NULL	0.000

=== modified file 'mysql-test/t/kill_processlist-6619.test'

--- mysql-test/t/kill_processlist-6619.test	2015-01-19 13:07:41 +0000

+++ mysql-test/t/kill_processlist-6619.test	2015-01-23 12:23:02 +0000

@@ -9,6 +9,8 @@

 --let $con_id = `SELECT CONNECTION_ID()`

 --replace_column 1 # 3 # 6 # 7 #

 SHOW PROCESSLIST;

+SET @old_dbug= @@debug_dbug;

+SET debug_dbug="+d,inject_knielsen";

 SET DEBUG_SYNC='before_execute_sql_command WAIT_FOR go';

 send SHOW PROCESSLIST;

 --connection default

@@ -18,5 +20,7 @@ SET DEBUG_SYNC='now SIGNAL go';

 --connection con1

 --error ER_QUERY_INTERRUPTED

 reap;

+SET debug_dbug= @old_dbug;

+SET DEBUG_SYNC='reset';

 --replace_column 1 # 3 # 6 # 7 #

 SHOW PROCESSLIST;

=== modified file 'sql/sql_parse.cc'

--- sql/sql_parse.cc	2015-01-21 11:03:02 +0000

+++ sql/sql_parse.cc	2015-01-23 12:35:39 +0000

@@ -1124,6 +1124,7 @@ bool dispatch_command(enum enum_server_c

   thd->enable_slow_log= TRUE;

   thd->query_plan_flags= QPLAN_INIT;

   thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */

+DBUG_EXECUTE_IF("inject_knielsen", my_sleep(50000););

   thd->reset_kill_query();

   DEBUG_SYNC(thd,"dispatch_command_before_set_time");

So it seems that the problem happens when the connection con1 is delayed for
some reason. Then the KILL sent by the default connection is reset at the
start of the SHOW PROCESSLIST query.

Kristian Nielsen added a comment - 2015-01-23 14:41 This patch makes the failure easy to reproduce: === modified file 'mysql-test/r/kill_processlist-6619.result' --- mysql-test/r/kill_processlist-6619.result 2015-01-19 13:07:41 +0000 +++ mysql-test/r/kill_processlist-6619.result 2015-01-23 12:23:34 +0000 @@ -3,6 +3,8 @@ SHOW PROCESSLIST; Id User Host db Command Time State Info Progress # root # test Sleep # # NULL 0.000 # root # test Query # # SHOW PROCESSLIST 0.000 +SET @old_dbug= @@debug_dbug; +SET debug_dbug="+d,inject_knielsen"; SET DEBUG_SYNC='before_execute_sql_command WAIT_FOR go'; SHOW PROCESSLIST; connection default; @@ -10,6 +12,8 @@ KILL QUERY con_id; SET DEBUG_SYNC='now SIGNAL go'; connection con1; ERROR 70100: Query execution was interrupted +SET debug_dbug= @old_dbug; +SET DEBUG_SYNC='reset'; SHOW PROCESSLIST; Id User Host db Command Time State Info Progress # root # test Sleep # # NULL 0.000 === modified file 'mysql-test/t/kill_processlist-6619.test' --- mysql-test/t/kill_processlist-6619.test 2015-01-19 13:07:41 +0000 +++ mysql-test/t/kill_processlist-6619.test 2015-01-23 12:23:02 +0000 @@ -9,6 +9,8 @@ --let $con_id = `SELECT CONNECTION_ID()` --replace_column 1 # 3 # 6 # 7 # SHOW PROCESSLIST; +SET @old_dbug= @@debug_dbug; +SET debug_dbug="+d,inject_knielsen"; SET DEBUG_SYNC='before_execute_sql_command WAIT_FOR go'; send SHOW PROCESSLIST; --connection default @@ -18,5 +20,7 @@ SET DEBUG_SYNC='now SIGNAL go'; --connection con1 --error ER_QUERY_INTERRUPTED reap; +SET debug_dbug= @old_dbug; +SET DEBUG_SYNC='reset'; --replace_column 1 # 3 # 6 # 7 # SHOW PROCESSLIST; === modified file 'sql/sql_parse.cc' --- sql/sql_parse.cc 2015-01-21 11:03:02 +0000 +++ sql/sql_parse.cc 2015-01-23 12:35:39 +0000 @@ -1124,6 +1124,7 @@ bool dispatch_command(enum enum_server_c thd->enable_slow_log= TRUE; thd->query_plan_flags= QPLAN_INIT; thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */ +DBUG_EXECUTE_IF("inject_knielsen", my_sleep(50000);); thd->reset_kill_query(); DEBUG_SYNC(thd,"dispatch_command_before_set_time"); So it seems that the problem happens when the connection con1 is delayed for some reason. Then the KILL sent by the default connection is reset at the start of the SHOW PROCESSLIST query.

Kristian Nielsen made changes - 2015-01-23 14:41

Assignee

Elena Stepanova [ elenst ]

Kristian Nielsen [ knielsen ]

Kristian Nielsen made changes - 2015-01-23 14:41

Status

Open [ 1 ]

In Progress [ 3 ]

Kristian Nielsen added a comment - 2015-01-23 14:59

http://lists.askmonty.org/pipermail/commits/2015-January/007323.html

Kristian Nielsen added a comment - 2015-01-23 14:59 http://lists.askmonty.org/pipermail/commits/2015-January/007323.html

Kristian Nielsen made changes - 2015-01-23 14:59

Fix Version/s		10.0.16 [ 17900 ]
Fix Version/s	10.0 [ 16000 ]
Resolution		Fixed [ 1 ]
Status	In Progress [ 3 ]	Closed [ 6 ]

Rasmus Johansson (Inactive) made changes - 2015-05-18 17:51

Workflow

MariaDB v2 [ 59041 ]

MariaDB v3 [ 65524 ]

Sergei Golubchik made changes - 2021-12-06 21:40

Workflow

MariaDB v3 [ 65524 ]

MariaDB v4 [ 148644 ]

People

Assignee:: Kristian Nielsen

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 2014-12-19 19:35

Updated:: 2015-01-23 14:59

Resolved:: 2015-01-23 14:59

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server