Assertion failure: buf0flu.cc:3567:UT_LIST_GET_LEN(buf_pool->flush_list) == 0
General
Escalation
General
Escalation
Description
Environment
None
Smart Checklist
Activity
Show:
puneet.kaushik August 5, 2022 at 5:32 AM
Bug Fix verified in PS 8.0.29 , Not able to reproduce assertion after following attached test-case.
Marcelo Altmann April 20, 2022 at 4:48 PM
Reproducible on 5.7 as well:
2022-04-20 13:43:03 0x7f915e531700 InnoDB: Assertion failure in thread 140262329489152 in file buf0flu.cc line 3505
InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush_list) == 0
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
16:43:03 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
Please help us make Percona Server better by reporting any
bugs at https://bugs.percona.com/key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=0
max_threads=152
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68425 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Build ID: d8f7aa3c42af1d70916f2eed03ae57da802bdfc8
Server Version: 5.7.37-40-debug Percona Server (GPL), Revision a1b5e525399-DebugThread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x40000
bin/mysqld(my_print_stacktrace+0x47)[0x559ad73f7a0a]
bin/mysqld(handle_fatal_signal+0x446)[0x559ad71421c0]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x143c0)[0x7f917c2083c0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcb)[0x7f917c04303b]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x12b)[0x7f917c022859]
bin/mysqld(+0x1bf7113)[0x559ad774b113]
bin/mysqld(buf_flush_page_cleaner_coordinator+0xe0a)[0x559ad77dcc39]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8609)[0x7f917c1fc609]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x43)[0x7f917c11f163]
You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.Done
Details
Details
Assignee
Marcelo Altmann
Marcelo Altmann(Deactivated)Reporter
Marcelo Altmann
Marcelo Altmann(Deactivated)Time tracking
2d logged
Fix versions
Affects versions
Priority
MediumSmart Checklist
Open Smart Checklist
Smart Checklist
Open Smart Checklist
Created April 20, 2022 at 2:47 PM
Updated March 6, 2024 at 10:12 AM
Resolved August 17, 2022 at 11:23 AM
MySQL crash at shutdown with following assertion:MySQL crash at shutdown with following assertion:
2022-04-19T19:13:18.313078Z 0 [Note] [MY-013072] [InnoDB] Starting shutdown... 2022-04-19T19:13:19.535081Z 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: buf0flu.cc:3567:UT_LIST_GET_LEN(buf_pool->flush_list) == 0 thread 140422792267520 Backtrace: (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00007f85960b4859 in __GI_abort () at abort.c:79 #2 0x000055629009fae1 in my_server_abort () at /work/mysql/src/sql/signal_handler.cc:258 #3 0x00005562915a7bd5 in my_abort () at /work/mysql/src/mysys/my_init.cc:258 #4 0x0000556291a71db2 in ut_dbg_assertion_failed (expr=0x556293a183f8 "UT_LIST_GET_LEN(buf_pool->flush_list) == 0", file=0x556293a17060 "/work/mysql/src/storage/innobase/buf/buf0flu.cc", line=3567) at /work/mysql/src/storage/innobase/ut/ut0dbg.cc:99 #5 0x0000556291b6990b in buf_flush_page_coordinator_thread (n_page_cleaners=1) at /work/mysql/src/storage/innobase/buf/buf0flu.cc:3567 #6 0x00005562919e4e0a in std::__invoke_impl<void, void (*&)(unsigned long), unsigned long&> (__f=@0x7f8570a68b80: 0x556291b6878a <buf_flush_page_coordinator_thread(size_t)>) at /usr/include/c++/7/bits/invoke.h:60 #7 0x00005562919e4d79 in std::__invoke<void (*&)(unsigned long), unsigned long&> (__fn=@0x7f8570a68b80: 0x556291b6878a <buf_flush_page_coordinator_thread(size_t)>) at /usr/include/c++/7/bits/invoke.h:95 #8 0x00005562919e4c39 in std::_Bind<void (*(unsigned long))(unsigned long)>::__call<void, , 0ul>(std::tuple<>&&, std::_Index_tuple<0ul>) (this=0x7f8570a68b80, __args=...) at /usr/include/c++/7/functional:467 #9 0x00005562919e4975 in std::_Bind<void (*(unsigned long))(unsigned long)>::operator()<, void>() (this=0x7f8570a68b80) at /usr/include/c++/7/functional:551 #10 0x00005562919e4583 in Detached_thread::operator()<void (*)(unsigned long), unsigned long> (this=0x7f85843f1b28, f=@0x7f85843f1b20: 0x556291b6878a <buf_flush_page_coordinator_thread(size_t)>) at /work/mysql/src/storage/innobase/include/os0thread-create.h:193 #11 0x00005562919e350e in std::__invoke_impl<void, Detached_thread, void (*)(unsigned long), unsigned long> (__f=...) at /usr/include/c++/7/bits/invoke.h:60 #12 0x00005562919e099b in std::__invoke<Detached_thread, void (*)(unsigned long), unsigned long> (__fn=...) at /usr/include/c++/7/bits/invoke.h:95 #13 0x00005562919e4f39 in std::thread::_Invoker<std::tuple<Detached_thread, void (*)(unsigned long), unsigned long> >::_M_invoke<0ul, 1ul, 2ul> (this=0x7f85843f1b18) at /usr/include/c++/7/thread:234 #14 0x00005562919e4ed3 in std::thread::_Invoker<std::tuple<Detached_thread, void (*)(unsigned long), unsigned long> >::operator() (this=0x7f85843f1b18) at /usr/include/c++/7/thread:243 #15 0x00005562919e4eb2 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<Detached_thread, void (*)(unsigned long), unsigned long> > >::_M_run (this=0x7f85843f1b10) at /usr/include/c++/7/thread:186 #16 0x00007f85964c86b4 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6 #17 0x00007f8596b02609 in start_thread (arg=<optimized out>) at pthread_create.c:477 #18 0x00007f85961b1163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95The problem is happening due to the fact that there are still pages in the flush_list by the end the final sweep on flushing bp.
Those page(s) have not been flushed because despite the fact that they have been added to flush list they still have not been fully read, having it's io_fix still marked as BUF_IO_READ making it not eligible to flush (as per buf_flush_ready_for_flush_gen).
They have been brought to BP by srv_master_main_loop->srv_master_do_idle_tasks->ibuf_merge_in_background and we are still in the process of reading the page and applying the ibuf records while the shutdown happens and we never reached the point where we will mark the block as BUF_IO_NONE which would make the page eligible for flush from flush_list.
Some further information:
Flush list still has one page which is currently has io_fix->BUF_IO_READ:
(rr) bt 6 #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00007f85960b4859 in __GI_abort () at abort.c:79 #2 0x000055629009fae1 in my_server_abort () at /work/mysql/src/sql/signal_handler.cc:258 #3 0x00005562915a7bd5 in my_abort () at /work/mysql/src/mysys/my_init.cc:258 #4 0x0000556291a71db2 in ut_dbg_assertion_failed (expr=0x556293a183f8 "UT_LIST_GET_LEN(buf_pool->flush_list) == 0", file=0x556293a17060 "/work/mysql/src/storage/innobase/buf/buf0flu.cc", line=3567) at /work/mysql/src/storage/innobase/ut/ut0dbg.cc:99 #5 0x0000556291b6990b in buf_flush_page_coordinator_thread (n_page_cleaners=1) at /work/mysql/src/storage/innobase/buf/buf0flu.cc:3567 (More stack frames follow...) (rr) f 5 #5 0x0000556291b6990b in buf_flush_page_coordinator_thread (n_page_cleaners=1) at /work/mysql/src/storage/innobase/buf/buf0flu.cc:3567 3567 ut_a(UT_LIST_GET_LEN(buf_pool->flush_list) == 0); (rr) p buf_pool->flush_list $2 = { first_element = 0x7f8573d1c5c8, last_element = 0x7f8573d1c5c8, init = 51966, count = { <std::__atomic_base<unsigned long>> = { static _S_alignment = 8, _M_i = 1 }, members of std::atomic<unsigned long>: static is_always_lock_free = true } } (rr) p buf_pool->flush_list->first_element->id $3 = { m_space = 12, m_page_no = 7789 } (rr) p buf_pool->flush_list->first_element->io_fix $4 = { <std::atomic<buf_io_fix>> = { static _S_min_alignment = 1, static _S_alignment = 1, _M_i = BUF_IO_READ, static is_always_lock_free = <error reading variable: Missing ELF symbol "_ZNSt6atomicI10buf_io_fixE19is_always_lock_freeE".> }, <No data fields>} (rr) p buf_pool->flush_list->first_element->state $5 = BUF_BLOCK_FILE_PAGE (rr) p buf_pool->flush_list->first_element->flush_type $6 = BUF_FLUSH_LRU (rr)IO thread is still doing insert buffer merge for this page:
(rr) t 6 [Switching to thread 6 (Thread 174822.174828)] #0 0x0000000070000002 in syscall_traced () (rr) f 28 #28 0x0000556291b28835 in buf_page_io_complete (bpage=0x7f8573d1c5c8, evict=false) at /work/mysql/src/storage/innobase/buf/buf0buf.cc:5647 5647 ibuf_merge_or_delete_for_page((buf_block_t *)bpage, bpage->id, (rr) p bpage->id $7 = { m_space = 12, m_page_no = 7789 }FYI: It is still reproducible on 8.0.27 which is the latest GA release at the time of this report, but I can reproduce it way back (AFAIR I tested it until 8.0.23 and gave up trying lower versions).
How to repeat:
Unfortunately, I don't have a 100% deterministic test case. But I can continuously reproduce it with a debug flag to start a shutdown as soon as master thread is doing its idle tasks instructing insert buffer to do a full IO capacity flush;
Compile 8.0.28 with below change:
diff --git a/storage/innobase/ibuf/ibuf0ibuf.cc b/storage/innobase/ibuf/ibuf0ibuf.cc index 98d68e17146..04c6eea9427 100644 --- a/storage/innobase/ibuf/ibuf0ibuf.cc +++ b/storage/innobase/ibuf/ibuf0ibuf.cc @@ -30,6 +30,7 @@ this program; if not, write to the Free Software Foundation, Inc., Created 7/19/1997 Heikki Tuuri *******************************************************/ +#include <sql/mysqld.h> #include <sys/types.h> #include "btr0sea.h" @@ -2470,6 +2471,9 @@ ulint ibuf_merge_in_background(bool full) { if (full) { /* Caller has requested a full batch */ n_pages = PCT_IO(100); + DBUG_EXECUTE_IF("shutdown_on_full_ibuf", { + kill_mysql(); + }); } else { /* By default we do a batch of 5% of the io_capacity */ n_pages = PCT_IO(5);2. Start MySQL with default parameters.
3. Prepare the instance with some data:
mysql -e "CREATE USER sysbench@'%' IDENTIFIED WITH mysql_native_password' BY 'sysbench';" mysql -e "GRANT ALL ON . TO sysbench@'%';" mysql -e "create database sbtest;" WRITE_IP=127.1 WRITE_PORT=3310 sysbench --db-driver=mysql --db-ps-mode=disable --mysql-host=${WRITE_IP} --mysql-port=${WRITE_PORT} --mysql-user=sysbench --mysql-password=sysbench --table_size=500000 --tables=8 --threads=4 /usr/share/sysbench/oltp_read_write.lua prepare4. Stop MySQL
5. Run below script. It basically does:
5.1 - Start MySQL in background not loading BP pages (this increases the changes of having more ibuf operations)
5.2 - Generate some new data so changes to secondary index will be buffered on insert buffer
5.3 - kill MySQL so next time it will do a crash recovery - this makes mostly all pages that will be load to BP on next start up become dirty.
5.4 - Start MySQL again, this time using the debug flush to execute a SHUTDOWN as soon as we are doing a full insert buffer merge.
Script:
#!/bin/bash cd /work/mysql/ins/8.0 WRITE_IP=127.1 WRITE_PORT=3310function wait_mysql() { for i in $(seq 1 100); do mysqladmin -h${WRITE_IP} -P${WRITE_PORT} ping &> /dev/null if [ $? -eq 0 ]; then break; fi sleep 0.1 done }for b in $(seq 1 100); do bin/mysqld --defaults-file=my.cnf --log-error-verbosity=3 --innodb-buffer-pool-dump-at-shutdown=OFF \ --innodb-buffer-pool-load-at-startup=OFF & PID=$! wait_mysql sysbench --db-driver=mysql --db-ps-mode=disable --mysql-host=${WRITE_IP} \ --mysql-port=${WRITE_PORT} --mysql-user=sysbench --mysql-password=sysbench \ --table_size=500000 --tables=8 --threads=20 \ /usr/share/sysbench/oltp_write_only.lua --time=10 run > /dev/null kill -9 ${PID} bin/mysqld --defaults-file=my.cnf --log-error-verbosity=3 --innodb-buffer-pool-dump-at-shutdown=OFF \ --innodb-buffer-pool-load-at-startup=OFF --debug='+d,shutdown_on_full_ibuf' if [ $? -ne 0 ]; then break; fi echo "completed run ${b}" echo "" done