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

InnoDB hangs on startup between "InnoDB: Apply batch completed" and "rollback segment(s) are active", various tests fail sporadically in buildbot on p8-rhel6-bintar-debug

    XMLWordPrintable

Details

    Description

      There are multiple failures in different tests in buildbot which seem to have the common cause. A test runs with InnoDB or XtraDB; at some point as a part of the test flow it sigkills the server; the server gets restarted; InnoDB recovery starts; it goes like this:

      Version: '10.1.13-MariaDB-debug'  socket: '/home/buildbot/maria-slave/power8-vlp01-bintar-debug/build/mysql-test/var/tmp/4/mysqld.1.sock'  port: 16020  Source distribution
      		 
      SIGKILL myself
      		 
      2016-03-30 11:51:13 17590032101456 [Note] /home/buildbot/maria-slave/power8-vlp01-bintar-debug/build/sql/mysqld (mysqld 10.1.13-MariaDB-debug) starting as process 20770 ...
      		 
      2016-03-30 11:51:13 17590032101456 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
      		 
      2016-03-30 11:51:13 17590032101456 [Note] Plugin 'SEQUENCE' is disabled.
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Using mutexes to ref count buffer pool pages
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: The InnoDB memory heap is disabled
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Compressed tables use zlib 1.2.6
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Using Linux native AIO
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Using generic crc32 instructions
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Initializing buffer pool, size = 32.0M
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Highest supported file format is Barracuda.
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Log scan progressed past the checkpoint lsn 2963393
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Database was not shutdown normally!
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Starting crash recovery.
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Reading tablespace information from the .ibd files...
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Restoring possible half-written data pages 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: from the doublewrite buffer...
      		 
      InnoDB: Doing recovery: scanned up to log sequence number 2977463
      		 
      2016-03-30 11:51:14 17590032101456 [Note] InnoDB: Starting an apply batch of log records to the database...
      		 
      InnoDB: Progress in percent: 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
      InnoDB: Apply batch completed

      and nothing further. The test waits until timeout is exceeded and reports

      ...
      		 
      mysqltest: In included file "./include/wait_until_connected_again.inc": 
      included from ./include/rpl_reconnect.inc at line 93:
      		 
      included from ./include/rpl_start_server.inc at line 57:
      		 
      included from /home/buildbot/maria-slave/power8-vlp01-bintar-debug/build/mysql-test/suite/rpl/t/rpl_domain_id_filter_master_crash.test at line 70:
      		 
      At line 26: Server failed to restart

      Here is the cross-reference report which selects such failures (some of them might be of a different nature, but most of them are related):
      cross-reference report
      (be patient, it will take long to load)

      Recent example:
      http://buildbot.askmonty.org/buildbot/builders/p8-rhel6-bintar-debug/builds/1436/steps/test/logs/mysqld.1.err.4
      (search for 2016-03-30 11:51:13 17590032101456, that's where the failed server startup begins)
      In this case it is parts.partition_debug_innodb test running on 10.1 of March 30. If you scroll the log back from the failing point, you'll see that the test does recovery many times, and only one of them failed.

      According to the cross-reference report, the test failures are currently only observed on p8-rhel6-bintar-debug.

      Here is an example of a similar problem, but without recovery:
      http://buildbot.askmonty.org/buildbot/builders/p8-rhel6-bintar-debug/builds/1445/steps/test/logs/mysqld.2.err.1
      Test rpl.rpl_unsafe_statements

      CURRENT_TEST: rpl.rpl_unsafe_statements
      		 
      2016-04-01 18:05:42 17590418370640 [Note] /home/buildbot/maria-slave/power8-vlp01-bintar-debug/build/sql/mysqld (mysqld 10.2.0-MariaDB-debug) starting as process 17484 ...
      		 
      2016-04-01 18:05:42 17590418370640 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
      		 
      2016-04-01 18:05:42 17590418370640 [Note] Plugin 'partition' is disabled.
      		 
      2016-04-01 18:05:42 17590418370640 [Note] Plugin 'SEQUENCE' is disabled.
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB: Using mutexes to ref count buffer pool pages
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB: The InnoDB memory heap is disabled
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB: Compressed tables use zlib 1.2.6
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB: Using Linux native AIO
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB: Using generic crc32 instructions
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB: Initializing buffer pool, size = 8.0M
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2016-04-01 18:05:42 17590418370640 [Note] InnoDB: Highest supported file format is Barracuda.
      		 
      CURRENT_TEST: rpl.rpl_loaddata_s
      		 
      2016-04-01 18:08:45 17590534631504 [Note] /home/buildbot/maria-slave/power8-vlp01-bintar-debug/build/sql/mysqld (mysqld 10.2.0-MariaDB-debug) starting as process 23021 ...

      Attachments

        Issue Links

          blocks

          Task - A task that needs to be done. MDEV-7069 Fix buildbot failures in main server trees

          • Major - Major loss of function.
          • Stalled

          Task - A task that needs to be done. MDEV-14481 Execute InnoDB crash recovery in the background

          • Major - Major loss of function.
          • Closed
          relates to

          Task - A task that needs to be done. MDEV-11499 mysqltest, Windows : improve diagnostics if server fails to shutdown

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-13485 MTR tests fail massively with --innodb-sync-debug

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-15333 MariaDB (still) slow start

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-13869 MariaDB slow start

          • Major - Major loss of function.
          • Closed

          Activity

            People

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