Skip to content

MDEV-36301 SET GLOBAL innodb_log_file_disabled, innodb_log_group_home_dir #4014

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 3 commits into
base: main
Choose a base branch
from

Conversation

dr-m
Copy link
Contributor

@dr-m dr-m commented Apr 25, 2025

  • 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

  • This is a new feature or a refactoring, and the PR is based against the main branch.
  • 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

  • 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.

@dr-m dr-m self-assigned this Apr 25, 2025
@CLAassistant
Copy link

CLA assistant check
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.

@dr-m dr-m force-pushed the MDEV-36301 branch 2 times, most recently from 3459e02 to 2cc94dc Compare April 30, 2025 07:38
@dr-m dr-m force-pushed the MDEV-36301 branch 5 times, most recently from 5fc1dba to c4095de Compare May 7, 2025 05:37
@mariadb-SaahilAlam
Copy link

mariadb-SaahilAlam commented May 12, 2025

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

@mariadb-SaahilAlam
Copy link

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)

@mariadb-SaahilAlam
Copy link

created a jira bug ticket: https://jira.mariadb.org/browse/MDEV-36803

@dr-m
Copy link
Contributor Author

dr-m commented May 15, 2025

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.

@dr-m dr-m changed the title MDEV-36301 SET GLOBAL innodb_log_file_disabled etc. MDEV-36301 SET GLOBAL innodb_log_file_disabled, innodb_log_group_home_dir May 16, 2025
Comment on lines 273 to 286
bool log_t::resize_rename() noexcept
{
std::string old_name{get_log_file_path("ib_logfile101")};
std::string old_name{get_log_file_path("ib_logfile101", log_sys.resize_dir)};
std::string new_name{get_log_file_path()};

if (IF_WIN(MoveFileEx(old_name.c_str(), new_name.c_str(),
MOVEFILE_REPLACE_EXISTING),
!rename(old_name.c_str(), new_name.c_str())))
return false;

const int err= IF_WIN(int(GetLastError()), errno);
std::string &remove= err == IF_WIN(ERROR_NOT_SAME_DEVICE, EXDEV)
? old_name : new_name;
IF_WIN(DeleteFile(remove.c_str()), unlink(remove.c_str()));
Copy link
Contributor Author

@dr-m dr-m May 16, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I realized SET GLOBAL innodb_log_group_home_dir must actually retain new_name in log_sys.resize_dir. Attempting the atomic rename is fine, but the subsequent steps need to be different:

  • Whether or not the atomic renaming succeeded, rename the file further to ib_logfile0 in log_sys.resize_dir if it is not nullptr.
  • If the initial atomic renaming failed with errno==EXDEV and the subsequent renaming succeeded, we will have two ib_logfile0, both of which are valid for recovery. Delete the original ib_logfile0 and declare success.

@dr-m dr-m changed the base branch from 10.11 to main May 16, 2025 13:32
@dr-m dr-m force-pushed the MDEV-36301 branch 3 times, most recently from 9170459 to 9ba9164 Compare May 16, 2025 13:38
@dr-m dr-m marked this pull request as ready for review May 16, 2025 13:42
@dr-m dr-m force-pushed the MDEV-36301 branch 2 times, most recently from db846e8 to 1700b6f Compare May 19, 2025 05:50
dr-m added 2 commits May 22, 2025 09:40
The parameter innodb_log_spin_wait_delay will be deprecated and
ignored, because there is no spin loop anymore.

Thanks to commit 685d958
and commit a635c40
multiple mtr_t::commit() can concurrently copy their slice of
mtr_t::m_log to the shared log_sys.buf.  Each writer would allocate
their own log sequence number by invoking log_t::append_prepare()
while holding a shared log_sys.latch.  This function was too heavy,
because it would invoke a minimum of 4 atomic read-modify-write
operations as well as system calls in the supposedly fast code path.

It turns out that with a simpler data structure, instead of having
several data fields that needed to be kept consistent with each other,
we only need one Atomic_relaxed<uint64_t> write_lsn_offset, on which
we can operate using fetch_add(), fetch_sub() as well as a single-bit
fetch_or(), which reasonably modern compilers (GCC 7, Clang 15 or later)
can translate into loop-free code on AMD64.

Before anything can be written to the log, log_sys.clear_mmap()
must be invoked.

log_t::base_lsn: The LSN of the last write_buf() or persist().
This is a rough approximation of log_sys.lsn, which will be removed.

log_t::write_lsn_offset: An Atomic_relaxed<uint64_t> that buffers
updates of write_to_buf and base_lsn.

log_t::buf_free, log_t::max_buf_free, log_t::lsn. Remove.
Replaced by base_lsn and write_lsn_offset.

log_t::buf_size: Always reflects the usable size in append_prepare().

log_t::lsn_lock: Remove.  For the memory-mapped log in resize_write(),
there will be a resize_wrap_mutex.

log_t::get_lsn_approx(): Return a lower bound of get_lsn().
This should be exact unless append_prepare_wait() is pending.

log_get_lsn(): A wrapper for log_sys.get_lsn(), which must be invoked
while holding an exclusive log_sys.latch.

recv_recovery_from_checkpoint_start(): Do not invoke fil_names_clear();
it would seem to be unnecessary.

In many places, references to log_sys.get_lsn() are replaced with
log_sys.get_flushed_lsn(), which remains a simple std::atomic::load().

Reviewed by: Debarun Banerjee

(cherry picked from commit acd071f)
log_t::append_prepare_wait(): Do not attempt to read log_sys.write_lsn
because it is not protected by log_sys.latch but by write_lock, which
we cannot hold here. The assertion could fail if log_t::write_buf()
is executing concurrently, and it has not yet executed log_write_buf()
or updated log_sys.write_lsn.

Fixes up commit acd071f (MDEV-21923)

(cherry picked from commit 84dd243)
@mariadb-SaahilAlam
Copy link

Assertion found on RQG testing
origin/MDEV-36301 1700b6f 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

@mariadb-SaahilAlam
Copy link

Hitting this Assertion on latest commit :-origin/MDEV-36301 8ce4b1a 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

@dr-m dr-m force-pushed the MDEV-36301 branch 6 times, most recently from 4560600 to 2ca4fef Compare May 26, 2025 12:50
@mariadb-SaahilAlam
Copy link

mariadb-SaahilAlam commented May 27, 2025

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

@mariadb-SaahilAlam
Copy link

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

@mariadb-SaahilAlam
Copy link

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

@dr-m
Copy link
Contributor Author

dr-m commented May 27, 2025

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.

@dr-m
Copy link
Contributor Author

dr-m commented May 27, 2025

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. 05e7df7 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.

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 of log_sys.buf) differently.

log_sys.disabled: The current setting of innodb_log_file_disabled.

log_t::append_prepare(): Instead of referring to file_size or
capacity() for mmap=true, always refer to buf_size.
When log_sys.disabled holds, log_sys.buf may be much smaller than
log_sys.file_size. Its size is always reflected by log_sys.buf_size.

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 and advance the group_lock and flush_lock
to the current LSN, 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_t::resize_write(): Detect memory-mapped log by
!resize_log.is_opened().  If the memory-mapped log is being re-enabled,
log_sys.resize_flush_buf may temporarily store the value of a dummy
log_sys.flush_buf.  During any log resizing or disabling or enabling,
both buf and resize_buf must appear to be either file-based or
memory-mapped.

log_t::write_buf(), log_write_up_to(): Handle the special case that
disable() executed or resize_start() started re-enabling the log while
we were waiting for flush_lock or write_lock. In the latter case,
log_sys.writer will be changed from log_t::skip_write_buf to
log_writer_resizing during the execution of log_write_up_to().

log_t::persist(): Skip the writes if the log is disabled, that is,
a memory-mapped log is in the process being re-enabled. In this case,
we cannot trust log_sys.file_size, and the pmem_persist() could be
invoked on an invalid address range.

log_resize_acquire_group(): Acquier the group locks for write and flush.

log_resize_release_group(): Release the group locks for write and flush.

log_resize_acquire(): Return whether the group locks were elided.

log_write_and_flush_prepare(), log_write_and_flush(): Protect also the
log_sys.is_mmap() case with write_lock and flush_lock, in order to
prevent a race condition between mtr_t::commit_file() and
log_t::disable().

log_t::persist(): Remove the assertions about not holding write_lock or
flush_lock.  We will hold them during DDL operations.
@mariadb-SaahilAlam
Copy link

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

@dr-m
Copy link
Contributor Author

dr-m commented May 28, 2025

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

Core 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. 8f486f2 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.

Copy link
Contributor

@mariadb-DebarunBanerjee mariadb-DebarunBanerjee left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please find my initial comments on the feature/testcase.

Comment on lines 13 to 17
# restart: --innodb-force-recovery=6
SET GLOBAL innodb_log_checkpoint_now=1;
Warnings:
Warning 138 InnoDB doesn't force checkpoint when innodb-force-recovery=6.
# restart: --innodb-read-only=1
SET GLOBAL innodb_log_checkpoint_now=1;
Warnings:
Warning 138 InnoDB doesn't force checkpoint when innodb-read-only=1.
# restart
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The warnings seem useful. Should we remove them ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The warnings are not being localized via errmsg-utf8.txt; they are always in English. I wanted to make innodb_log_checkpoint_now to be able to use the same interface once MDEV-36828 has been fixed. The changes related to innodb_log_checkpoint_now can surely be reverted.

Comment on lines +25 to +30
SET GLOBAL innodb_log_file_disabled=ON;
ALTER TABLE t ADD c2 CHAR FIRST;
INSERT INTO t(a) SELECT * from seq_1_to_10000;
SET STATEMENT max_statement_time=1e-6 FOR
SET GLOBAL innodb_log_file_disabled=OFF;
DROP TABLE t;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  1. Can we crash the server, restart and do select count(*) ? The intent is to check that the data is recovered properly after innodb_log_file_disabled is set to OFF.
  2. We should also test the case of a crash when innodb_log_file_disabled is ON and on restart. I think there should be an error message and server should refuse normal startup.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  1. Sure, this is worth adding.
  2. At the start of the test, the eval $check_no_innodb that InnoDB will refuse to start if it had been shut down or killed while innodb_log_file_disabled=ON was in effect. It does not matter which one.

What we could add is a check that a startup with innodb_force_recovery=6 is possible. Executing that after a server kill would lead to nondeterministic results, that is, sometimes the database might appear OK, sometimes not. But hopefully it should not crash, no matter what. For example, the root page could be pointing to child pages that had not been written yet, or the sibling links between pages could be broken, if only some of the pages had been written from the buffer pool. This would be interesting and worthwhile to test.

Comment on lines +40 to +42
--source include/restart_mysqld.inc
SELECT * FROM t;
DROP TABLE t;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We should also specify and test the scenario of default and slow shutdown (innodb_fast_shutdown=0,1) when innodb_log_file_disabled=ON. Do we expect it to work ? In MySQL it works as all pages are flushed and no redo recovery is involved.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It should work, and the test step is worth adding. Due to b07920b, InnoDB would only start up with innodb_force_recovery=6, which makes it read-only. We could check the consistency of the data with CHECK TABLE and SELECT and expect it to be correct after the server was shut down, as long as innodb_fast_shutdown=2 is not being used.

SHOW VARIABLES LIKE 'innodb_log_file_size';
Variable_name Value
innodb_log_file_size 5242880
SET GLOBAL innodb_log_file_size=6291456;
SET GLOBAL innodb_log_file_disabled=ON;
SET GLOBAL innodb_log_group_home_dir='log';
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Adding a comment here to capture our discussion. Changing innodb_log_group_home_dir dynamically would cause the server restart to fail unless the configuration file is also changed by user. It could be an hindrance to usability making it virtually unusable unless the configuration change is temporarily done (and reverted back subsequently) for some testing purpose. It should be documented well.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That is right. I edited the description of MDEV-36301 to try to make this clearer.

@@ -0,0 +1 @@
--skip-innodb-undo-tablespaces
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggest to add a comment on why we need to disable undo tablespaces.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK. The reason is that this test is bootstrapping a new InnoDB data directory, and it assumes that we have innodb_undo_tablespaces=0. I originally developed this test for the 10.11 branch where that is the default setting. I didn’t investigate how to make this work with the new default innodb_undo_tablespaces=3, because I thought that with fewer files it is simpler.

SET GLOBAL innodb_log_file_disabled=ON;
--list_files $datadir ib_logfile*
--list_files $datadir/log ib_logfile*
SET GLOBAL innodb_log_group_home_dir='log';
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What happens if a concurrent mariabackup is copying the redo log files ? Are we synchronizing with backup locks. Let's define the behaviour and test.

This comment is relevant for both innodb_log_file_disabled and innodb_log_group_home_dir.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

When mariadb-backup --backup is running concurrently with any change of log related parameters, it will continue to monitor the old ib_logfile0 that it opened when the backup was started. That file will stop to receive any updates as soon as the checkpoint completes and the ib_logfile101 is supposed to take over. So, mariadb-backup --backup will basically hang. This problem exists ever since 177345d was implemented. As far as I can tell, the problem could only be addressed by making the mariadbd process responsible for copying (or replicating) the log when a backup is running.

For SET GLOBAL innodb_log_file_disabled=ON, the trouble starts immediately: log_t::disable() will unlink the ib_logfile0 and redirect log_sys.writer to the dummy function. Any processes that are holding an open file handle to the old log file will be able to read it, but that file will cease to receive any updates.

@mariadb-SaahilAlam
Copy link

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

@mariadb-SaahilAlam
Copy link

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

@mariadb-SaahilAlam
Copy link

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

Successfully merging this pull request may close these issues.

5 participants