server
server copied to clipboard
Published
20 hours ago •
MariaDB
MariaDB
MDEV-36301 SET GLOBAL innodb_log_file_disabled, innodb_log_group_home_dir
- [x] The Jira issue number for this PR is: MDEV-36301
Description
innodb_log_file_disabled: A new Boolean settable global parameter, for disabling the InnoDB redo log. When set, the server is not crash safe.
innodb_log_group_home_dir: Allow the value to be changed with SET GLOBAL, as long as the log remains in the same file system or innodb_log_file_disabled=ON was set.
innodb_log_update(): A common function for implementing SET GLOBAL innodb_log_file_size, innodb_log_file_disabled, innodb_log_checkpoint_now, innodb_log_group_home_dir.
log_sys.buf_size_requested: The configured innodb_log_buffer_size. While the log is disabled, we may set log_sys.buf_size (the actual size) differently.
log_sys.disabled: The current setting of innodb_log_file_disabled.
log_t::attach(): Handle log_sys.disabled.
log_t::disable(): Implements SET innodb_log_file_disabled=ON. Even if the log used to be in persistent memory, here we will set up dummy log_sys.buf and log_sys.flush_buf so that the dummy writes will appear to use file based writes.
log_t::skip_write_buf(): A dummy log writer implementation that is used when log_sys.disabled holds and the log is not being resized.
log_t::resize_abort(): When the log remains disabled, "persist" all the log, just like log_t::disable() does.
log_t::resize_start(): Handle log_sys.disabled, that is, SET GLOBAL innodb_log_file_disabled=OFF when the redo log had previously been disabled. If we are on persistent memory, we will "fake" the dummy log_sys.buf to appear as memory-mapped as well, so that log_t::resize_write() and log_t::resize_write_buf() can assume that both log files are of the same type (memory-mapped or file-based). The dummy log_sys.flush_buf will be stored in log_sys.resize_flush_buf in that case. When moving from memory-mapped to a regular log file, we will allocate log_sys.checkpoint_buf. It will be freed in log_t::close().
log_t::resize_rename(): When innodb_log_group_home_dir is changed between file systems, handle the non-atomic replacement of the log file in a special way. For a moment, a recoverable ib_logfile0 will exist in both locations.
log_resize_release_group(): Release the group write and flush locks.
log_resize_acquire(): Return whether the group locks were elided.
How can this PR be tested?
See the modified test cases. Additionally, SET GLOBAL innodb_log_group_home_dir was tested between file systems.
Basing the PR against the correct MariaDB version
- [x] This is a new feature or a refactoring, and the PR is based against the
mainbranch. - [ ] This is a bug fix, and the PR is based against the earliest maintained branch in which the bug can be reproduced.
For now, this includes the dependencies #3925 and #4038, because they have not been merged into the main branch yet.
PR quality check
- [x] I checked the CODING_STANDARDS.md file and my PR conforms to this where appropriate.
- [ ] For any trivial modifications to the PR, I am ok with the reviewer making the changes themselves.
Thank you for your submission! We really appreciate it. Like many open source projects, we ask that you sign our Contributor License Agreement before we can accept your contribution.
You have signed the CLA already but the status is still pending? Let us recheck it.
I am seeing a crash here is the stacktrace:-
Assertion:- mysqld: /home/saahil/MDEV-36301/storage/innobase/log/log0log.cc:743: log_t::resize_start_status log_t::resize_start(os_offset_t, const char *, void *): Assertion `disabled == (writer == skip_write_buf)' failed.
# 2025-05-12T12:17:57 [95729] Thread 1 (Thread 0x1543ed5696c0 (LWP 95741)):
# 2025-05-12T12:17:57 [95729] #0 0x0000000070000002 in ?? ()
# 2025-05-12T12:17:57 [95729] #1 0x00001543fae081e8 in _raw_syscall () at /home/roel/rr/src/preload/raw_syscall.S:120
# 2025-05-12T12:17:57 [95729] #2 0x00001543fae02fb9 in traced_raw_syscall (call=0x1543c83fffa0) at /home/roel/rr/src/preload/syscallbuf.c:379
# 2025-05-12T12:17:57 [95729] #3 0x00001543fae05f38 in sys_setsockopt (call=<optimized out>) at /home/roel/rr/src/preload/syscallbuf.c:3461
# 2025-05-12T12:17:57 [95729] #4 syscall_hook_internal (call=0x1543c83fffa0) at /home/roel/rr/src/preload/syscallbuf.c:4282
# 2025-05-12T12:17:57 [95729] #5 syscall_hook (call=0x1543c83fffa0) at /home/roel/rr/src/preload/syscallbuf.c:4387
# 2025-05-12T12:17:57 [95729] #6 syscall_hook (call=0x1543c83fffa0) at /home/roel/rr/src/preload/syscallbuf.c:4371
# 2025-05-12T12:17:57 [95729] #7 0x00001543fae022e3 in _syscall_hook_trampoline () at /home/roel/rr/src/preload/syscall_hook.S:308
# 2025-05-12T12:17:57 [95729] #8 0x00001543fae0234d in __morestack () at /home/roel/rr/src/preload/syscall_hook.S:443
# 2025-05-12T12:17:57 [95729] #9 0x00001543fae02354 in _syscall_hook_trampoline_48_3d_01_f0_ff_ff () at /home/roel/rr/src/preload/syscall_hook.S:457
# 2025-05-12T12:17:57 [95729] #10 0x00001543f9c45541 in __GI_kill () at ../sysdeps/unix/syscall-template.S:120
# 2025-05-12T12:17:57 [95729] #11 0x000055b37166df76 in handle_fatal_signal (sig=6) at /home/saahil/MDEV-36301/sql/signal_handler.cc:310
# 2025-05-12T12:17:57 [95729] #12 <signal handler called>
# 2025-05-12T12:17:57 [95729] #13 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
# 2025-05-12T12:17:57 [95729] #14 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
# 2025-05-12T12:17:57 [95729] #15 __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
# 2025-05-12T12:17:57 [95729] #16 0x00001543f9c4527e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
# 2025-05-12T12:17:57 [95729] #17 0x00001543f9c288ff in __GI_abort () at ./stdlib/abort.c:79
# 2025-05-12T12:17:57 [95729] #18 0x00001543f9c2881b in __assert_fail_base (fmt=0x1543f9dd01e8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55b371e1e921 "disabled == (writer == skip_write_buf)", file=file@entry=0x55b371e1e2e2 "/home/saahil/MDEV-36301/storage/innobase/log/log0log.cc", line=line@entry=743, function=function@entry=0x55b371e1e8c0 "log_t::resize_start_status log_t::resize_start(os_offset_t, const char *, void *)") at ./assert/assert.c:96
# 2025-05-12T12:17:57 [95729] #19 0x00001543f9c3b517 in __assert_fail (assertion=0x55b371e1e921 "disabled == (writer == skip_write_buf)", file=0x55b371e1e2e2 "/home/saahil/MDEV-36301/storage/innobase/log/log0log.cc", line=743, function=0x55b371e1e8c0 "log_t::resize_start_status log_t::resize_start(os_offset_t, const char *, void *)") at ./assert/assert.c:105
# 2025-05-12T12:17:57 [95729] #20 0x000055b37197d244 in log_t::resize_start (this=0x55b372f7ff00 <log_sys>, size=100663296, dir=0x55b3738c3978 "./", thd=0x1543d80fea48) at /home/saahil/MDEV-36301/storage/innobase/log/log0log.cc:743
# 2025-05-12T12:17:57 [95729] #21 0x000055b371907f9b in innodb_log_file_update (thd=0x1543d80fea48) at /home/saahil/MDEV-36301/storage/innobase/handler/ha_innodb.cc:18756
# 2025-05-12T12:17:57 [95729] #22 0x000055b371406f7d in sys_var_pluginvar::global_update (this=0x55b3738a77d0, thd=0x1543d80fea48, var=<optimized out>) at /home/saahil/MDEV-36301/sql/sql_plugin.cc:3683
# 2025-05-12T12:17:57 [95729] #23 0x000055b3713161fe in sys_var::update (this=this@entry=0x55b3738a77d0, thd=0x1543d80fea48, var=var@entry=0x1543d810d970) at /home/saahil/MDEV-36301/sql/set_var.cc:209
# 2025-05-12T12:17:57 [95729] #24 0x000055b371317834 in set_var::update (this=0x1543d810d970, thd=<optimized out>) at /home/saahil/MDEV-36301/sql/set_var.cc:868
# 2025-05-12T12:17:57 [95729] #25 0x000055b371317399 in sql_set_variables (thd=thd@entry=0x1543d80fea48, var_list=var_list@entry=0x1543d8103ca8, free=true) at /home/saahil/MDEV-36301/sql/set_var.cc:749
# 2025-05-12T12:17:57 [95729] #26 0x000055b3713e45e4 in mysql_execute_command (thd=thd@entry=0x1543d80fea48, is_called_from_prepared_stmt=<optimized out>) at /home/saahil/MDEV-36301/sql/sql_parse.cc:5158
# 2025-05-12T12:17:57 [95729] #27 0x000055b3713dd82e in mysql_parse (thd=thd@entry=0x1543d80fea48, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1543ed568440) at /home/saahil/MDEV-36301/sql/sql_parse.cc:8179
# 2025-05-12T12:17:57 [95729] #28 0x000055b3713dbd05 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1543d80fea48, packet=packet@entry=0x1543d81056c9 "SET GLOBAL innodb_log_file_disabled = OFF /* QNO 887 CON_ID 9 */ ", packet_length=packet_length@entry=65, blocking=true) at /home/saahil/MDEV-36301/sql/sql_parse.cc:1905
# 2025-05-12T12:17:57 [95729] #29 0x000055b3713ddc80 in do_command (thd=thd@entry=0x1543d80fea48, blocking=<optimized out>) at /home/saahil/MDEV-36301/sql/sql_parse.cc:1418
# 2025-05-12T12:17:57 [95729] #30 0x000055b3715218dd in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55b373cc8db8, put_in_cache=true) at /home/saahil/MDEV-36301/sql/sql_connect.cc:1386
# 2025-05-12T12:17:57 [95729] #31 0x000055b3715216de in handle_one_connection (arg=0x55b373cc8db8) at /home/saahil/MDEV-36301/sql/sql_connect.cc:1298
# 2025-05-12T12:17:57 [95729] #32 0x00001543f9c9caa4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
# 2025-05-12T12:17:57 [95729] #33 0x00001543f9d29a34 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
# 2025-05-12T12:17:57 [95729] Test completed with failure status STATUS_SERVER_CRASHED (101)
Attaching mysql.log file and rr trace path mysql.log
/home/saahil/.local/share/rr/mysqld-0
sofia machine- 172.20.0.163
Incorrect inputs getting executed for the variable :-
MariaDB [test]> set global innodb_log_file_disabled =ON , innodb_log_file_disabled =-0; Query OK, 0 rows affected (0.000 sec)
created a jira bug ticket: https://jira.mariadb.org/browse/MDEV-36803
Incorrect inputs getting executed for the variable :-
MariaDB [test]> set global innodb_log_file_disabled =ON , innodb_log_file_disabled =-0; Query OK, 0 rows affected (0.000 sec)
This is something in the option parsing code outside InnoDB. I assume that -0 would be interpreted as OFF.
Assertion found on RQG testing origin/MDEV-36301 1700b6f5b4462e742dbaaf59266865c863ef1d92 2025-05-19T08:48:36+03:00
InnoDB: Assertion failure in file /data/Server/MDEV-36301A/storage/innobase/buf/buf0buf.cc line 1192 InnoDB: Failing assertion: !block->n_hash_helps
__pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
warning: 44 ./nptl/pthread_kill.c: No such file or directory
(rr) set print addr off
(rr) bt
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 __GI_abort () at ./stdlib/abort.c:79
#5 ut_dbg_assertion_failed (expr=expr@entry="!block->n_hash_helps", file=file@entry="/data/Server/MDEV-36301A/storage/innobase/buf/buf0buf.cc", line=line@entry=1192)
at /data/Server/MDEV-36301A/storage/innobase/ut/ut0dbg.cc:60
#6 buf_block_init_low (block=block@entry=) at /data/Server/MDEV-36301A/storage/innobase/buf/buf0buf.cc:1192
#7 buf_block_t::initialise (this=this@entry=, page_id=page_id@entry=..., zip_size=zip_size@entry=0, fix=fix@entry=1) at /data/Server/MDEV-36301A/storage/innobase/buf/buf0buf.cc:3012
#8 buf_page_create_low (page_id=..., zip_size=zip_size@entry=0, mtr=mtr@entry=, free_block=free_block@entry=) at /data/Server/MDEV-36301A/storage/innobase/buf/buf0buf.cc:3027
#9 buf_page_create (space=space@entry=, offset=offset@entry=3, zip_size=0, mtr=mtr@entry=, free_block=free_block@entry=) at /data/Server/MDEV-36301A/storage/innobase/buf/buf0buf.cc:3227
#10 fsp_page_create (space=space@entry=, offset=offset@entry=3, mtr=mtr@entry=) at /data/Server/MDEV-36301A/storage/innobase/fsp/fsp0fsp.cc:1063
#11 fsp_alloc_free_page (space=space@entry=, hint=<optimized out>, hint@entry=0, mtr=mtr@entry=, init_mtr=init_mtr@entry=, err=err@entry=)
at /data/Server/MDEV-36301A/storage/innobase/fsp/fsp0fsp.cc:1187
#12 fseg_alloc_free_page_low (space=space@entry=, seg_inode=seg_inode@entry="", iblock=, hint=hint@entry=0, direction=direction@entry=111 'o',
has_done_reservation=has_done_reservation@entry=false, mtr=, init_mtr=, err=) at /data/Server/MDEV-36301A/storage/innobase/fsp/fsp0fsp.cc:2177
#13 fseg_create (space=space@entry=, byte_offset=byte_offset@entry=84, mtr=mtr@entry=, err=err@entry=, has_done_reservation=has_done_reservation@entry=false, block=block@entry=)
at /data/Server/MDEV-36301A/storage/innobase/fsp/fsp0fsp.cc:1765
#14 btr_create (type=<optimized out>, space=, index_id=5577, index=index@entry=, mtr=mtr@entry=, err=err@entry=) at /data/Server/MDEV-36301A/storage/innobase/btr/btr0btr.cc:977
#15 dict_create_index_tree_step (node=node@entry=) at /data/Server/MDEV-36301A/storage/innobase/dict/dict0crea.cc:790
#16 dict_create_index_step (thr=thr@entry=) at /data/Server/MDEV-36301A/storage/innobase/dict/dict0crea.cc:1251
#17 que_thr_step (thr=thr@entry=) at /data/Server/MDEV-36301A/storage/innobase/que/que0que.cc:563
#18 que_run_threads_low (thr=thr@entry=) at /data/Server/MDEV-36301A/storage/innobase/que/que0que.cc:609
#19 que_run_threads (thr=thr@entry=) at /data/Server/MDEV-36301A/storage/innobase/que/que0que.cc:629
#20 row_create_index_for_mysql (index=<optimized out>, index@entry=, trx=trx@entry=, field_lengths=field_lengths@entry=, mode=mode@entry=FIL_ENCRYPTION_DEFAULT, key_id=key_id@entry=1)
at /data/Server/MDEV-36301A/storage/innobase/row/row0mysql.cc:2155
#21 fts_create_one_index_table (trx=trx@entry=, index=index@entry=, fts_table=fts_table@entry=, heap=heap@entry=) at /data/Server/MDEV-36301A/storage/innobase/fts/fts0fts.cc:2054
#22 fts_create_index_tables (trx=trx@entry=, index=, id=<optimized out>) at /data/Server/MDEV-36301A/storage/innobase/fts/fts0fts.cc:2105
#23 row_create_index_for_mysql (index=<optimized out>, index@entry=, trx=trx@entry=, field_lengths=field_lengths@entry=, mode=<optimized out>, key_id=1)
at /data/Server/MDEV-36301A/storage/innobase/row/row0mysql.cc:2164
#24 create_index (trx=, form=, table=, key_num=key_num@entry=3) at /data/Server/MDEV-36301A/storage/innobase/handler/ha_innodb.cc:10988
#25 create_table_info_t::create_table (this=this@entry=, create_fk=create_fk@entry=false, strict=true) at /data/Server/MDEV-36301A/storage/innobase/handler/ha_innodb.cc:12889
#26 ha_innobase::create (this=this@entry=, name=name@entry="test/t3", form=, create_info=create_info@entry=, file_per_table=<optimized out>, trx=trx@entry=)
at /data/Server/MDEV-36301A/storage/innobase/handler/ha_innodb.cc:13310
#27 ha_innobase::truncate (this=) at /data/Server/MDEV-36301A/storage/innobase/handler/ha_innodb.cc:14053
#28 handler::ha_truncate (this=) at /data/Server/MDEV-36301A/sql/handler.cc:5547
#29 Sql_cmd_truncate_table::handler_truncate (this=this@entry=, thd=thd@entry=, table_ref=table_ref@entry=, is_tmp_table=is_tmp_table@entry=false)
at /data/Server/MDEV-36301A/sql/sql_truncate.cc:251
#30 Sql_cmd_truncate_table::truncate_table (this=this@entry=, thd=thd@entry=, table_ref=table_ref@entry=) at /data/Server/MDEV-36301A/sql/sql_truncate.cc:536
#31 Sql_cmd_truncate_table::execute (this=, thd=) at /data/Server/MDEV-36301A/sql/sql_truncate.cc:602
#32 mysql_execute_command (thd=thd@entry=, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/MDEV-36301A/sql/sql_parse.cc:5861
#33 mysql_parse (thd=thd@entry=, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=) at /data/Server/MDEV-36301A/sql/sql_parse.cc:7891
#34 dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=, packet=packet@entry=" TRUNCATE TABLE t3 /* E_R Thread4 QNO 1760 CON_ID 122 */ ",
packet_length=packet_length@entry=58, blocking=blocking@entry=true) at /data/Server/MDEV-36301A/sql/sql_parse.cc:1877
#35 do_command (thd=thd@entry=, blocking=blocking@entry=true) at /data/Server/MDEV-36301A/sql/sql_parse.cc:1416
#36 do_handle_one_connection (connect=<optimized out>, connect@entry=, put_in_cache=put_in_cache@entry=true) at /data/Server/MDEV-36301A/sql/sql_connect.cc:1414
#37 handle_one_connection (arg=) at /data/Server/MDEV-36301A/sql/sql_connect.cc:1326
#38 start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
#39 clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
RR trace is present on SDP machine:-
/data/results/1747808608/TBR-2280_rr/ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio
Hitting this Assertion on latest commit :-origin/MDEV-36301 8ce4b1ac924bd15c739c8e055418f792b3ef4f63 2025-05-22T10:33:56+03:00
mariadbd: /data/Server/MDEV-36301B/storage/innobase/log/log0log.cc:1286: lsn_t log_t::write_buf() [with resizing_and_latch resizing = log_t::RESIZING; lsn_t = long unsigned int]: Assertion `!is_mmap()' failed.
Stacktrace:
Download failed: Invalid argument. Continuing without source file ./nptl/./nptl/pthread_kill.c.
__pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
warning: 44 ./nptl/pthread_kill.c: No such file or directory
(rr) set print addr off
(rr) bt
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 __GI_abort () at ./stdlib/abort.c:79
#5 __assert_fail_base (fmt="%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry="!is_mmap()",
file=file@entry="/data/Server/MDEV-36301B/storage/innobase/log/log0log.cc", line=line@entry=1286,
function=function@entry="lsn_t log_t::write_buf() [with resizing_and_latch resizing = log_t::RESIZING; lsn_t = long unsigned int]") at ./assert/assert.c:94
#6 __assert_fail (assertion="!is_mmap()", file="/data/Server/MDEV-36301B/storage/innobase/log/log0log.cc", line=1286,
function="lsn_t log_t::write_buf() [with resizing_and_latch resizing = log_t::RESIZING; lsn_t = long unsigned int]") at ./assert/assert.c:103
#7 log_t::write_buf<(log_t::resizing_and_latch)2> (this=<log_sys>) at /data/Server/MDEV-36301B/storage/innobase/log/log0log.cc:1286
#8 log_writer_resizing () at /data/Server/MDEV-36301B/storage/innobase/log/log0log.cc:1502
#9 log_write_up_to (lsn=8927009, durable=durable@entry=true, callback=<optimized out>, callback@entry=)
at /data/Server/MDEV-36301B/storage/innobase/log/log0log.cc:1478
#10 log_buffer_flush_to_disk (durable=durable@entry=true) at /data/Server/MDEV-36301B/storage/innobase/log/log0log.cc:1517
#11 srv_sync_log_buffer_in_background () at /data/Server/MDEV-36301B/storage/innobase/srv/srv0srv.cc:1238
#12 srv_master_callback () at /data/Server/MDEV-36301B/storage/innobase/srv/srv0srv.cc:1291
#13 tpool::thread_pool_generic::timer_generic::run (this=) at /data/Server/MDEV-36301B/tpool/tpool_generic.cc:336
#14 tpool::thread_pool_generic::timer_generic::execute (arg=<optimized out>) at /data/Server/MDEV-36301B/tpool/tpool_generic.cc:356
#15 tpool::task::execute (this=) at /data/Server/MDEV-36301B/tpool/task.cc:37
#16 tpool::thread_pool_generic::worker_main (this=, thread_var=) at /data/Server/MDEV-36301B/tpool/tpool_generic.cc:574
#17 std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=<optimized out>,
__t=<optimized out>) at /usr/include/c++/13/bits/invoke.h:74
#18 std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=<optimized out>)
at /usr/include/c++/13/bits/invoke.h:90
#19 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=<optimized out>) at /usr/include/c++/13/bits/std_thread.h:292
#20 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (
this=<optimized out>) at /usr/include/c++/13/bits/std_thread.h:299
#21 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=<optimized out>) at /usr/include/c++/13/bits/std_thread.h:244
#22 ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#23 start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
#24 clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
RR trace is present on SDP machine- /data/results/1748001679/TBR-2277_1
origin/MDEV-36301 2ca4fefe874fccfd48f505a782562a1d991cef45 2025-05-26T15:49:45+03:00
Got a Assertion during RQG test run on latest MDEV-36301 :-
# 2025-05-26T15:18:25 [1033153] | mariadbd: /data/Server/MDEV-36301C/storage/innobase/log/log0log.cc:1423: bool log_t::flush(lsn_t): Assertion `lsn >= get_flushed_lsn()' failed
Stacktrace:-
0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 __GI_abort () at ./stdlib/abort.c:79
#5 __assert_fail_base (fmt="%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry="lsn >= get_flushed_lsn()", file=file@entry="/data/Server/MDEV-36301C/storage/innobase/log/log0log.cc", line=line@entry=1423,
function=function@entry="bool log_t::flush(lsn_t)") at ./assert/assert.c:94
#6 __assert_fail (assertion="lsn >= get_flushed_lsn()", file="/data/Server/MDEV-36301C/storage/innobase/log/log0log.cc", line=1423, function="bool log_t::flush(lsn_t)") at ./assert/assert.c:103
#7 log_t::flush (this=this@entry=<log_sys>, lsn=lsn@entry=19345244) at /data/Server/MDEV-36301C/storage/innobase/log/log0log.cc:1423
#8 log_flush (lsn=19345244) at /data/Server/MDEV-36301C/storage/innobase/log/log0log.cc:1443
#9 log_write_up_to (lsn=19345244, durable=durable@entry=true, callback=<optimized out>, callback@entry=) at /data/Server/MDEV-36301C/storage/innobase/log/log0log.cc:1506
#10 log_buffer_flush_to_disk (durable=durable@entry=true) at /data/Server/MDEV-36301C/storage/innobase/log/log0log.cc:1539
#11 srv_sync_log_buffer_in_background () at /data/Server/MDEV-36301C/storage/innobase/srv/srv0srv.cc:1238
#12 srv_master_callback () at /data/Server/MDEV-36301C/storage/innobase/srv/srv0srv.cc:1291
#13 tpool::thread_pool_generic::timer_generic::run (this=) at /data/Server/MDEV-36301C/tpool/tpool_generic.cc:336
#14 tpool::thread_pool_generic::timer_generic::execute (arg=<optimized out>) at /data/Server/MDEV-36301C/tpool/tpool_generic.cc:356
#15 tpool::task::execute (this=) at /data/Server/MDEV-36301C/tpool/task.cc:37
#16 tpool::thread_pool_generic::worker_main (this=, thread_var=) at /data/Server/MDEV-36301C/tpool/tpool_generic.cc:574
#17 std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=<optimized out>, __t=<optimized out>) at /usr/include/c++/13/bits/invoke.h:74
#18 std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=<optimized out>) at /usr/include/c++/13/bits/invoke.h:90
#19 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=<optimized out>)
at /usr/include/c++/13/bits/std_thread.h:292
#20 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=<optimized out>) at /usr/include/c++/13/bits/std_thread.h:299
#21 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=<optimized out>)
at /usr/include/c++/13/bits/std_thread.h:244
#22 ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#23 start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
#24 clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
RR trace is present at SDP machine: /data/results/1748293310/TBR-2286
origin/MDEV-36301 2ca4fefe874fccfd48f505a782562a1d991cef45 2025-05-26T15:49:45+03:00
Got a Assertion during RQG test run on latest MDEV-36301 :-
mariadbd: /data/Server/MDEV-36301C/storage/innobase/buf/buf0flu.cc:2355: ulint page_cleaner_flush_pages_recommendation(ulint, lsn_t, double, ulint, double): Assertion `oldest_lsn <= cur_lsn' failed.
StackTrace:-
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 __GI_abort () at ./stdlib/abort.c:79
#5 __assert_fail_base (fmt="%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry="oldest_lsn <= cur_lsn", file=file@entry="/data/Server/MDEV-36301C/storage/innobase/buf/buf0flu.cc", line=line@entry=2355,
function=function@entry="ulint page_cleaner_flush_pages_recommendation(ulint, lsn_t, double, ulint, double)") at ./assert/assert.c:94
#6 __assert_fail (assertion="oldest_lsn <= cur_lsn", file="/data/Server/MDEV-36301C/storage/innobase/buf/buf0flu.cc", line=2355, function="ulint page_cleaner_flush_pages_recommendation(ulint, lsn_t, double, ulint, double)")
at ./assert/assert.c:103
#7 page_cleaner_flush_pages_recommendation (last_pages_in=last_pages_in@entry=0, oldest_lsn=oldest_lsn@entry=10291970, pct_lwm=pct_lwm@entry=0, dirty_blocks=<optimized out>, dirty_blocks@entry=43,
dirty_pct=dirty_pct@entry=0.26520291106451216) at /data/Server/MDEV-36301C/storage/innobase/buf/buf0flu.cc:2355
#8 buf_flush_page_cleaner () at /data/Server/MDEV-36301C/storage/innobase/buf/buf0flu.cc:2707
#9 std::__invoke_impl<void, void (*)() noexcept>(std::__invoke_other, void (*&&)() noexcept) (__f=<optimized out>) at /usr/include/c++/13/bits/invoke.h:60
#10 std::__invoke<void (*)() noexcept>(void (*&&)() noexcept) (__fn=<optimized out>) at /usr/include/c++/13/bits/invoke.h:96
#11 std::thread::_Invoker<std::tuple<void (*)() noexcept> >::_M_invoke<0ul>(std::_Index_tuple<0ul>) (this=<optimized out>) at /usr/include/c++/13/bits/std_thread.h:292
#12 std::thread::_Invoker<std::tuple<void (*)() noexcept> >::operator()() (this=<optimized out>) at /usr/include/c++/13/bits/std_thread.h:299
#13 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)() noexcept> > >::_M_run() (this=<optimized out>) at /usr/include/c++/13/bits/std_thread.h:244
#14 ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#15 start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
#16 clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
RR trace is present on SDP machine:- /data/results/1748293310/TBR-2287
origin/MDEV-36301 2ca4fefe874fccfd48f505a782562a1d991cef45 2025-05-26T15:49:45+03:00
Got a Segmentation fault during RQG test run on latest MDEV-36301 :-
StackTrace:-
# 2025-05-26T14:18:18 [3917616] | #0 pmem_clwb (buf=<optimized out>, size=1384782) at /data/Server/MDEV-36301C/storage/innobase/sync/cache.cc:53
# 2025-05-26T14:18:18 [3917616] | #1 0x0000576241cbdb02 in log_t::persist (this=this@entry=0x5762433c0940 <log_sys>, lsn=lsn@entry=46732915) at /data/Server/MDEV-36301C/storage/innobase/log/log0log.cc:1219
# 2025-05-26T14:18:18 [3917616] | #2 0x0000576241cbe8c8 in log_write_persist (lsn=lsn@entry=46732915) at /data/Server/MDEV-36301C/storage/innobase/log/log0log.cc:1239
# 2025-05-26T14:18:18 [3917616] | #3 0x0000576241cbea6f in log_write_up_to (lsn=lsn@entry=46732915, durable=true, callback=callback@entry=0x0) at /data/Server/MDEV-36301C/storage/innobase/log/log0log.cc:1466
# 2025-05-26T14:18:18 [3917616] | #4 0x0000576241dec086 in trx_prepare (trx=trx@entry=0x7f6bd9005c80) at /data/Server/MDEV-36301C/storage/innobase/trx/trx0trx.cc:1974
# 2025-05-26T14:18:18 [3917616] | #5 0x0000576241dec7e1 in trx_prepare_for_mysql (trx=trx@entry=0x7f6bd9005c80) at /data/Server/MDEV-36301C/storage/innobase/trx/trx0trx.cc:2001
# 2025-05-26T14:18:18 [3917616] | #6 0x0000576241c490da in innobase_xa_prepare (thd=0x7f6be0002868, prepare_trx=true) at /data/Server/MDEV-36301C/storage/innobase/handler/ha_innodb.cc:17212
# 2025-05-26T14:18:18 [3917616] | #7 0x00005762419f3a56 in prepare_or_error (ht=ht@entry=0x5762452e5f18, thd=thd@entry=0x7f6be0002868, all=all@entry=true) at /data/Server/MDEV-36301C/sql/handler.cc:1506
# 2025-05-26T14:18:18 [3917616] | #8 0x00005762419fffd4 in ha_commit_trans (thd=thd@entry=0x7f6be0002868, all=all@entry=true) at /data/Server/MDEV-36301C/sql/handler.cc:1979
# 2025-05-26T14:18:18 [3917616] | #9 0x000057624189f670 in trans_commit (thd=thd@entry=0x7f6be0002868) at /data/Server/MDEV-36301C/sql/transaction.cc:271
# 2025-05-26T14:18:18 [3917616] | #10 0x0000576241757c6d in mysql_execute_command (thd=thd@entry=0x7f6be0002868, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/MDEV-36301C/sql/sql_parse.cc:5490
# 2025-05-26T14:18:18 [3917616] | #11 0x000057624175969c in mysql_parse (thd=thd@entry=0x7f6be0002868, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f6bd95b33a0) at /data/Server/MDEV-36301C/sql/sql_parse.cc:7891
# 2025-05-26T14:18:18 [3917616] | #12 0x000057624175ac7e in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f6be0002868, packet=packet@entry=0x7f6be000cee9 " COMMIT /* E_R Thread6 QNO 244 CON_ID 22 */ ", packet_length=packet_length@entry=45, blocking=blocking@entry=true) at /data/Server/MDEV-36301C/sql/sql_parse.cc:1877
# 2025-05-26T14:18:18 [3917616] | #13 0x000057624175c1d4 in do_command (thd=thd@entry=0x7f6be0002868, blocking=blocking@entry=true) at /data/Server/MDEV-36301C/sql/sql_parse.cc:1416
# 2025-05-26T14:18:18 [3917616] | #14 0x000057624188e6cf in do_handle_one_connection (connect=<optimized out>, connect@entry=0x57624586e528, put_in_cache=put_in_cache@entry=true) at /data/Server/MDEV-36301C/sql/sql_connect.cc:1414
# 2025-05-26T14:18:18 [3917616] | #15 0x000057624188e8ec in handle_one_connection (arg=0x57624586e528) at /data/Server/MDEV-36301C/sql/sql_connect.cc:1326
# 2025-05-26T14:18:18 [3917616] | #16 0x00007f6beb09ca94 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
# 2025-05-26T14:18:18 [3917616] | #17 0x00007f6beb129a34 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
RR trace is present here(SDP) machine: /data/results/1748293310/TBR-2288
origin/MDEV-36301 2ca4fefe874fccfd48f505a782562a1d991cef45 2025-05-26T15:49:45+03:00 Got a Assertion during RQG test run on latest MDEV-36301 :- mariadbd: /data/Server/MDEV-36301C/storage/innobase/buf/buf0flu.cc:2355: ulint page_cleaner_flush_pages_recommendation(ulint, lsn_t, double, ulint, double): Assertion `oldest_lsn <= cur_lsn' failed.RR trace is present on SDP machine:- /data/results/1748293310/TBR-2287
I filed MDEV-36886 for this regression of #3925.
StackTrace:- # 2025-05-26T14:18:18 [3917616] | #0 pmem_clwb (buf=<optimized out>, size=1384782) at /data/Server/MDEV-36301C/storage/innobase/sync/cache.cc:53 # 2025-05-26T14:18:18 [3917616] | #1 0x0000576241cbdb02 in log_t::persist (this=this@entry=0x5762433c0940 <log_sys>, lsn=lsn@entry=46732915) at /data/Server/MDEV-36301C/storage/innobase/log/log0log.cc:1219
At this point, the memory-mapped log is being re-enabled, but it is currently disabled and we can’t trust log_sys.file_size for the memory-mapped interface. 05e7df7f8aa378544e2ab661d3d90af33ef688b1 will check log_sys.disabled in log_t::persist() to prevent this from occurring. In that way, we’ll be doing a ‘dummy write’ just fine.
origin/MDEV-36301 1f2f05f3d4eafe6335b004d7897e12ec885a3040 2025-05-27T14:12:01+03:00
Got a Assertion during RQG test runs on latest MDEV-36301
mariadbd: /data/Server/MDEV-36301D/storage/innobase/log/log0log.cc:1455: void log_t::set_flushed_lsn(lsn_t): Assertion flush_lock.is_owner()' failed
StackTrace
# 2025-05-28T01:02:24 [1937325] Thread 1 (Thread 0x7fb6bc4d36c0 (LWP 1941612)):
# 2025-05-28T01:02:24 [1937325] #0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
# 2025-05-28T01:02:24 [1937325] #1 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
# 2025-05-28T01:02:24 [1937325] #2 __GI___pthread_kill (threadid=<optimized out>, signo=6) at ./nptl/pthread_kill.c:89
# 2025-05-28T01:02:24 [1937325] #3 0x00006327d2a8c9bb in my_write_core (sig=6) at /data/Server/MDEV-36301D/mysys/stacktrace.c:424
# 2025-05-28T01:02:24 [1937325] #4 0x00006327d2521966 in handle_fatal_signal (sig=6) at /data/Server/MDEV-36301D/sql/signal_handler.cc:298
# 2025-05-28T01:02:24 [1937325] #5 <signal handler called>
# 2025-05-28T01:02:24 [1937325] #6 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
# 2025-05-28T01:02:24 [1937325] #7 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
# 2025-05-28T01:02:24 [1937325] #8 __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
# 2025-05-28T01:02:24 [1937325] #9 0x00007fb6c384526e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
# 2025-05-28T01:02:24 [1937325] #10 0x00007fb6c38288ff in __GI_abort () at ./stdlib/abort.c:79
# 2025-05-28T01:02:24 [1937325] #11 0x00007fb6c382881b in __assert_fail_base (fmt=0x7fb6c39d01e8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x6327d2d23eb1 "flush_lock.is_owner()", file=file@entry=0x6327d2c441a8 "/data/Server/MDEV-36301D/storage/innobase/log/log0log.cc", line=line@entry=1455, function=function@entry=0x6327d2c45170 "void log_t::set_flushed_lsn(lsn_t)") at ./assert/assert.c:94
# 2025-05-28T01:02:24 [1937325] #12 0x00007fb6c383b507 in __assert_fail (assertion=0x6327d2d23eb1 "flush_lock.is_owner()", file=0x6327d2c441a8 "/data/Server/MDEV-36301D/storage/innobase/log/log0log.cc", line=1455, function=0x6327d2c45170 "void log_t::set_flushed_lsn(lsn_t)") at ./assert/assert.c:103
# 2025-05-28T01:02:24 [1937325] #13 0x00006327d27f4541 in log_t::set_flushed_lsn (this=this@entry=0x6327d3ef2940 <log_sys>, lsn=lsn@entry=31212236) at /data/Server/MDEV-36301D/storage/innobase/log/log0log.cc:1455
# 2025-05-28T01:02:24 [1937325] #14 0x00006327d27efcaf in log_write_up_to (lsn=31212236, lsn@entry=31211966, durable=durable@entry=true, callback=<optimized out>, callback@entry=0x7fb6bc4d12e0) at /data/Server/MDEV-36301D/storage/innobase/log/log0log.cc:1521
# 2025-05-28T01:02:24 [1937325] #15 0x00006327d291c265 in trx_flush_log_if_needed (lsn=31211966, trx=0x7fb6bc601780) at /data/Server/MDEV-36301D/storage/innobase/trx/trx0trx.cc:1267
# 2025-05-28T01:02:24 [1937325] #16 0x00006327d291cc6e in trx_commit_complete_for_mysql (trx=trx@entry=0x7fb6bc601780) at /data/Server/MDEV-36301D/storage/innobase/trx/trx0trx.cc:1751
# 2025-05-28T01:02:24 [1937325] #17 0x00006327d2779e6f in innobase_commit (thd=0x7fb630000d58, commit_trx=false) at /data/Server/MDEV-36301D/storage/innobase/handler/ha_innodb.cc:4626
# 2025-05-28T01:02:24 [1937325] #18 0x00006327d2526784 in commit_one_phase_2 (thd=thd@entry=0x7fb630000d58, all=all@entry=false, trans=trans@entry=0x7fb6300049a0, is_real_trans=true) at /data/Server/MDEV-36301D/sql/handler.cc:2217
# 2025-05-28T01:02:24 [1937325] #19 0x00006327d253063e in ha_commit_one_phase (thd=thd@entry=0x7fb630000d58, all=all@entry=false) at /data/Server/MDEV-36301D/sql/handler.cc:2159
# 2025-05-28T01:02:24 [1937325] #20 0x00006327d2530e6e in ha_commit_trans (thd=thd@entry=0x7fb630000d58, all=all@entry=false) at /data/Server/MDEV-36301D/sql/handler.cc:1953
# 2025-05-28T01:02:24 [1937325] #21 0x00006327d23d0e7c in trans_commit_stmt (thd=thd@entry=0x7fb630000d58) at /data/Server/MDEV-36301D/sql/transaction.cc:498
# 2025-05-28T01:02:24 [1937325] #22 0x00006327d228a059 in mysql_execute_command (thd=thd@entry=0x7fb630000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/MDEV-36301D/sql/sql_parse.cc:5945
# 2025-05-28T01:02:24 [1937325] #23 0x00006327d228a69c in mysql_parse (thd=thd@entry=0x7fb630000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7fb6bc4d23a0) at /data/Server/MDEV-36301D/sql/sql_parse.cc:7891
# 2025-05-28T01:02:24 [1937325] #24 0x00006327d228bc7e in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fb630000d58, packet=packet@entry=0x7fb63000b3d9 "", packet_length=packet_length@entry=110, blocking=blocking@entry=true) at /data/Server/MDEV-36301D/sql/sql_parse.cc:1877
# 2025-05-28T01:02:24 [1937325] #25 0x00006327d228d1d4 in do_command (thd=thd@entry=0x7fb630000d58, blocking=blocking@entry=true) at /data/Server/MDEV-36301D/sql/sql_parse.cc:1416
# 2025-05-28T01:02:24 [1937325] #26 0x00006327d23bf6cf in do_handle_one_connection (connect=<optimized out>, connect@entry=0x6327d5c7f5f8, put_in_cache=put_in_cache@entry=true) at /data/Server/MDEV-36301D/sql/sql_connect.cc:1414
# 2025-05-28T01:02:24 [1937325] #27 0x00006327d23bf8ec in handle_one_connection (arg=0x6327d5c7f5f8) at /data/Server/MDEV-36301D/sql/sql_connect.cc:1326
# 2025-05-28T01:02:24 [1937325] #28 0x00007fb6c389ca94 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
# 2025-05-28T01:02:24 [1937325] #29 0x00007fb6c3929c3c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78
Core dump is present on SDP machine /data/results/1748419115/TBR-2289
origin/MDEV-36301 1f2f05f3d4eafe6335b004d7897e12ec885a3040 2025-05-27T14:12:01+03:00 Got a Assertion during RQG test runs on latest MDEV-36301 mariadbd: /data/Server/MDEV-36301D/storage/innobase/log/log0log.cc:1455: void log_t::set_flushed_lsn(lsn_t): Assertion flush_lock.is_owner()' failedCore dump is present on SDP machine /data/results/1748419115/TBR-2289
We have log_sys.disabled here, and we are in the process of enabling a memory-mapped log file. 8f486f2f74a81d568b0ae1c89f7971cbff4ed6ee moves this assertion to the appropriate place in the caller log_write_up_to(). In the memory-mapped log write path, neither write_lock nor flush_lock is normally used.
origin/MDEV-36301 8f486f2f74a81d568b0ae1c89f7971cbff4ed6ee 2025-05-28T14:14:20+03:00
Got a Assertion during RQG test runs on latest MDEV-36301
# 2025-05-28T11:23:51 [2397948] | mariadbd: /data/Server/MDEV-36301E/storage/innobase/log/log0log.cc:1516: void log_write_up_to(lsn_t, bool, const completion_callback*): Assertion `flush_lock.is_owner()' failed.
StackTrace:-
# 2025-05-28T11:25:06 [2397948] #0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
# 2025-05-28T11:25:06 [2397948] #1 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
# 2025-05-28T11:25:06 [2397948] #2 __GI___pthread_kill (threadid=<optimized out>, signo=6) at ./nptl/pthread_kill.c:89
# 2025-05-28T11:25:06 [2397948] #3 0x00005c40b024e9c9 in my_write_core (sig=6) at /data/Server/MDEV-36301E/mysys/stacktrace.c:424
# 2025-05-28T11:25:06 [2397948] #4 0x00005c40afce3966 in handle_fatal_signal (sig=6) at /data/Server/MDEV-36301E/sql/signal_handler.cc:298
# 2025-05-28T11:25:06 [2397948] #5 <signal handler called>
# 2025-05-28T11:25:06 [2397948] #6 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
# 2025-05-28T11:25:06 [2397948] #7 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
# 2025-05-28T11:25:06 [2397948] #8 __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
# 2025-05-28T11:25:06 [2397948] #9 0x00007b67a964526e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
# 2025-05-28T11:25:06 [2397948] #10 0x00007b67a96288ff in __GI_abort () at ./stdlib/abort.c:79
# 2025-05-28T11:25:06 [2397948] #11 0x00007b67a962881b in __assert_fail_base (fmt=0x7b67a97d01e8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x5c40b04e5bb2 "flush_lock.is_owner()", file=file@entry=0x5c40b04061a8 "/data/Server/MDEV-36301E/storage/innobase/log/log0log.cc", line=line@entry=1516, function=function@entry=0x5c40b0406610 "void log_write_up_to(lsn_t, bool, const completion_callback*)") at ./assert/assert.c:94
# 2025-05-28T11:25:06 [2397948] #12 0x00007b67a963b507 in __assert_fail (assertion=0x5c40b04e5bb2 "flush_lock.is_owner()", file=0x5c40b04061a8 "/data/Server/MDEV-36301E/storage/innobase/log/log0log.cc", line=1516, function=0x5c40b0406610 "void log_write_up_to(lsn_t, bool, const completion_callback*)") at ./assert/assert.c:103
# 2025-05-28T11:25:06 [2397948] #13 0x00005c40affb1d7e in log_write_up_to (lsn=lsn@entry=5438733, durable=durable@entry=true, callback=<optimized out>, callback@entry=0x0) at /data/Server/MDEV-36301E/storage/innobase/log/log0log.cc:1516
# 2025-05-28T11:25:06 [2397948] #14 0x00005c40b0138f15 in buf_dblwr_t::flush_buffered_writes_completed (this=<optimized out>, request=...) at /data/Server/MDEV-36301E/storage/innobase/buf/buf0dblwr.cc:787
# 2025-05-28T11:25:06 [2397948] #15 0x00005c40b019100a in IORequest::write_complete (this=this@entry=0x5c40b4104670, io_error=0) at /data/Server/MDEV-36301E/storage/innobase/fil/fil0fil.cc:2908
# 2025-05-28T11:25:06 [2397948] #16 0x00005c40afff3667 in write_io_callback (c=0x5c40b4104608) at /data/Server/MDEV-36301E/storage/innobase/os/os0file.cc:3063
# 2025-05-28T11:25:06 [2397948] #17 0x00005c40b01f2368 in tpool::task_group::execute (this=0x5c40b40accf0, t=t@entry=0x5c40b4104650) at /data/Server/MDEV-36301E/tpool/task_group.cc:73
# 2025-05-28T11:25:06 [2397948] #18 0x00005c40b01f2421 in tpool::task::execute (this=0x5c40b4104650) at /data/Server/MDEV-36301E/tpool/task.cc:32
# 2025-05-28T11:25:06 [2397948] #19 0x00005c40b01efa55 in tpool::thread_pool_generic::worker_main (this=0x5c40b40af9a0, thread_var=0x5c40b40bed60) at /data/Server/MDEV-36301E/tpool/tpool_generic.cc:574
# 2025-05-28T11:25:06 [2397948] #20 0x00005c40b01f1ff1 in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=<optimized out>, __t=<optimized out>) at /usr/include/c++/13/bits/invoke.h:74
# 2025-05-28T11:25:06 [2397948] #21 0x00005c40b01f200f in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=<optimized out>) at /usr/include/c++/13/bits/invoke.h:90
# 2025-05-28T11:25:06 [2397948] #22 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=<optimized out>) at /usr/include/c++/13/bits/std_thread.h:292
# 2025-05-28T11:25:06 [2397948] #23 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=<optimized out>) at /usr/include/c++/13/bits/std_thread.h:299
# 2025-05-28T11:25:06 [2397948] #24 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=<optimized out>) at /usr/include/c++/13/bits/std_thread.h:244
# 2025-05-28T11:25:06 [2397948] #25 0x00007b67a9aeabb4 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
# 2025-05-28T11:25:06 [2397948] #26 0x00007b67a969ca94 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
# 2025-05-28T11:25:06 [2397948] #27 0x00007b67a9729c3c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78
Core dump is present on SDP machine:-/data/results/1748456386/TBR-2290
MDEV-36301 CS 12.1.0 8f486f2f74a81d568b0ae1c89f7971cbff4ed6ee (Debug) Build 29/05/2025
Improper Error message when enabling and disabling innodb_log_file_disabled.
There is no entry in the logs when enabling this variable
Sql used
12.1.0-dbg>SET GLOBAL innodb_log_file_size = 201326592, innodb_log_file_disabled = OFF, innodb_log_file_disabled = ON;
Query OK, 0 rows affected (2.016 sec)
12.1.0-dbg>SET GLOBAL innodb_log_file_size = 201326592, innodb_log_file_disabled = OFF, innodb_log_file_disabled = OFF;
Query OK, 0 rows affected (1.016 sec)
12.1.0-dbg>SET GLOBAL innodb_log_file_disabled = ON;
Query OK, 0 rows affected (0.000 sec)
12.1.0-dbg>SET GLOBAL innodb_log_file_disabled = OFF;
Query OK, 0 rows affected (1.017 sec)
12.1.0-dbg>SET GLOBAL innodb_log_file_disabled = ON;
Query OK, 0 rows affected (0.000 sec)
Logs
2025-06-03 11:39:48 0 [Note] InnoDB: log sequence number 57155; transaction id 15
2025-06-03 11:39:48 0 [Note] InnoDB: Loading buffer pool(s) from /test/MDEV-36301-MD290525-mariadb-12.1.0-linux-x86_64-dbg/data/ib_buffer_pool
2025-06-03 11:39:48 0 [Note] InnoDB: Buffer pool(s) load completed at 250603 11:39:48
2025-06-03 11:39:48 0 [Note] Plugin 'FEEDBACK' is disabled.
2025-06-03 11:39:48 0 [Note] Plugin 'wsrep-provider' is disabled.
2025-06-03 11:39:49 0 [Note] Server socket created on IP: '0.0.0.0'.
2025-06-03 11:39:49 0 [Note] Server socket created on IP: '::'.
2025-06-03 11:39:49 0 [Note] mariadbd: Event Scheduler: Loaded 0 events
2025-06-03 11:39:49 0 [Note] /test/MDEV-36301-MD290525-mariadb-12.1.0-linux-x86_64-dbg/bin/mariadbd: ready for connections.
Version: '12.1.0-MariaDB-debug' socket: '/test/MDEV-36301-MD290525-mariadb-12.1.0-linux-x86_64-dbg/socket.sock' port: 10809 MariaDB Server
2025-06-03 11:40:18 0 [Note] InnoDB: Resized log to 192.000MiB; start LSN=57344
2025-06-03 11:40:19 4 [Note] InnoDB: Disabled redo log at LSN=57363
2025-06-03 11:40:43 4 [Note] InnoDB: Disabled redo log at LSN=57363
2025-06-03 11:40:43 0 [Note] InnoDB: Resized log to 192.000MiB; start LSN=57363
2025-06-03 11:41:20 4 [Note] InnoDB: Disabled redo log at LSN=57379
2025-06-03 11:41:37 0 [Note] InnoDB: Resized log to 192.000MiB; start LSN=57379
2025-06-03 11:41:52 4 [Note] InnoDB: Disabled redo log at LSN=57395
Please check if this is the expected outcome
Leads to:-
/MDEV-36301E_fast<- GIT_SHOW: HEAD -> MDEV-36301, origin/MDEV-36301 8f486f2f74a81d568b0ae1c89f7971cbff4ed6ee 2025-05-28T14:14:20+03:00
# 2025-06-03T09:06:15 [188084] | 2025-06-03 09:06:11 0x739e574006c0 InnoDB: Assertion failure in file /data/Server/MDEV-36301E/storage/innobase/log/log0sync.cc line 291
# 2025-06-03T09:06:15 [188084] | InnoDB: Failing assertion: num >= value()
Stacktrace:-
# 2025-06-03T09:06:48 [188084] #0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
# 2025-06-03T09:06:48 [188084] #1 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
# 2025-06-03T09:06:48 [188084] #2 __GI___pthread_kill (threadid=<optimized out>, signo=6) at ./nptl/pthread_kill.c:89
# 2025-06-03T09:06:48 [188084] #3 0x0000626ed89c71e8 in handle_fatal_signal (sig=6) at /data/Server/MDEV-36301E/sql/signal_handler.cc:298
# 2025-06-03T09:06:48 [188084] #4 <signal handler called>
# 2025-06-03T09:06:48 [188084] #5 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
# 2025-06-03T09:06:48 [188084] #6 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
# 2025-06-03T09:06:48 [188084] #7 __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
# 2025-06-03T09:06:48 [188084] #8 0x0000739e9804526e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
# 2025-06-03T09:06:48 [188084] #9 0x0000739e980288ff in __GI_abort () at ./stdlib/abort.c:79
# 2025-06-03T09:06:48 [188084] #10 0x0000626ed85eccdd in ut_dbg_assertion_failed (expr=expr@entry=0x626ed9015f4b "num >= value()", file=file@entry=0x626ed9078d58 "/data/Server/MDEV-36301E/storage/innobase/log/log0sync.cc", line=line@entry=291) at /data/Server/MDEV-36301E/storage/innobase/ut/ut0dbg.cc:60
# 2025-06-03T09:06:48 [188084] #11 0x0000626ed85d51d6 in group_commit_lock::release (this=this@entry=0x626eda1767c0 <write_lock>, num=12871879) at /data/Server/MDEV-36301E/storage/innobase/log/log0sync.cc:291
# 2025-06-03T09:06:48 [188084] #12 0x0000626ed8c6c1cd in log_write_up_to (lsn=<optimized out>, durable=durable@entry=true, callback=<optimized out>, callback@entry=0x0) at /data/Server/MDEV-36301E/storage/innobase/log/log0log.cc:1503
# 2025-06-03T09:06:48 [188084] #13 0x0000626ed8d2f973 in buf_dblwr_t::flush_buffered_writes_completed (this=<optimized out>, request=...) at /data/Server/MDEV-36301E/storage/innobase/buf/buf0dblwr.cc:787
# 2025-06-03T09:06:48 [188084] #14 0x0000626ed8d61be5 in IORequest::write_complete (this=this@entry=0x626edb8bef90, io_error=<optimized out>) at /data/Server/MDEV-36301E/storage/innobase/fil/fil0fil.cc:2908
# 2025-06-03T09:06:48 [188084] #15 0x0000626ed8c89f7d in write_io_callback (c=0x626edb8bef28) at /data/Server/MDEV-36301E/storage/innobase/os/os0file.cc:3063
# 2025-06-03T09:06:48 [188084] #16 0x0000626ed8da39fa in tpool::task_group::execute (this=0x626edb8bede0, t=0x626edb8bef70) at /data/Server/MDEV-36301E/tpool/task_group.cc:73
# 2025-06-03T09:06:48 [188084] #17 0x0000626ed8da1fbf in tpool::thread_pool_generic::worker_main (this=0x626edb876c30, thread_var=0x626edb877680) at /data/Server/MDEV-36301E/tpool/tpool_generic.cc:574
# 2025-06-03T09:06:48 [188084] #18 0x0000739e984eabb4 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
# 2025-06-03T09:06:48 [188084] #19 0x0000739e9809ca94 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
# 2025-06-03T09:06:48 [188084] #20 0x0000739e98129c3c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S
Core dump is present on SDP machine : /data/results/1748942553/TBR-2285
We seem to have 2 more race conditions in log_write_up_to() when the log is being disabled or enabled during the execution. The message about resizing log could be revised to say "Enabling redo log" when the log was previously disabled.