Matthias Leich added a comment - 2022-11-22 09:32 RQG === # git clone https://github.com/mleich1/rqg --branch experimental RQG # # GIT_SHOW: HEAD -> experimental, origin/experimental ec83f640bab8f5ea31f07b9bc118d508abae3b35 2022-11-17T15:46:44+01:00 # rqg.pl : Version 4.0.6 (2022-09) # # $RQG_HOME/rqg.pl \ # --grammar=conf/mariadb/table_stress_innodb_nocopy1.yy \ # --gendata=conf/mariadb/table_stress.zz \ # --gendata_sql=conf/mariadb/table_stress.sql \ # --reporters=CrashRecovery1 \ # --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \ # --mysqld=--loose-idle_write_transaction_timeout=0 \ # --mysqld=--loose-idle_transaction_timeout=0 \ # --mysqld=--loose-idle_readonly_transaction_timeout=0 \ # --mysqld=--connect_timeout=60 \ # --mysqld=--interactive_timeout=28800 \ # --mysqld=--slave_net_timeout=60 \ # --mysqld=--net_read_timeout=30 \ # --mysqld=--net_write_timeout=60 \ # --mysqld=--loose-table_lock_wait_timeout=50 \ # --mysqld=--wait_timeout=28800 \ # --mysqld=--lock-wait-timeout=86400 \ # --mysqld=--innodb-lock-wait-timeout=50 \ # --no-mask \ # --queries=10000000 \ # --seed=random \ # --reporters=Backtrace \ # --reporters=ErrorLog \ # --reporters=Deadlock1 \ # --validators=None \ # --mysqld=--log_output=none \ # --mysqld=--log_bin_trust_function_creators=1 \ # --mysqld=--loose-debug_assert_on_not_freed_memory=0 \ # --engine=InnoDB \ # --restart_timeout=240 \ # --mysqld=--plugin-load-add=file_key_management.so \ # --mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \ # --mysqld=--plugin-load-add=provider_lzo.so \ # --mysqld=--plugin-load-add=provider_bzip2.so \ # --mysqld=--plugin-load-add=provider_lzma.so \ # --mysqld=--plugin-load-add=provider_snappy.so \ # --mysqld=--plugin-load-add=provider_lz4.so \ # --duration=300 \ # --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \ # --mysqld=--innodb_file_per_table=1 \ # --mysqld=--loose-innodb_read_only_compressed=OFF \ # --mysqld=--innodb_stats_persistent=off \ # --mysqld=--innodb_adaptive_hash_index=off \ # --mysqld=--log-bin \ # --mysqld=--sync-binlog=1 \ # --mysqld=--loose-innodb_evict_tables_on_commit_debug=on \ # --mysqld=--loose-max-statement-time=30 \ # --threads=33 \ # --mysqld=--innodb-use-native-aio=0 \ # --mysqld=--loose-gdb \ # --mysqld=--loose-debug-gdb \ # --rr=Extended \ # --rr_options=--chaos --wait \ # --mysqld=--innodb_rollback_on_timeout=ON \ # --mysqld=--innodb_page_size=64K \ # --mysqld=--innodb-buffer-pool-size=24M \ # <local settings>   sdp:/data/results/1669039949/TBR-1663 Error pattern [ 'TBR-1663', 'INFO: Reporter \'CrashRecovery.\': Attempting database recovery using the server.+\[Note\] InnoDB: Starting crash recovery from checkpoint LSN.+\[ERROR\] \[FATAL\] InnoDB: Trying to write .{1,20} bytes at .{1,20} outside the bounds of the file: .{1,250}\.ibd.+RESULT: The RQG run ended with status STATUS_RECOVERY_FAILURE' ],

Marko Mäkelä added a comment - 2022-11-22 11:00 The fix that I initially had in mind is too complex, could cause a performance regression, and actually cannot fix the failure. In the rr replay trace, fil_ibd_load() is being invoked multiple times on the file test/t5.ibd , and each time it returns FIL_LOAD_DEFER , which the caller does not make note of ( MDEV-25909 ). Each of those calls also invokes os_file_get_size() but throws away the result. The data set that I uploaded to MDEV-30068 actually does recover, because the first page of the file test/t5.ibd had already been written by recovery. I should have copied the data directory before the restart attempt. In that data directory, the file test/t5.ibd consists of 448*65536 NUL bytes. This problem was caused by MDEV-24626 in MariaDB Server 10.6. As far as I can tell, a second attempt to recover the data directory should succeed. The FSP_SIZE in page 0 of the file will be recovered to 0x1c0 (448) pages on my system, while in the data directory that I attached to MDEV-30068 , it was only recovered to 10 pages. That is what recv_sys_t::recover_deferred() recovered as the file size in the rr replay traces. Finally, I was able to reproduce this with data.tar.xz (before the recovery attempt) and encryption_keys.txt and a little cheat: diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc index 9b81aa9307c..73d29692907 100644 --- a/storage/innobase/handler/ha_innodb.cc +++ b/storage/innobase/handler/ha_innodb.cc @@ -3821,6 +3821,7 @@ static int innodb_init_params() pages, even for larger pages */ MYSQL_SYSVAR_NAME(buffer_pool_size).min_val= min_buffer_pool_size(); +#if 0 if (innobase_buffer_pool_size < MYSQL_SYSVAR_NAME(buffer_pool_size).min_val) { ib::error() << "innodb_page_size=" << srv_page_size << " requires " @@ -3830,6 +3831,7 @@ static int innodb_init_params() << "MiB"; DBUG_RETURN(HA_ERR_INITIALIZATION); } +#endif #ifndef HAVE_LZ4 if (innodb_compression_algorithm == PAGE_LZ4_ALGORITHM) { mariadbd --plugin-dir=$BUILD_DIR/plugin/file_key_management --plugin-load-add=file_key_management.so --file-key-management-filename=$(pwd)/encryption_keys.txt --innodb_page_size=64K --innodb-log-file-size=96M --innodb-buffer-pool-size=12M --datadir $(pwd)/data 10.6 377ec1b5c906ea55fa2af9ae048a14eb9e1cf201 (patched) 2022-11-22 12:54:38 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=48561117,51775692 2022-11-22 12:54:38 0 [Note] InnoDB: Starting a batch to recover 503 pages from redo log. 2022-11-22 12:54:38 0 [ERROR] [FATAL] InnoDB: Trying to write 65536 bytes at 2359296 outside the bounds of the file: ./test/t5.ibd Like in the rr replay trace, the tablespace size is 10 and the recv_size is 448 pages at this point. I think that the problem occurs when a created data file is recovered during an earlier batch of recovery. At that point, we fail to read the file size metadata from the file system.

Otto Kekäläinen added a comment - 2024-05-09 04:40 I saw this on s390x builder on Launchpad for MariaDB 10.11.7: innodb.undo_truncate '4k,innodb' w2 [ fail ] Found warnings/errors in server log file! Test ended at 2024-05-08 03:54:42 line 2024-05-08 3:54:18 0 [ERROR] [FATAL] InnoDB: Trying to write 4096 bytes at 2621440 outside the bounds of the file: .//undo001 Attempting backtrace. You can use the following information to find out ^ Found warnings in /<<PKGBUILDDIR>>/builddir/mysql-test/var/2/log/mysqld.1.err ok Full log: https://launchpadlibrarian.net/728605875/buildlog_ubuntu-noble-s390x.mariadb_1%3A10.11.7-5~bpo24.04.1~1715057361.1833c7608a3+debian.latest_BUILDING.txt.gz