Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-4393

show_explain.test times out randomly

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Fixed
    • 10.0.2, 10.0.9
    • 10.0.16
    • Tests
    • None

    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

      Attachments

        Issue Links

          Activity

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

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

            psergei Sergei Petrunia added a comment - Created a branch http://buildbot.askmonty.org/buildbot/grid?branch=10.0-show-explain made a number of pushes. Unable to repeat the problem.

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

            • bld-dan-debug
            • kvm-dgcov-jaunty-i386
            • win32-debug2
            • work-amd64-valgrind
            psergei Sergei Petrunia added a comment - Buildbot hosts on which the problem could be observed in 2013: bld-dan-debug kvm-dgcov-jaunty-i386 win32-debug2 work-amd64-valgrind

            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.

            psergei Sergei Petrunia added a comment - 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.

            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

            elenst Elena Stepanova added a comment - 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
            elenst Elena Stepanova added a comment - Fresh one: http://buildbot.askmonty.org/buildbot/builders/kvm-dgcov-jaunty-i386/builds/4448/steps/test_3/logs/stdio

            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.

            knielsen Kristian Nielsen added a comment - 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.
            knielsen Kristian Nielsen added a comment - Pushed to 10.0.16: http://lists.askmonty.org/pipermail/commits/2014-December/007148.html

            People

              knielsen Kristian Nielsen
              psergei Sergei Petrunia
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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