[MDEV-4393] show_explain.test times out randomly Created: 2013-04-13  Updated: 2014-12-03  Resolved: 2014-12-03

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.0.2, 10.0.9
Fix Version/s: 10.0.16

Type: Bug Priority: Major
Reporter: Sergei Petrunia Assignee: Kristian Nielsen
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-3982 show_explain.test fails, times out or... Closed
relates to MDEV-7069 Fix buildbot failures in main server ... Stalled

 Description   

main.show_explain 'innodb_plugin'        w1 [ fail ]  timeout after 2700 seconds
        Test ended at 2013-04-10 17:39:24
 
Test case timeout after 2700 seconds
 
== /dev/shm/var_auto_EmqH/1/log/show_explain.log == 
Warnings:
Note	1003	select count(*) from t1 A, t1 B where B.key1 < A.col2 and A.col1=3 AND B.col2 + 1 < 100
show explain for $thr2;
id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
1	SIMPLE	A	ALL	NULL	NULL	NULL	NULL	100	Using where
1	SIMPLE	B	ALL	key1	NULL	NULL	NULL	100	Range checked for each record (index map: 0x1)
Warnings:
Note	1003	select count(*) from t1 A, t1 B where B.key1 < A.col2 and A.col1=3 AND B.col2 + 1 < 100
show explain for $thr2;
id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
1	SIMPLE	A	ALL	NULL	NULL	NULL	NULL	100	Using where
1	SIMPLE	B	ALL	key1	NULL	NULL	NULL	100	Range checked for each record (index map: 0x1)
Warnings:
Note	1003	select count(*) from t1 A, t1 B where B.key1 < A.col2 and A.col1=3 AND B.col2 + 1 < 100
show explain for $thr2;
id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
1	SIMPLE	A	ALL	NULL	NULL	NULL	NULL	100	Using where
1	SIMPLE	B	ALL	key1	NULL	NULL	NULL	100	Range checked for each record (index map: 0x1)
Warnings:
Note	1003	select count(*) from t1 A, t1 B where B.key1 < A.col2 and A.col1=3 AND B.col2 + 1 < 100
 
 == /dev/shm/var_auto_EmqH/1/tmp/analyze-timeout-mysqld.1.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/dev/shm/var_auto_EmqH/tmp/1/mysqld.1.sock' (111 "Connection refused")
 
 
 - saving '/dev/shm/var_auto_EmqH/1/log/main.show_explain-innodb_plugin/' to '/dev/shm/var_auto_EmqH/log/main.show_explain-innodb_plugin/'
 
Retrying test main.show_explain, attempt(2/3)...
 
***Warnings generated in error logs during shutdown after running tests: main.events_trans main.auto_increment_ranges_innodb main.alter_table_trans main.func_rollback main.foreign_key main.func_analyse main.endspace main.parser_bug21114_innodb main.range_vs_index_merge_innodb main.consistent_snapshot main.innodb_ext_key main.cache_innodb main.range main.plugin_innodb main.loaddata_autocom_innodb main.mysqlcheck innodb.innodb_prefix_index_restart_server main.group_min_max_innodb main.information_schema_inno main.row-checksum main.innodb_bug878769 main.index_intersect_innodb main.innodb_icp innodb.innodb_trx_weight main.deadlock_innodb main.flush_block_commit main.read_only_innodb main.function_defaults main.flush-innodb main.innodb_utf8 main.alter_table_online main.multi_update_innodb main.flush_read_lock main.innodb_mrr_cpk main.group_by_innodb main.lowercase_table2 main.innodb_mysql_sync main.flush_read_lock_kill main.merge_innodb main.commit main.range_mrr_icp innodb.mdev-117 main.events_trans_notembedded main.func_group_innodb main.show_explain main.join_outer_innodb main.group_by
 
Attempting backtrace. You can use the following information to find out
 
main.show_explain 'innodb_plugin'        w1 [ retry-pass ]   4999



 Comments   
Comment by Sergei Petrunia [ 2013-05-20 ]

Created a branch http://buildbot.askmonty.org/buildbot/grid?branch=10.0-show-explain

made a number of pushes. Unable to repeat the problem.

Comment by Sergei Petrunia [ 2013-05-20 ]

Buildbot hosts on which the problem could be observed in 2013:

  • bld-dan-debug
  • kvm-dgcov-jaunty-i386
  • win32-debug2
  • work-amd64-valgrind
Comment by Sergei Petrunia [ 2013-05-20 ]

10.0-show-explain is a "second-class" tree in buildbot, not all builders build it.

However, builders mentioned in the previous comment do build it, and had no show_explain.test failures so far.

Comment by Elena Stepanova [ 2014-03-26 ]

Still happens on 10.0 tree.
Buildbot, revno 4081:
http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/1934/steps/test_6/logs/stdio

Test case timeout after 900 seconds
 
== /run/shm/var_auto_kSzH/1/log/show_explain.log == 
set debug_dbug='+d,show_explain_probe_join_exec_start';
select t2.a, ((select max(a) from t0 where t2.a + t0.a <3) >3) as SUBQ from t2;
show explain for $thr2;
id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
1	PRIMARY	t2	ALL	NULL	NULL	NULL	NULL	3	
2	DEPENDENT SUBQUERY	t0	ALL	NULL	NULL	NULL	NULL	10	Using where
Warnings:
Note	1003	select t2.a, ((select max(a) from t0 where t2.a + t0.a <3) >3) as SUBQ from t2
show explain for $thr2;
id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
1	PRIMARY	t2	ALL	NULL	NULL	NULL	NULL	3	
2	DEPENDENT SUBQUERY	t0	ALL	NULL	NULL	NULL	NULL	10	Using where
Warnings:
Note	1003	select t2.a, ((select max(a) from t0 where t2.a + t0.a <3) >3) as SUBQ from t2
show explain for $thr2;
id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
1	PRIMARY	t2	ALL	NULL	NULL	NULL	NULL	3	
2	DEPENDENT SUBQUERY	t0	ALL	NULL	NULL	NULL	NULL	10	Using where
Warnings:
Note	1003	select t2.a, ((select max(a) from t0 where t2.a + t0.a <3) >3) as SUBQ from t2

I also got a timeout on a local machine by executing
perl ./mtr main.show_explain --repeat=100

Comment by Elena Stepanova [ 2014-11-19 ]

Fresh one: http://buildbot.askmonty.org/buildbot/builders/kvm-dgcov-jaunty-i386/builds/4448/steps/test_3/logs/stdio

Comment by Kristian Nielsen [ 2014-12-03 ]

The test case can be easily reproduced with this patch:

=== modified file 'sql/sql_select.cc'
--- sql/sql_select.cc	2014-11-03 16:47:37 +0000
+++ sql/sql_select.cc	2014-12-03 13:16:42 +0000
@@ -302,6 +302,7 @@ void dbug_serve_apcs(THD *thd, int n_cal
     if (thd->check_killed())
       break;
   }
+my_sleep(400000);
   thd_proc_info(thd, save_proc_info);
 }
 
 

I guess there is a race, where the test case can run ahead and send a second
SHOW EXPLAIN FOR before the query has time to set back the thd_proc_info.

Comment by Kristian Nielsen [ 2014-12-03 ]

Pushed to 10.0.16:

http://lists.askmonty.org/pipermail/commits/2014-December/007148.html

Generated at Thu Feb 08 06:56:05 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.