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

    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

            Activity

              People

              • Assignee:
                marko Marko Mäkelä
                Reporter:
                elenst Elena Stepanova
              • Votes:
                0 Vote for this issue
                Watchers:
                7 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: