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

Various issues when using --innodb-data-file-size-debug=-1 | SIGABRT in fil_mutex_enter_and_prepare_for_io




      Trivial debug-only issue it seems, but with varied outcomes.

      # mysqld options required for replay:  --innodb-data-file-size-debug=-1   # or other larger negative values

      Leads to (on debug):

      10.5.3 64488a6f2dd6aa43462292b757e783cfba11a8c6

      2020-05-08  7:40:53 0 [Note] InnoDB: Completed initialization of buffer pool
      2020-05-08  7:40:53 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2020-05-08  7:40:53 0 [Note] InnoDB: Header page consists of zero bytes in datafile: ./ibdata1, Space ID:0, Flags: 0
      2020-05-08  7:40:53 0 [ERROR] InnoDB: Corrupted page [page id: space=0, page number=0] of datafile './ibdata1' could not be found in the doublewrite buffer.
      2020-05-08  7:40:53 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1382] with error Data structure corruption
      2020-05-08  7:40:53 0 [Note] InnoDB: Starting shutdown...
      2020-05-08  7:40:54 0 [ERROR] Plugin 'InnoDB' init function returned error.
      2020-05-08  7:40:54 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
      2020-05-08  7:40:54 0 [Note] Plugin 'FEEDBACK' is disabled.
      2020-05-08  7:40:54 0 [ERROR] Could not open mysql.plugin table: "Table 'mysql.plugin' doesn't exist". Some plugins may be not loaded
      2020-05-08  7:40:54 0 [ERROR] Unknown/unsupported storage engine: InnoDB
      2020-05-08  7:40:54 0 [ERROR] Aborting

      10.5.3 64488a6f2dd6aa43462292b757e783cfba11a8c6

      Core was generated by `/test/MD050520-mariadb-10.5.3-linux-x86_64-dbg/bin/mysqld --no-defaults --lc-me'.
      Program terminated with signal SIGABRT, Aborted.
      #0  0x000015113e1f2187 in kill () at ../sysdeps/unix/syscall-template.S:78
      78	../sysdeps/unix/syscall-template.S: No such file or directory.
      [Current thread is 1 (Thread 0x15113fb7c7c0 (LWP 204096))]
      (gdb) bt
      #0  0x000015113e1f2187 in kill () at ../sysdeps/unix/syscall-template.S:78
      #1  0x00005571eb3fffee in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:341
      #2  <signal handler called>
      #3  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
      #4  0x000015113e1f3801 in __GI_abort () at abort.c:79
      #5  0x00005571eba182aa in ut_dbg_assertion_failed (expr=expr@entry=0x5571ec3e1951 "success", 
          file=file@entry=0x5571ec112130 "/test/10.5_dbg/storage/innobase/fil/fil0fil.cc", 
          line=line@entry=940) at /test/10.5_dbg/storage/innobase/ut/ut0dbg.cc:60
      #6  0x00005571ebb339e5 in fil_mutex_enter_and_prepare_for_io (space_id=space_id@entry=0)
          at /test/10.5_dbg/storage/innobase/fil/fil0fil.cc:940
      #7  0x00005571ebb3698c in fil_io (type=..., sync=sync@entry=false, page_id=..., zip_size=0, 
          byte_offset=byte_offset@entry=0, len=16384, buf=0x151123850000, message=0x151123400238, 
          ignore=false, punch_hole=false) at /test/10.5_dbg/storage/innobase/fil/fil0fil.cc:3956
      #8  0x00005571ebaafa83 in buf_flush_write_block_low (sync=false, flush_type=BUF_FLUSH_LIST, 
          bpage=0x151123400238) at /test/10.5_dbg/storage/innobase/buf/buf0flu.cc:1190
      #9  buf_flush_page (bpage=bpage@entry=0x151123400238, flush_type=flush_type@entry=BUF_FLUSH_LIST, 
          sync=sync@entry=false) at /test/10.5_dbg/storage/innobase/buf/buf0flu.cc:1325
      #10 0x00005571ebab0837 in buf_flush_try_neighbors (n_to_flush=18446744073709551614, n_flushed=0, 
          flush_type=BUF_FLUSH_LIST, page_id=...) at /test/10.5_dbg/storage/innobase/buf/buf0flu.cc:1535
      #11 buf_flush_page_and_try_neighbors (bpage=bpage@entry=0x151123400238, 
          flush_type=flush_type@entry=BUF_FLUSH_LIST, n_to_flush=n_to_flush@entry=18446744073709551614, 
          count=count@entry=0x7ffe0a3ac948) at /test/10.5_dbg/storage/innobase/buf/buf0flu.cc:1598
      #12 0x00005571ebab2c6e in buf_do_flush_list_batch (lsn_limit=18446744073709551615, 
          min_n=18446744073709551614) at /test/10.5_dbg/storage/innobase/buf/buf0flu.cc:1827
      #13 buf_flush_batch (flush_type=flush_type@entry=BUF_FLUSH_LIST, 
          min_n=min_n@entry=18446744073709551614, lsn_limit=lsn_limit@entry=18446744073709551615, 
          n=n@entry=0x7ffe0a3acb80) at /test/10.5_dbg/storage/innobase/buf/buf0flu.cc:1895
      #14 0x00005571ebab320c in buf_flush_do_batch (type=type@entry=BUF_FLUSH_LIST, 
          min_n=min_n@entry=18446744073709551614, lsn_limit=lsn_limit@entry=18446744073709551615, 
          n=n@entry=0x7ffe0a3acb80) at /test/10.5_dbg/storage/innobase/buf/buf0flu.cc:2018
      #15 0x00005571ebab3372 in buf_flush_lists (min_n=min_n@entry=18446744073709551614, 
          lsn_limit=lsn_limit@entry=18446744073709551615, n_processed=n_processed@entry=0x0)
          at /test/10.5_dbg/storage/innobase/buf/buf0flu.cc:2077
      #16 0x00005571ebab33c4 in buf_flush_sync () at /test/10.5_dbg/storage/innobase/buf/buf0flu.cc:3138
      #17 0x00005571eb9b0d51 in srv_start (create_new_db=<optimized out>)
          at /test/10.5_dbg/storage/innobase/srv/srv0start.cc:1514
      #18 0x00005571eb7d3a07 in innodb_init (p=<optimized out>)
          at /test/10.5_dbg/storage/innobase/handler/ha_innodb.cc:4033
      #19 0x00005571eb4046f8 in ha_initialize_handlerton (plugin=0x15113d586eb0)
          at /test/10.5_dbg/sql/handler.cc:584
      #20 0x00005571eb1724b7 in plugin_initialize (tmp_root=tmp_root@entry=0x7ffe0a3b31b0, 
          plugin=plugin@entry=0x15113d586eb0, argc=argc@entry=0x5571ec99e040 <remaining_argc>, 
          argv=argv@entry=0x15113d440448, options_only=<optimized out>)
          at /test/10.5_dbg/sql/sql_plugin.cc:1459
      #21 0x00005571eb173f55 in plugin_init (argc=argc@entry=0x5571ec99e040 <remaining_argc>, 
          argv=<optimized out>, flags=1) at /test/10.5_dbg/sql/sql_plugin.cc:1752
      #22 0x00005571eb05603d in init_server_components () at /test/10.5_dbg/sql/mysqld.cc:5002
      #23 0x00005571eb05c96f in mysqld_main (argc=<optimized out>, argv=<optimized out>)
          at /test/10.5_dbg/sql/mysqld.cc:5557
      #24 0x00005571eb04edc3 in main (argc=<optimized out>, argv=<optimized out>)
          at /test/10.5_dbg/sql/main.cc:25

      Affected versions 10.1-10.5 (debug), in various ways. Using this option on debug creates all sort of issues (out of disk space, defunct mysqld processes, issues with data init etc.). Had to restart server in the end to cleanup state.

      MariaDB 10.1 debug gives this :

      2020-05-08  8:00:45 23305409935296 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.

      But then starts filling up the disk;

      -rw-rw---- 1 roel roel  50G May  8 08:02 ibdata1

      And counting - Likely due to the negative->to->max var.

      Also seen;

      roel      111770  111767  0 04:30 pts/8    00:00:00 [mysqld] <defunct>
      roel      111767  111740  0 04:30 pts/8    00:00:00 [mariadb-install] <defunct>

      Fix may be as easy as disabling <0 values?


          Issue Links



              marko Marko Mäkelä
              Roel Roel Van de Paar
              0 Vote for this issue
              4 Start watching this issue



                  Git Integration