Assertion failure: buf0buf.cc:5894:ib::fatal
General
Escalation
General
Escalation
Description
Environment
None
Smart Checklist
Activity
Show:
puneet.kaushik January 31, 2023 at 7:50 PM
Bug Fix verified in PS 8.0.31
./mtr suite/clone/t/ddl_encrypt.test
Logging: ./mtr suite/clone/t/ddl_encrypt.test
MySQL Version 8.0.31
Checking supported features
- Binaries are debug compiled
Using 'all' suites
Collecting tests
Checking leftover processes
Removing old var directory
Creating var directory '/home/puneet.kaushik/Percona-Server-8.0.31-23-Linux.x86_64.glibc2.17-debug/mysql-test/var'
Installing system database
Using parallel: 1
==============================================================================
TEST NAME RESULT TIME (ms) COMMENT
------------------------------------------------------------------------------
[ 50%] clone.ddl_encrypt [ pass ] 165723
[100%] shutdown_report [ pass ]
------------------------------------------------------------------------------
The servers were restarted 0 times
The servers were reinitialized 0 times
Spent 165.723 of 219 seconds executing testcases
Completed: All 2 tests were successful.
Done
Details
Details
Assignee
Oleksandr Kachan
Oleksandr KachanReporter
Oleksandr Kachan
Oleksandr KachanNeeds QA
Yes
Time tracking
2h logged
Fix versions
Affects versions
Priority
MediumSmart Checklist
Open Smart Checklist
Smart Checklist
Open Smart Checklist
Created October 26, 2022 at 7:57 PM
Updated March 6, 2024 at 9:58 AM
Resolved January 12, 2023 at 9:16 AM
The issue may be reproduced by running clone.ddl_encrypt MTR test. There was a fix done for the same issue at https://github.com/percona/percona-server/pull/4624/commits/aacfbcbb4816bdba3c780d71a072474f31b1ced0 but it covers not all scenarios. Below is a backtrace from release-8.0.30 branch but the same should be reproducible for 8.0
#0 __pthread_kill_implementation (threadid=<optimized out>, signo=6, no_tid=<optimized out>) at pthread_kill.c:44 #1 0x0000000004b88422 in my_write_core (sig=6) at percona-server/8.0/mysys/stacktrace.cc:396 #2 0x0000000003a048ce in handle_fatal_signal (sig=6) at percona-server/8.0/sql/signal_handler.cc:228 #3 <signal handler called> #4 __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44 #5 0x00007fa74aeb4cb3 in __pthread_kill_internal (signo=6, threadid=<optimized out>) at pthread_kill.c:78 #6 0x00007fa74ae649c6 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26 #7 0x00007fa74ae4e7f4 in __GI_abort () at abort.c:79 #8 0x0000000003a04a57 in my_server_abort () at percona-server/8.0/sql/signal_handler.cc:287 #9 0x0000000004b7ee1a in my_abort () at percona-server/8.0/mysys/my_init.cc:264 #10 0x000000000506822f in ut_dbg_assertion_failed (expr=0x6fde3c0 "ib::fatal triggered", file=0x701eb10 "percona-server/8.0/storage/innobase/buf/buf0buf.cc", line=5894) at percona-server/8.0/storage/innobase/ut/ut0dbg.cc:99 #11 0x0000000005075495 in ib::fatal::~fatal (this=0x7fa7447473a0, __in_chrg=<optimized out>) at percona-server/8.0/storage/innobase/ut/ut0ut.cc:522 #12 0x000000000511c2b7 in buf_must_be_all_freed_instance (buf_pool=0x7fa73c31b4a0) at percona-server/8.0/storage/innobase/buf/buf0buf.cc:5894 #13 0x000000000511c53f in buf_pool_invalidate_instance (buf_pool=0x7fa73c31b4a0) at percona-server/8.0/storage/innobase/buf/buf0buf.cc:5941 #14 0x000000000511c6c1 in buf_pool_invalidate () at percona-server/8.0/storage/innobase/buf/buf0buf.cc:5968 #15 0x0000000004e52539 in recv_apply_hashed_log_recs (log=..., allow_ibuf=false) at percona-server/8.0/storage/innobase/log/log0recv.cc:1343 #16 0x0000000004fcff05 in srv_start (create_new_db=false) at percona-server/8.0/storage/innobase/srv/srv0start.cc:2212 #17 0x0000000004cc142d in innobase_init_files (dict_init_mode=DICT_INIT_CHECK_FILES, tablespaces=0x7fa74474e320, is_dd_encrypted=@0x7fa74474d0cf: false) at percona-server/8.0/storage/innobase/handler/ha_innodb.cc:6069 #18 0x0000000004cd42e4 in innobase_ddse_dict_init (dict_init_mode=DICT_INIT_CHECK_FILES, tables=0x7fa74474e340, tablespaces=0x7fa74474e320) at percona-server/8.0/storage/innobase/handler/ha_innodb.cc:13998 #19 0x000000000492bd5c in dd::bootstrap::DDSE_dict_init (thd=0xbb38dc0, dict_init_mode=DICT_INIT_CHECK_FILES, version=80023) at percona-server/8.0/sql/dd/impl/bootstrap/bootstrapper.cc:742 #20 0x0000000004b45715 in dd::upgrade_57::do_pre_checks_and_initialize_dd (thd=0xbb38dc0) at percona-server/8.0/sql/dd/upgrade_57/upgrade.cc:914 #21 0x0000000003b3a962 in bootstrap::handle_bootstrap (arg=0x7fff624e2460) at percona-server/8.0/sql/bootstrap.cc:327 #22 0x0000000005435db1 in pfs_spawn_thread (arg=0xbaca9b0) at percona-server/8.0/storage/perfschema/pfs.cc:2943 #23 0x00007fa74aeb2e2d in start_thread (arg=<optimized out>) at pthread_create.c:442 #24 0x00007fa74af381b0 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81From error log
2022-10-26T14:45:27.281851Z 1 [Note] [MY-012552] [InnoDB] Starting crash recovery. 2022-10-26T14:45:27.282168Z 1 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 52785676, whereas checkpoint_lsn = 52786060 and start_lsn = 52785664 2022-10-26T14:45:27.394668Z 1 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 58028544 2022-10-26T14:45:27.462719Z 1 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 61058507 2022-10-26T14:45:27.472758Z 1 [Note] [MY-013083] [InnoDB] Log background threads are being started... 2022-10-26T14:45:27.474190Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 713 redo log records ... 2022-10-26T14:45:27.484830Z 1 [Note] [MY-012533] [InnoDB] 10% 2022-10-26T14:45:27.493655Z 1 [Note] [MY-012533] [InnoDB] 20% 2022-10-26T14:45:27.497604Z 1 [Note] [MY-012533] [InnoDB] 30% 2022-10-26T14:45:27.914542Z 1 [Note] [MY-012533] [InnoDB] 40% 2022-10-26T14:45:28.334371Z 1 [Note] [MY-012533] [InnoDB] 50% 2022-10-26T14:45:28.531138Z 1 [Note] [MY-012533] [InnoDB] 60% 2022-10-26T14:45:28.774819Z 1 [Note] [MY-012533] [InnoDB] 70% 2022-10-26T14:45:28.779429Z 1 [Note] [MY-012533] [InnoDB] 80% 2022-10-26T14:45:29.184410Z 1 [Note] [MY-012533] [InnoDB] 90% 2022-10-26T14:45:29.336144Z 1 [Note] [MY-012533] [InnoDB] 100% 2022-10-26T14:45:29.938810Z 1 [ERROR] [MY-011908] [InnoDB] [FATAL] Page [page id: space=4294967278, page number=63] still fixed or dirty 2022-10-26T14:45:29.938892Z 1 [ERROR] [MY-013183] [InnoDB] Assertion failure: buf0buf.cc:5894:ib::fatal triggered thread 140439417140800The original fix implemented taking into account that buf_pool_invalidate() is invoked only once during server startup. This is not the case unfortunately, we can see it is also invoked second time after recovery is done. The synchronization between buf_pool_invalidate() and buf_lru_manager_thread() should take this into account.