[MDEV-22501] Various issues when using --innodb-data-file-size-debug=-1 | SIGABRT in fil_mutex_enter_and_prepare_for_io Created: 2020-05-08  Updated: 2020-05-08  Resolved: 2020-05-08

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.5.4, 10.1.46, 10.2.33, 10.3.24, 10.4.14

Type: Bug Priority: Trivial
Reporter: Roel Van de Paar Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Problem/Incident
is caused by MDEV-11556 InnoDB redo log apply fails to adjust... Closed
Relates
relates to MDEV-22219 negative values on system variables l... Closed

 Description   

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?

 Comments   
Comment by Marko Mäkelä [ 2020-05-08 ]

This debug parameter is specifically for fault injection only:

innodb_data_file_size_debug: A debug parameter for setting the system tablespace size in recovery even when the redo log does not contain any size changes. It is hard to write a small test case that would cause the system tablespace to be extended at the critical moment.

Roel, we could set a smaller maximum value. The variable is only used by the test innodb.log_data_file_size. I checked two runs, and the maximum size of the system tablespace in mysql-test/var was 79,691,776 bytes. So, maybe a limit of 256MiB would work?

The fact that negative values passed to unsigned parameters wrap around to positive has already been reported in MDEV-22219.

Comment by Roel Van de Paar [ 2020-05-08 ]

Thank you Marko. Yes for this trivial bug I would suggest disapproving values smaller then 0 for this and other such parameters (as we saw in MDEV-22219), and with a max as defined by something reasonable per variable - perhaps 32GiB for example?

Comment by Roel Van de Paar [ 2020-05-08 ]

Marko is pushing a change which will set max values, and fixing MDEV-22219 will fix all unsigned parameters.

Generated at Thu Feb 08 09:15:12 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.