Details
-
Bug
-
Status: Closed (View Workflow)
-
Blocker
-
Resolution: Fixed
-
10.6, 10.7(EOL), 10.8(EOL), 10.9(EOL), 10.10(EOL), 10.11
Description
We got a data directory and an rr trace of failed recovery:
2022-11-28 14:25:35 0 [Note] InnoDB: Starting a batch to recover 504 pages from redo log.
|
2022-11-28 14:25:36 0 [Note] InnoDB: Starting a batch to recover 578 pages from redo log.
|
2022-11-28 14:25:37 0 [Note] InnoDB: Starting final batch to recover 295 pages from redo log.
|
...
|
2022-11-28 14:25:37 0 [Note] InnoDB: log sequence number 31381348 (memory-mapped); transaction id 27971
|
...
|
2022-11-28 14:25:39 0 [Note] /data/Server_bin/bb-10.11-new-innodb-defaults_asan_Og/bin/mysqld: ready for connections.
|
...
|
2022-11-28 14:25:40 6 [Warning] InnoDB: 8192 bytes should have been read. Only 512 bytes read. Retrying for the remaining bytes.
|
...
|
2022-11-28 14:25:40 6 [Warning] InnoDB: Retry attempts for reading partial data failed.
|
2022-11-28 14:25:40 6 [ERROR] InnoDB: File (null) was not found
|
2022-11-28 14:25:40 6 [ERROR] [FATAL] InnoDB: Tried to read 8192 bytes at offset 335872, but was only able to read 512.Cannot read from file. OS error number 2.
|
The fix of MDEV-30069 turns out to be ineffective after all. Before recovery was attempted, there was a file cool_down/t7.ibd that consists of 0x58000 NUL bytes. Recovery would actually shrink the file here:
#0 0x00005643699d96ef in fil_space_extend_must_retry (space=..., node=...,
|
size=..., success=...)
|
at /data/Server/bb-10.11-new-innodb-defaults/storage/innobase/fil/fil0fil.cc:550
|
#1 0x00005643699da7cb in fil_space_t::prepare_acquired (this=...)
|
at /data/Server/bb-10.11-new-innodb-defaults/storage/innobase/fil/fil0fil.cc:667
|
#2 0x00005643699daae4 in fil_space_t::acquire_and_prepare (this=...)
|
at /data/Server/bb-10.11-new-innodb-defaults/storage/innobase/fil/fil0fil.cc:707
|
#3 0x000056436935aba3 in fil_space_t::acquire (this=...)
|
at /data/Server/bb-10.11-new-innodb-defaults/storage/innobase/log/log0recv.cc:956
|
#4 recv_sys_t::recover_deferred (this=..., p=..., name=..., free_block=...)
|
at /data/Server/bb-10.11-new-innodb-defaults/storage/innobase/log/log0recv.cc:954
|
We must invoke a special form of fil_space_t::acquire(), or we must set fil_space_t::committed_size based on the actual file size, so that the file will not be shrunk.
Furthermore, the intentional crash during a file read is against the spirit of MDEV-13542. The read error must be propagated up the call stack.
I can reproduce the crash on MariaDB 10.9 (anything later than 10.8 will do) as follows:
tar xJf data.tar.xz
|
mariadbd --innodb-buffer-pool-size=4m --innodb-page-size=8k --innodb-log-file-size=100663296 --datadir "$(pwd)"/data --plugin-dir="$BUILDDIR"/plugin/file_key_management --plugin-load-add=file_key_management.so --file-key-management-filename="$(pwd)"/encryption_keys.txt --innodb-undo-tablespaces=3 &
|
echo 'check table cool_down.t7 extended;'|mariadb -uroot
|
|
10.9 9abd70e390bd8ef2e8347677a2aedd00151f0712 |
...
|
2022-11-30 9:08:29 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=2106076
|
2022-11-30 9:08:29 0 [Note] InnoDB: Starting a batch to recover 159 pages from redo log.
|
2022-11-30 9:08:30 0 [Note] InnoDB: Starting a batch to recover 255 pages from redo log.
|
2022-11-30 9:08:30 0 [Note] InnoDB: Starting a batch to recover 348 pages from redo log.
|
2022-11-30 9:08:30 0 [Note] InnoDB: Starting a batch to recover 372 pages from redo log.
|
2022-11-30 9:08:30 0 [Note] InnoDB: Starting a batch to recover 429 pages from redo log.
|
2022-11-30 9:08:30 0 [Note] InnoDB: Starting a batch to recover 410 pages from redo log.
|
2022-11-30 9:08:30 0 [Note] InnoDB: Starting a batch to recover 478 pages from redo log.
|
2022-11-30 9:08:30 0 [Note] InnoDB: Opened 3 undo tablespaces
|
2022-11-30 9:08:30 0 [Note] InnoDB: Starting final batch to recover 146 pages from redo log.
|
...
|
Version: '10.9.5-MariaDB-debug' socket: '/dev/shm/mariadb.sock' port: 3306 Source distribution
|
2022-11-30 9:08:54 3 [Warning] InnoDB: 8192 bytes should have been read. Only 512 bytes read. Retrying for the remaining bytes.
|
...
|
2022-11-30 9:08:54 3 [Warning] InnoDB: Retry attempts for reading partial data failed.
|
2022-11-30 9:08:54 3 [ERROR] InnoDB: File (null) was not found
|
2022-11-30 9:08:54 3 [ERROR] [FATAL] InnoDB: Tried to read 8192 bytes at offset 335872, but was only able to read 512.Cannot read from file. OS error number 2.
|
If I use a larger innodb_buffer_pool_size so that everything will be recovered in a single batch, the database will not crash.
Attachments
Issue Links
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
Activity
The recovery of the dataset is nondeterministic. After I fixed up something in the MDEV-30069 fix, data.tar.xz
recovered each time when I tried it with rr record --chaos.
diff --git a/storage/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc
|
index 3dcc7e54ab0..b0651d8b8da 100644
|
--- a/storage/innobase/log/log0recv.cc
|
+++ b/storage/innobase/log/log0recv.cc
|
@@ -998,6 +998,7 @@ bool recv_sys_t::recover_deferred(recv_sys_t::map::iterator &p,
|
{
|
space->size= node->size= n_pages;
|
space->set_committed_size();
|
+ goto size_set;
|
}
|
}
|
if (!os_file_set_size(node->name, node->handle,
|
@@ -1007,6 +1008,7 @@ bool recv_sys_t::recover_deferred(recv_sys_t::map::iterator &p,
|
space->release();
|
goto release_and_fail;
|
}
|
+ size_set:
|
node->deferred= false;
|
space->release();
|
it->second.space= space; |
Some results of RQG testing.
|
A simplified RQG test (developed against bb-10.11-new-innodb-defaults) replayed
|
the error patterns
|
- [ 'TBR-1680', 'INFO: Reporter \'CrashRecovery.*\': Attempting database recovery using the server.+\[Note\] InnoDB: Starting crash recovery from checkpoint LSN.+\[Warning\] InnoDB: .{1,10} bytes should have been read. Only .{1,10} bytes read. Retrying for the remaining bytes..+InnoDB: Assertion failure in file .{1,250}fil0fil.cc .+InnoDB: Failing assertion: type\.type == IORequest::DBLWR_RECOVER \|\| err == DB_SUCCESS.+RESULT: The RQG run ended with status STATUS_RECOVERY_FAILURE' ],
|
- [ 'TBR-1682', 'INFO: Reporter \'CrashRecovery.*\': Attempting database recovery using the server.+\[Note\] InnoDB: Starting crash recovery from checkpoint LSN.+\[Warning\] InnoDB: .{1,10} bytes should have been read. Only .{1,10} bytes read. Retrying for the remaining bytes..+\[ERROR\] InnoDB: File \(unknown\): \'read\' returned OS error 0.+RESULT: The RQG run ended with status STATUS_RECOVERY_FAILURE' ],
|
on origin/10.11 commit fc1403d3a9ef3230324396f621f72f02097c8a6a 2022-11-30T10:41:11+02:00
|
|
|
No replay on origin/10.11, 10.11 b81b1943932a383a92bcd22d053e112198507ae2 2022-11-30T12:59:57+02:00
|
which contains the fixes for
|
- MDEV-30132 Crash after recovery, with InnoDB: Tried to read ...
|
- MDEV-30069 fixup: Do not truncate files on recovery
|
|
|
There was also no replay on origin/10.6 ae6ebafd819d48c965d2615fc78f1f950e0fbf40 2022-11-14T15:44:55+02:00 even though I adjusted the server to the defaults used in 10.11.
|
One testing result which might belong to this MDEV.
|
origin/10.6 6d40274f65b8d145fbf496e9b1b1d46f258de227 2022-11-23T18:13:28+02:00
|
10.6.12
|
Szenario:
|
1. Start server + generate some initial data.
|
2. One session runs a DDL/DML mix
|
3. During 2. is ongoing kill the server intentional
|
4. Restart with success
|
5. As soon as the server is connectable the consistency of table data is checked.
|
Some SELECT * FROM `cool_down`.`t6` FORCE INDEX (`PRIMARY`) WHERE `col1` IS NULL OR `col1` IS NOT NULL
|
leads to the crash of the server
|
Snip of server error log:
|
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61655]2022-12-02 2:09:38 6 [Warning] InnoDB: 16384 bytes should have been read. Only 512 bytes read. Retrying for the remaining bytes.
|
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61659]2022-12-02 2:09:38 6 [Warning] InnoDB: 16384 bytes should have been read. Only 512 bytes read. Retrying for the remaining bytes.
|
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61663]2022-12-02 2:09:38 6 [Warning] InnoDB: Retry attempts for reading partial data failed.
|
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61667]2022-12-02 2:09:38 6 [ERROR] InnoDB: Operating system error number 2 in a file operation.
|
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61671]2022-12-02 2:09:38 6 [ERROR] InnoDB: The error means the system cannot find the path specified.
|
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61675]2022-12-02 2:09:38 6 [ERROR] InnoDB: File (unknown): 'read' returned OS error 71. Cannot continue operation
|
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61691]221202 2:09:38 [rr 3807036 61694][ERROR] mysqld got signal 6 ;
|
|
|
(rr) bt
|
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=21621471700544) at ./nptl/pthread_kill.c:44
|
#1 __pthread_kill_internal (signo=6, threadid=21621471700544) at ./nptl/pthread_kill.c:78
|
#2 __GI___pthread_kill (threadid=21621471700544, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
|
#3 0x0000754155d90476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
|
#4 0x0000754155d767f3 in __GI_abort () at ./stdlib/abort.c:79
|
#5 0x0000558ae1be2ece in os_file_handle_error_cond_exit (name=name@entry=0x0, operation=operation@entry=0x558ae2c50ca0 "read", should_abort=should_abort@entry=true, on_error_silent=on_error_silent@entry=false)
|
at /data/Server/10.6A/storage/innobase/os/os0file.cc:3064
|
#6 0x0000558ae1be99c6 in os_file_read_page (type=..., file=<optimized out>, buf=buf@entry=0x493d3f3cc000, offset=offset@entry=491520, n=n@entry=16384, o=o@entry=0x0, exit_on_err=<optimized out>)
|
at /data/Server/10.6A/storage/innobase/os/os0file.cc:2950
|
#7 0x0000558ae1bea042 in os_file_read_func (type=..., file=<optimized out>, buf=buf@entry=0x493d3f3cc000, offset=offset@entry=491520, n=n@entry=16384) at /data/Server/10.6A/storage/innobase/os/os0file.cc:3344
|
#8 0x0000558ae1bea326 in os_aio (type=..., buf=buf@entry=0x493d3f3cc000, offset=<optimized out>, n=n@entry=16384) at /data/Server/10.6A/storage/innobase/os/os0file.cc:3790
|
#9 0x0000558ae21365c0 in fil_space_t::io (this=this@entry=0x612000002bc0, type=..., offset=<optimized out>, len=len@entry=16384, buf=<optimized out>, bpage=bpage@entry=0x493d3ede80b0)
|
at /data/Server/10.6A/storage/innobase/fil/fil0fil.cc:2748
|
#10 0x0000558ae2041cdf in buf_read_page_low (err=err@entry=0x13aa24238a40, space=<optimized out>, sync=sync@entry=true, mode=mode@entry=132, page_id=..., zip_size=zip_size@entry=0, unzip=<optimized out>)
|
at /data/Server/10.6A/storage/innobase/buf/buf0rea.cc:319
|
#11 0x0000558ae204744f in buf_read_page (page_id=..., zip_size=zip_size@entry=0) at /data/Server/10.6A/storage/innobase/buf/buf0rea.cc:457
|
#12 0x0000558ae1fee0aa in buf_page_get_low (page_id=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=1, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x13aa24239450, err=<optimized out>,
|
allow_ibuf_merge=<optimized out>) at /data/Server/10.6A/storage/innobase/buf/buf0buf.cc:2496
|
#13 0x0000558ae1ff2663 in buf_page_get_gen (page_id=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=1, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x13aa24239450, err=0x0, allow_ibuf_merge=false)
|
at /data/Server/10.6A/storage/innobase/buf/buf0buf.cc:2962
|
#14 0x0000558ae1f62777 in btr_copy_blob_prefix (buf=<optimized out>, len=<optimized out>, id=..., offset=offset@entry=38) at /data/Server/10.6A/storage/innobase/btr/btr0cur.cc:7404
|
#15 0x0000558ae1f8952e in btr_copy_externally_stored_field_prefix_low (buf=buf@entry=0x6290018e7288 '\276' <repeats 200 times>..., len=len@entry=8193, zip_size=zip_size@entry=0, id=..., id@entry=..., offset=offset@entry=38)
|
at /data/Server/10.6A/storage/innobase/btr/btr0cur.cc:7604
|
#16 0x0000558ae1f89e87 in btr_copy_externally_stored_field (len=len@entry=0x13aa24239920, data=data@entry=0x493d3ef4848e "", zip_size=zip_size@entry=0, local_len=0, local_len@entry=20, heap=heap@entry=0x6290018e7200)
|
at /data/Server/10.6A/storage/innobase/btr/btr0cur.cc:7704
|
#17 0x0000558ae1f8a27e in btr_rec_copy_externally_stored_field (rec=rec@entry=0x493d3ef48461 "\200", offsets=offsets@entry=0x13aa2423a620, zip_size=0, no=no@entry=7, len=len@entry=0x13aa24239920, heap=heap@entry=0x6290018e7200)
|
at /data/Server/10.6A/storage/innobase/btr/btr0cur.cc:7761
|
#18 0x0000558ae1dc406d in row_sel_store_mysql_field (mysql_rec=mysql_rec@entry=0x61a0000816b8 "\340\v\001", prebuilt=prebuilt@entry=0x621000091188, rec=rec@entry=0x493d3ef48461 "\200", index=index@entry=0x61600446b008,
|
offsets=offsets@entry=0x13aa2423a620, field_no=7, templ=<optimized out>) at /data/Server/10.6A/storage/innobase/row/row0sel.cc:3019
|
#19 0x0000558ae1dc4d43 in row_sel_store_mysql_rec (mysql_rec=mysql_rec@entry=0x61a0000816b8 "\340\v\001", prebuilt=prebuilt@entry=0x621000091188, rec=0x493d3ef48461 "\200", vrow=0x0, rec_clust=false, index=0x61600446b008,
|
offsets=0x13aa2423a620) at /data/Server/10.6A/storage/innobase/row/row0sel.cc:3236
|
#20 0x0000558ae1de42b8 in row_search_mvcc (buf=buf@entry=0x61a0000816b8 "\340\v\001", mode=<optimized out>, mode@entry=PAGE_CUR_UNSUPP, prebuilt=<optimized out>, match_mode=match_mode@entry=0, direction=direction@entry=1)
|
at /data/Server/10.6A/storage/innobase/row/row0sel.cc:5683
|
#21 0x0000558ae199fa6c in ha_innobase::general_fetch (this=this@entry=0x61d0001bb2b8, buf=0x61a0000816b8 "\340\v\001", direction=direction@entry=1, match_mode=match_mode@entry=0)
|
at /data/Server/10.6A/storage/innobase/handler/ha_innodb.cc:9332
|
#22 0x0000558ae19c5490 in ha_innobase::rnd_next (this=0x61d0001bb2b8, buf=<optimized out>) at /data/Server/10.6A/storage/innobase/handler/ha_innodb.cc:9536
|
#23 0x0000558ae0f24d43 in handler::ha_rnd_next (this=0x61d0001bb2b8, buf=0x61a0000816b8 "\340\v\001") at /data/Server/10.6A/sql/handler.cc:3416
|
#24 0x0000558ae1562e52 in rr_sequential (info=0x62b0000d6c18) at /data/Server/10.6A/sql/records.cc:519
|
#25 0x0000558ae0753b58 in READ_RECORD::read_record (this=0x62b0000d6c18) at /data/Server/10.6A/sql/records.h:81
|
#26 sub_select (join=0x62b0000d3fe0, join_tab=0x62b0000d6b50, end_of_records=false) at /data/Server/10.6A/sql/sql_select.cc:21391
|
#27 0x0000558ae07caa72 in do_select (join=join@entry=0x62b0000d3fe0, procedure=<optimized out>) at /data/Server/10.6A/sql/sql_select.cc:20915
|
#28 0x0000558ae07f43a4 in JOIN::exec_inner (this=this@entry=0x62b0000d3fe0) at /data/Server/10.6A/sql/sql_select.cc:4796
|
#29 0x0000558ae07f46d7 in JOIN::exec (this=this@entry=0x62b0000d3fe0) at /data/Server/10.6A/sql/sql_select.cc:4574
|
#30 0x0000558ae07ee39d in mysql_select (thd=thd@entry=0x62b0000cb218, tables=0x62b0000d2a58, fields=..., conds=0x62b0000d3588, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2148272640,
|
result=0x62b0000d3fb0, unit=0x62b0000cf388, select_lex=0x62b0000d2370) at /data/Server/10.6A/sql/sql_select.cc:5053
|
#31 0x0000558ae07efccd in handle_select (thd=thd@entry=0x62b0000cb218, lex=lex@entry=0x62b0000cf2c0, result=result@entry=0x62b0000d3fb0, setup_tables_done_option=setup_tables_done_option@entry=0)
|
at /data/Server/10.6A/sql/sql_select.cc:555
|
#32 0x0000558ae064824c in execute_sqlcom_select (thd=thd@entry=0x62b0000cb218, all_tables=<optimized out>) at /data/Server/10.6A/sql/sql_parse.cc:6256
|
#33 0x0000558ae066f6ee in mysql_execute_command (thd=thd@entry=0x62b0000cb218, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/10.6A/sql/sql_parse.cc:3946
|
#34 0x0000558ae067f57e in mysql_parse (thd=thd@entry=0x62b0000cb218, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x13aa2423c620) at /data/Server/10.6A/sql/sql_parse.cc:8016
|
#35 0x0000558ae0685db9 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62b0000cb218, packet=packet@entry=0x62900164e219 '1' <repeats 200 times>..., packet_length=packet_length@entry=98,
|
blocking=blocking@entry=true) at /data/Server/10.6A/sql/sql_parse.cc:1896
|
--Type <RET> for more, q to quit, c to continue without paging--c
|
#36 0x0000558ae068ae18 in do_command (thd=0x62b0000cb218, blocking=blocking@entry=true) at /data/Server/10.6A/sql/sql_parse.cc:1409
|
#37 0x0000558ae0aa6786 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x608000000e38, put_in_cache=put_in_cache@entry=true) at /data/Server/10.6A/sql/sql_connect.cc:1415
|
#38 0x0000558ae0aa6dec in handle_one_connection (arg=0x608000000e38) at /data/Server/10.6A/sql/sql_connect.cc:1317
|
#39 0x0000754155de2b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
|
#40 0x0000754155e73bb4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
|
(rr)
|
|
The following patch will improve upon the fix of
MDEV-30069:diff --git a/storage/innobase/fil/fil0fil.cc b/storage/innobase/fil/fil0fil.ccindex 98024bd2769..c59e15da2c7 100644--- a/storage/innobase/fil/fil0fil.cc+++ b/storage/innobase/fil/fil0fil.cc@@ -661,6 +661,7 @@ ATTRIBUTE_COLD bool fil_space_t::prepare_acquired()if (!is_open)release();+ else if (node->deferred);else if (auto desired_size= recv_size){