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

innodb.undo_truncate_recover failed in buildbot with MySQL server has gone away on SHOW VARIABLES

Details

    Description

      http://buildbot.askmonty.org/buildbot/builders/win32-debug/builds/10757

      innodb.undo_truncate_recover '16k,2,innodb' w2 [ fail ]
              Test ended at 2018-10-11 20:49:09
       
      CURRENT_TEST: innodb.undo_truncate_recover
      mysqltest: In included file "./include/shutdown_mysqld.inc": 
      included from D:/win32-debug/build/src/mysql-test/suite/innodb/t/undo_truncate_recover.test at line 45:
      At line 40: 'SHOW VARIABLES LIKE 'pid_file'' failed: 2006 MySQL server has gone away
       
      The result from queries just before the failure was:
      SET GLOBAL innodb_undo_logs = 4;
      SET GLOBAL innodb_undo_log_truncate = 1;
      SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;
      create table t1(keyc int primary key, c char(100)) engine = innodb;
      begin;
      commit;
      begin;
      update t1 set c = 'MariaDB';
      update t1 set c = 'InnoDB';
      set global debug_dbug = '+d,ib_undo_trunc';
      commit;
      call mtr.add_suppression("InnoDB: The transaction log size is too large");
      SET GLOBAL innodb_fast_shutdown=0;
      

      Attachments

        Issue Links

          Activity

            As far as I can tell, the statement ought to be part of the following in shutdown_mysqld.inc:

            --shutdown_server $server_shutdown_timeout
            

            void do_shutdown_server(struct st_command *command)
            {
              if (query_get_string(mysql, "SHOW VARIABLES LIKE 'pid_file'", 1,
                                   &ds_pidfile_name))
                die("Failed to get pid_file from server");
            

            Apparently, the server was killed due to some reason while the shutdown as about to be initiated. Here is an excerpt from the server error log:

            10.2 81a5b6ccd531e802bbb0f2034189095d2196de8b

            Version: '10.2.19-MariaDB-debug-log'  socket: ''  port: 16020  Source distribution
            2018-10-11 20:48:58 2080 [Note] InnoDB: Truncating UNDO tablespace 1
            2018-10-11 20:48:59 2080 [Warning] InnoDB: The transaction log size is too large for innodb_log_buffer_size (1389258 >= 1048576 / 2). Trying to extend it.
            2018-10-11 20:48:59 2080 [Note] InnoDB: innodb_log_buffer_size was extended to 1392640.
            2018-10-11 20:48:59 2080 [Note] InnoDB: ib_undo_trunc
            CURRENT_TEST: innodb.undo_truncate_recover
            

            The last message is a suicide note from trx_purge_initiate_truncate():

            	DBUG_EXECUTE_IF("ib_undo_trunc",
            			ib::info() << "ib_undo_trunc";
            			log_write_up_to(LSN_MAX, true);
            			DBUG_SUICIDE(););
            

            This looks like a race condition in the test.
            We do expect the server to commit suicide during the slow shutdown, but not already during the initial step of shutdown_server.

            marko Marko Mäkelä added a comment - As far as I can tell, the statement ought to be part of the following in shutdown_mysqld.inc : --shutdown_server $server_shutdown_timeout void do_shutdown_server( struct st_command *command) { … if (query_get_string(mysql, "SHOW VARIABLES LIKE 'pid_file'" , 1, &ds_pidfile_name)) die( "Failed to get pid_file from server" ); Apparently, the server was killed due to some reason while the shutdown as about to be initiated. Here is an excerpt from the server error log : 10.2 81a5b6ccd531e802bbb0f2034189095d2196de8b Version: '10.2.19-MariaDB-debug-log' socket: '' port: 16020 Source distribution 2018-10-11 20:48:58 2080 [Note] InnoDB: Truncating UNDO tablespace 1 2018-10-11 20:48:59 2080 [Warning] InnoDB: The transaction log size is too large for innodb_log_buffer_size (1389258 >= 1048576 / 2). Trying to extend it. 2018-10-11 20:48:59 2080 [Note] InnoDB: innodb_log_buffer_size was extended to 1392640. 2018-10-11 20:48:59 2080 [Note] InnoDB: ib_undo_trunc CURRENT_TEST: innodb.undo_truncate_recover The last message is a suicide note from trx_purge_initiate_truncate() : DBUG_EXECUTE_IF( "ib_undo_trunc" , ib::info() << "ib_undo_trunc" ; log_write_up_to(LSN_MAX, true ); DBUG_SUICIDE();); This looks like a race condition in the test. We do expect the server to commit suicide during the slow shutdown, but not already during the initial step of shutdown_server .

            Last occurrence:

            10.2 acb4a872049e0ac23a1fdf7a1aaf12ed

            innodb.undo_truncate_recover '16k,2,innodb' w4 [ fail ]
                    Test ended at 2019-03-11 22:29:32
             
            CURRENT_TEST: innodb.undo_truncate_recover
            mysqltest: In included file "./include/shutdown_mysqld.inc": 
            included from D:/winx64-debug/build/src/mysql-test/suite/innodb/t/undo_truncate_recover.test at line 46:
            At line 40: 'SHOW VARIABLES LIKE 'pid_file'' failed: 2006 MySQL server has gone away
            

            marko Marko Mäkelä added a comment - Last occurrence: 10.2 acb4a872049e0ac23a1fdf7a1aaf12ed innodb.undo_truncate_recover '16k,2,innodb' w4 [ fail ] Test ended at 2019-03-11 22:29:32   CURRENT_TEST: innodb.undo_truncate_recover mysqltest: In included file "./include/shutdown_mysqld.inc": included from D:/winx64-debug/build/src/mysql-test/suite/innodb/t/undo_truncate_recover.test at line 46: At line 40: 'SHOW VARIABLES LIKE 'pid_file'' failed: 2006 MySQL server has gone away

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 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.