MySQL Bugs: #112608: redo log consumer cannot advance

Bug #112608	redo log consumer cannot advance
Submitted:	3 Oct 2023 16:37	Modified:	13 Mar 2024 22:53
Reporter:	Marcelo Altmann (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	8.0	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Redo log consumer cannot advance if capacity is full and another thread is running CREATE USER.

T1. advance function waits on MDL taken on privilege tables (T2)
T2. create user waits on space on redo logs (T3)
T3. log_writer waits on the consumer to advance lsn (T1)

How to repeat:
T1. DO innodb_redo_log_consumer_register();

-- run load/sysbench until the redo log is full. Error log will have:

2023-10-03T16:21:43.152501Z 0 [Warning] [MY-013934] [InnoDB] Redo log writer is waiting for MEB redo log consumer which is currently reading LSN=133323691 preventing reclamation of subsequent portion of the redo log. Consider increasing innodb_redo_log_capacity.

T2. Create a user: CREATE USER u1@localhost

T1. Try to advance consumer: DO innodb_redo_log_consumer_advance(231113932);
innodb_redo_log_consumer_advance will hang

--- Thread Dump (mysqld 8.1.0-debug) -----

CONSUMER:

Thread 40 (Thread 0x7fe44c2f0640 (LWP 528100) "connection"):
#0  __futex_abstimed_wait_common64 (private=-2011781424, cancel=true, abstime=0x7fe44c2ec8b0, op=393, expected=0, futex_word=0x7fe388126398) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (cancel=true, private=-2011781424, abstime=0x7fe44c2ec8b0, clockid=-2011781424, expected=0, futex_word=0x7fe388126398) at ./nptl/futex-internal.c:87
#2  __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x7fe388126398, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x7fe44c2ec8b0, private=private@entry=0) at ./np
tl/futex-internal.c:139
#3  0x00007fe4633bbf1b in __pthread_cond_wait_common (abstime=0x7fe44c2ec8b0, clockid=0, mutex=0x7fe388000ee8, cond=0x7fe388126370) at ./nptl/pthread_cond_wait.c:503
#4  ___pthread_cond_timedwait64 (cond=0x7fe388126370, mutex=0x7fe388000ee8, abstime=0x7fe44c2ec8b0) at ./nptl/pthread_cond_wait.c:652
#5  0x0000564eca8ecc27 in native_cond_timedwait (cond=0x7fe388126370, mutex=0x7fe388000ee8, abstime=0x7fe44c2ec8b0) at /work/mysql/src/include/thr_cond.h:99
#6  0x0000564eca8ecf9a in safe_cond_timedwait (cond=0x7fe388126370, mp=0x7fe388000ec0, abstime=0x7fe44c2ec8b0, file=0x564ec6511f02 "/work/mysql/src/sql/mdl.cc", line=1819) at /work/mysql/src/mysys/thr_cond.cc:11
3
#7  0x0000564ec8eb1dad in my_cond_timedwait (cond=0x7fe388126370, mp=0x7fe388126340, abstime=0x7fe44c2ec8b0, file=0x564ec6511f02 "/work/mysql/src/sql/mdl.cc", line=1819) at /work/mysql/src/include/thr_cond.h:146
#8  0x0000564ec8eb24b0 in inline_mysql_cond_timedwait (that=0x7fe388126370, mutex=0x7fe388126340, abstime=0x7fe44c2ec8b0, src_file=0x564ec6511f02 "/work/mysql/src/sql/mdl.cc", src_line=1819) at /work/mysql/src/i
nclude/mysql/psi/mysql_cond.h:242
#9  0x0000564ec8eb3964 in MDL_wait::timed_wait (this=0x7fe388126340, owner=0x7fe388125fb0, abs_timeout=0x7fe44c2ec8b0, set_status_on_timeout=false, wait_state_name=0x564ecbc30e40 <MDL_key::m_namespace_to_wait_st
ate_name+416>) at /work/mysql/src/sql/mdl.cc:1819
#10 0x0000564ec8eb5c44 in MDL_context::acquire_lock (this=0x7fe388126340, mdl_request=0x7fe44c2ec940, lock_wait_timeout=3600) at /work/mysql/src/sql/mdl.cc:3496
#11 0x0000564ec8f3edce in Acl_cache_lock_guard::lock (this=0x7fe44c2ecb70, raise_error=false) at /work/mysql/src/sql/auth/sql_auth_cache.cc:3551
#12 0x0000564ec8f67e00 in Security_context::has_global_grant (this=0x7fe388127318, priv=0x564ec7ba657c "BACKUP_ADMIN", priv_len=12) at /work/mysql/src/sql/auth/sql_security_ctx.cc:661
#13 0x0000564ecae36c89 in meb::verify_privilege (thd=0x7fe388125fb0, priv_name=0x564ec7ba657c "BACKUP_ADMIN") at /work/mysql/src/storage/innobase/log/log0meb.cc:829
#14 0x0000564ecae3bcd2 in meb::innodb_redo_log_consumer_advance (initid=0x7fe388132ef0, args=0x7fe388132eb0, null_value=0x7fe388132f21 "", error=0x7fe388132f20 "") at /work/mysql/src/storage/innobase/log/log0meb.cc:2420
#15 0x0000564ec8e80a16 in udf_handler::val_int (this=0x7fe388132ea0, null_value=0x7fe388132e57) at /work/mysql/src/sql/item_func.cc:4782
#16 0x0000564ec8e817c3 in Item_func_udf_int::val_int (this=0x7fe388132da8) at /work/mysql/src/sql/item_func.cc:4989
#17 0x0000564ec8e01136 in Item::evaluate (this=0x7fe388132da8, thd=0x7fe388125fb0, buffer=0x7fe44c2ece60) at /work/mysql/src/sql/item.cc:7571
#18 0x0000564ec96a4936 in Query_result_do::send_data (this=0x7fe388150dd0, thd=0x7fe388125fb0, items=...) at /work/mysql/src/sql/sql_do.cc:44
#19 0x0000564ec974f22e in Query_expression::ExecuteIteratorQuery (this=0x7fe388131720, thd=0x7fe388125fb0) at /work/mysql/src/sql/sql_union.cc:1785
#20 0x0000564ec974f4bf in Query_expression::execute (this=0x7fe388131720, thd=0x7fe388125fb0) at /work/mysql/src/sql/sql_union.cc:1823
#21 0x0000564ec9693712 in Sql_cmd_dml::execute_inner (this=0x7fe388150d98, thd=0x7fe388125fb0) at /work/mysql/src/sql/sql_select.cc:1022
#22 0x0000564ec9692a83 in Sql_cmd_dml::execute (this=0x7fe388150d98, thd=0x7fe388125fb0) at /work/mysql/src/sql/sql_select.cc:793
#23 0x0000564ec95ffc95 in mysql_execute_command (thd=0x7fe388125fb0, first_level=true) at /work/mysql/src/sql/sql_parse.cc:4797
#24 0x0000564ec9602107 in dispatch_sql_command (thd=0x7fe388125fb0, parser_state=0x7fe44c2ee9b0) at /work/mysql/src/sql/sql_parse.cc:5447
#25 0x0000564ec95f752b in dispatch_command (thd=0x7fe388125fb0, com_data=0x7fe44c2ef300, command=COM_QUERY) at /work/mysql/src/sql/sql_parse.cc:2112
#26 0x0000564ec95f53cb in do_command (thd=0x7fe388125fb0) at /work/mysql/src/sql/sql_parse.cc:1459
#27 0x0000564ec9856f95 in handle_connection (arg=0x564ed08d24d0) at /work/mysql/src/sql/conn_handler/connection_handler_per_thread.cc:303
#28 0x0000564ecb4f849e in pfs_spawn_thread (arg=0x564ed08d3110) at /work/mysql/src/storage/perfschema/pfs.cc:3043
#29 0x00007fe4633bcb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#30 0x00007fe46344ea00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

CREATE USER:
Thread 38 (Thread 0x7fe44c4f4640 (LWP 528015) "connection"):
#0  __futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x564ecc078acc <Commit_stage_manager::get_instance()::shared_instance+268>) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (cancel=true, private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x564ecc078acc <Commit_stage_manager::get_instance()::shared_instance+268>) at ./nptl/futex-internal.c:87
#2  __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x564ecc078acc <Commit_stage_manager::get_instance()::shared_instance+268>, expected=expected@entry=0, clockid=clockid@entry=0, abstime=ab
stime@entry=0x0, private=private@entry=0) at ./nptl/futex-internal.c:139
#3  0x00007fe4633bbac1 in __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x564ed042b818, cond=0x564ecc078aa0 <Commit_stage_manager::get_instance()::shared_instance+224>) at ./nptl/pthread_cond_wait.c:
503
#4  ___pthread_cond_wait (cond=0x564ecc078aa0 <Commit_stage_manager::get_instance()::shared_instance+224>, mutex=0x564ed042b818) at ./nptl/pthread_cond_wait.c:627
#5  0x0000564eca8ecc4c in native_cond_wait (cond=0x564ecc078aa0 <Commit_stage_manager::get_instance()::shared_instance+224>, mutex=0x564ed042b818) at /work/mysql/src/include/thr_cond.h:108
#6  0x0000564eca8ecdbb in safe_cond_wait (cond=0x564ecc078aa0 <Commit_stage_manager::get_instance()::shared_instance+224>, mp=0x564ed042b7f0, file=0x564ec7386850 "/work/mysql/src/sql/rpl_commit_stage_manager.cc"
, line=355) at /work/mysql/src/mysys/thr_cond.cc:71
#7  0x0000564eca402f31 in my_cond_wait (cond=0x564ecc078aa0 <Commit_stage_manager::get_instance()::shared_instance+224>, mp=0x564ecc078b10 <Commit_stage_manager::get_instance()::shared_instance+336>, file=0x564e
c7386850 "/work/mysql/src/sql/rpl_commit_stage_manager.cc", line=355) at /work/mysql/src/include/thr_cond.h:159
#8  0x0000564eca40308c in inline_mysql_cond_wait (that=0x564ecc078aa0 <Commit_stage_manager::get_instance()::shared_instance+224>, mutex=0x564ecc078b10 <Commit_stage_manager::get_instance()::shared_instance+336>
, src_file=0x564ec7386850 "/work/mysql/src/sql/rpl_commit_stage_manager.cc", src_line=355) at /work/mysql/src/include/mysql/psi/mysql_cond.h:198
#9  0x0000564eca4048f4 in Commit_stage_manager::enroll_for (this=0x564ecc0789c0 <Commit_stage_manager::get_instance()::shared_instance>, stage=Commit_stage_manager::BINLOG_FLUSH_STAGE, thd=0x7fe39c001050, stage_
mutex=0x0, enter_mutex=0x564ecc077628 <mysql_bin_log+8>) at /work/mysql/src/sql/rpl_commit_stage_manager.cc:355
#10 0x0000564eca37fd75 in MYSQL_BIN_LOG::change_stage (this=0x564ecc077620 <mysql_bin_log>, thd=0x7fe39c001050, stage=Commit_stage_manager::BINLOG_FLUSH_STAGE, queue=0x7fe39c001050, leave_mutex=0x0, enter_mutex=
0x564ecc077628 <mysql_bin_log+8>) at /work/mysql/src/sql/binlog.cc:8696
#11 0x0000564eca380ece in MYSQL_BIN_LOG::ordered_commit (this=0x564ecc077620 <mysql_bin_log>, thd=0x7fe39c001050, all=true, skip_commit=false) at /work/mysql/src/sql/binlog.cc:8975
#12 0x0000564eca37edfb in MYSQL_BIN_LOG::commit (this=0x564ecc077620 <mysql_bin_log>, thd=0x7fe39c001050, all=true) at /work/mysql/src/sql/binlog.cc:8385
#13 0x0000564ec8f8bbcd in ha_commit_trans (thd=0x7fe39c001050, all=true, ignore_global_read_lock=false) at /work/mysql/src/sql/handler.cc:1783
#14 0x0000564ec97ced7a in trans_commit_implicit (thd=0x7fe39c001050, ignore_global_read_lock=false) at /work/mysql/src/sql/transaction.cc:339
#15 0x0000564ec8fe0168 in acl_end_trans_and_close_tables (thd=0x7fe39c001050, rollback_transaction=false) at /work/mysql/src/sql/auth/sql_user_table.cc:645
#16 0x0000564ec8fe06e7 in log_and_commit_acl_ddl (thd=0x7fe39c001050, transactional_tables=true, extra_users=0x7fe44c4ed480, rewrite_params=0x7fe44c4ed430, extra_error=false, write_to_binlog=true) at /work/mysql
/src/sql/auth/sql_user_table.cc:768
#17 0x0000564ec8fd94a2 in mysql_create_user (thd=0x7fe39c001050, list=..., if_not_exists=false, is_role=false) at /work/mysql/src/sql/auth/sql_user.cc:2918
#18 0x0000564ec95fd5dd in mysql_execute_command (thd=0x7fe39c001050, first_level=true) at /work/mysql/src/sql/sql_parse.cc:4025
#19 0x0000564ec9602107 in dispatch_sql_command (thd=0x7fe39c001050, parser_state=0x7fe44c4f29b0) at /work/mysql/src/sql/sql_parse.cc:5447
#20 0x0000564ec95f752b in dispatch_command (thd=0x7fe39c001050, com_data=0x7fe44c4f3300, command=COM_QUERY) at /work/mysql/src/sql/sql_parse.cc:2112
#21 0x0000564ec95f53cb in do_command (thd=0x7fe39c001050) at /work/mysql/src/sql/sql_parse.cc:1459
#22 0x0000564ec9856f95 in handle_connection (arg=0x564ed08d2480) at /work/mysql/src/sql/conn_handler/connection_handler_per_thread.cc:303
#23 0x0000564ecb4f849e in pfs_spawn_thread (arg=0x564ed08a8ff0) at /work/mysql/src/storage/perfschema/pfs.cc:3043
#24 0x00007fe4633bcb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#25 0x00007fe46344ea00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

LOG WRITER:

Thread 16 (Thread 0x7fe4167fc640 (LWP 527944) "ib_log_writer"):
#0  0x00007fe46340d868 in __GI___clock_nanosleep (clock_id=clock_id@entry=0, flags=flags@entry=0, req=0x7fe4167fb4e0, rem=0x7fe4167fb4e0) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:78
#1  0x00007fe4634126e7 in __GI___nanosleep (req=<optimized out>, rem=<optimized out>) at ../sysdeps/unix/sysv/linux/nanosleep.c:25
#2  0x0000564ec9406b30 in std::this_thread::sleep_for<long, std::ratio<1l, 1000l> > (__rtime=...) at /usr/include/c++/11/bits/this_thread_sleep.h:82
#3  0x0000564ecae69382 in log_writer_wait_on_consumers (log=..., next_write_lsn=139356240) at /work/mysql/src/storage/innobase/log/log0write.cc:2098
#4  0x0000564ecae69c69 in log_writer_write_buffer (log=..., next_write_lsn=139356240) at /work/mysql/src/storage/innobase/log/log0write.cc:2182
#5  0x0000564ecae6a3c8 in log_writer (log_ptr=0x7fe451d7f780) at /work/mysql/src/storage/innobase/log/log0write.cc:2292
#6  0x0000564ecae2e767 in std::__invoke_impl<void, void (*&)(log_t*), log_t*&> (__f=@0x7fe4167fb9d0: 0x564ecae6a0b0 <log_writer(log_t*)>) at /usr/include/c++/11/bits/invoke.h:61
#7  0x0000564ecae2e6c1 in std::__invoke<void (*&)(log_t*), log_t*&> (__fn=@0x7fe4167fb9d0: 0x564ecae6a0b0 <log_writer(log_t*)>) at /usr/include/c++/11/bits/invoke.h:96
#8  0x0000564ecae2e5e1 in std::_Bind<void (*(log_t*))(log_t*)>::__call<void, , 0ul>(std::tuple<>&&, std::_Index_tuple<0ul>) (this=0x7fe4167fb9d0, __args=...) at /usr/include/c++/11/functional:420
#9  0x0000564ecae2e519 in std::_Bind<void (*(log_t*))(log_t*)>::operator()<, void>() (this=0x7fe4167fb9d0) at /usr/include/c++/11/functional:503
#10 0x0000564ecae2e42f in Detached_thread::operator()<void (*)(log_t*), log_t*> (this=0x7fe452630128, f=@0x7fe452630120: 0x564ecae6a0b0 <log_writer(log_t*)>) at /work/mysql/src/storage/innobase/include/os0thread-create.h:194
#11 0x0000564ecae2e2dd in std::__invoke_impl<void, Detached_thread, void (*)(log_t*), log_t*> (__f=...) at /usr/include/c++/11/bits/invoke.h:61
#12 0x0000564ecae2e202 in std::__invoke<Detached_thread, void (*)(log_t*), log_t*> (__fn=...) at /usr/include/c++/11/bits/invoke.h:96
#13 0x0000564ecae2e121 in std::thread::_Invoker<std::tuple<Detached_thread, void (*)(log_t*), log_t*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x7fe452630118) at /usr/include/c++/11/bits/std_thread.h:259
#14 0x0000564ecae2e0ba in std::thread::_Invoker<std::tuple<Detached_thread, void (*)(log_t*), log_t*> >::operator() (this=0x7fe452630118) at /usr/include/c++/11/bits/std_thread.h:266
#15 0x0000564ecae2e09a in std::thread::_State_impl<std::thread::_Invoker<std::tuple<Detached_thread, void (*)(log_t*), log_t*> > >::_M_run (this=0x7fe452630110) at /usr/include/c++/11/bits/std_thread.h:211
#16 0x00007fe463733253 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#17 0x00007fe4633bcb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#18 0x00007fe46344ea00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

After this point, the server can no longer accept new connections.

Hi Mr. Altmann,

Thank you for your bug report.

However, this is a forum which requires fully repeatable test cases. Such a test case should consist only of a set of SQL statement and it can include configuration variables.

It can not be based on the call to specific functions, nor on the usage of commercial products, like MEB.

That being said, we do not doubt that you have experienced what you reported. it is only that we require a test case as described above.

We can also accept a report based on the code analysis.

When you send us such a test case, we shall be happy to proceed with the processing of your very interesting report.

> this is a forum which requires fully repeatable test cases. Such a test case should consist only of a set of SQL statement and it can include configuration variables.

This has been provided in the "how to repeat section".

> We can also accept a report based on the code analysis.

Code analyses have been explained in the Description section. There is a chain of events that leads to an internal deadlock.

Percona Xtrabackup uses the server redo consumer UDF exposed since MySQL 8.0.30.
Even though this forum is not for commercial products such as MEB, I believe that  PXB and MEB similarly consume the UDF, meaning that you might be interested in verifying this server bug, as someone using MEB with registering redo log consumer might cause the source server to reach an unresponsive and unrecoverable state.

Hi Mr. Altmann,

Once again, thank you.

However, this is a forum which requires fully repeatable test cases.
Such a test case should consist only of a set of SQL statement and it
can include configuration variables.

It can not be based on the call to specific functions, nor on the usage
of products that are not a part of Oracle's MySQL range.

Your how-to-repeat does not have any test case, only the stacktraces.

Can't repeat.

Hi Marcelo Altmann,
thanks for a detailed description of this interesting deadlock.
Have you considered increasing innodb_redo_log_capacity, as the error message says?

Hi Jakub,

Indeed having more room in redo log so the writer thread does not wait will mitigate the issue.
This has been found by our QA team while testing Xtrabackup against Oracle MySQL under a high write load. Sporadically we got this issue and the investigation unveiled this deadlock.

One way I think this can be fixed is by making the consumer inherit something like lock_wait_timeout and in case the advance call hangs for more than this time, the server automatically unregister the consumer.

Hi Marcelo Altmann,

To clarify, I did't mean setting large innodb_redo_log_capacity BEFORE starting the backup (although, obviously, it could help, too), but rather AFTER the error message has appeared, as a remedy to it.
The innodb_redo_log_capacity is dynamic sysvar, and AFAICT the design permits SETting its value even during such a deadlock, precisely to allow the operator to resolve an issue like this one.
That is, if you monitor the error log, and notice MY-013934 error in it, you can try (at least temporarily) increase the innodb_redo_log_capacity.

I don't think we can forcefully deregister a consumer, because that would violate the contract and cause even more problems down the line - in particular if the redo log consumer's job is to persist redo logs to some kind of archive/backup/stream, then violating the contract might mean the redo logs will be lost forever, which depending on use case can have catastrophic consequences.

May I ask why do you CREATE USER during taking the backup?

Hi Jakub,

> To clarify, I did't mean setting large innodb_redo_log_capacity

Good point. It does unfreeze the chain of deadlocks, however, at this point you need an already established connection, as new connections are blocked waiting for the acquire a mutex.

> I don't think we can forcefully deregister a consumer,

Indeed, I agree we will be breaking the contract here.

> May I ask why do you CREATE USER during taking the backup?

QA utilizes pstress https://github.com/Percona-QA/pstress to generate random load during the backup. In some runs, CREATE user is part of the test workload.

Hi Mr. Altmann,

After further analysis, we have discovered where is the problem in our code.

Hence, this report is now a verified bug.

Posted by developer:
 
Fixed as of the upcoming MySQL Server 8.4.0 release, and here's the proposed changelog entry from the documentation team:

The redo log consumer could not advance if capacity was full and another
thread was executing USER-related operations such as CREATE USER. This
also blocked new connections, which potentially prevented the workaround
solution of increasing innodb_redo_log_capacity size.

Thank you for the bug report.

Thank you, Mr. Olson.