[MDEV-32803] Assertion `total == 0' failed in Event_log::write_cache_raw Created: 2023-11-14  Updated: 2024-02-06  Resolved: 2024-01-30

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table
Affects Version/s: 11.2
Fix Version/s: 11.3.2, 11.2.4

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Nikita Malyavin
Resolution: Fixed Votes: 0
Labels: rr-profile


 Description   

bb-11.2-release c028e25cc1aea78c1cb8c7c7263dc121f8cacb9e with patch for MDEV-32771

 
(rr) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x000014902e71e859 in __GI_abort () at abort.c:79
 
#2  0x000014902e71e729 in __assert_fail_base (fmt=0x14902e8b4588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5607009a5850 "total == 0", 
    file=0x5607009a2130 "/data/for_nikita/bb-11.2-release-patched/sql/log.cc", line=7411, function=<optimized out>) at assert.c:92
 
#3  0x000014902e72ffd6 in __GI___assert_fail (assertion=0x5607009a5850 "total == 0", file=0x5607009a2130 "/data/for_nikita/bb-11.2-release-patched/sql/log.cc", line=7411, 
    function=0x5607009a5820 "int Event_log::write_cache_raw(THD*, IO_CACHE*)") at assert.c:101
 
#4  0x00005606ffed8f98 in Event_log::write_cache_raw (this=0x6a338036a8c0, thd=0x56cf80000d48, cache=0x55c704364c20) at /data/for_nikita/bb-11.2-release-patched/sql/log.cc:7411
 
#5  0x00005606fff66dac in online_alter_end_trans (cache_list=..., thd=0x56cf80000d48, is_ending_transaction=false, commit=false) at /data/for_nikita/bb-11.2-release-patched/sql/online_alter.cc:238
 
#6  0x00005606fff67330 in online_alter_rollback (hton=0x560702e43538, thd=0x56cf80000d48, all=false) at /data/for_nikita/bb-11.2-release-patched/sql/online_alter.cc:344
 
#7  0x00005606ffd7b72a in ha_rollback_trans (thd=0x56cf80000d48, all=false) at /data/for_nikita/bb-11.2-release-patched/sql/handler.cc:2264
 
#8  0x00005606ffb90034 in trans_rollback_stmt (thd=0x56cf80000d48) at /data/for_nikita/bb-11.2-release-patched/sql/transaction.cc:535
 
#9  0x00005606ff9b5b53 in mysql_execute_command (thd=0x56cf80000d48, is_called_from_prepared_stmt=false) at /data/for_nikita/bb-11.2-release-patched/sql/sql_parse.cc:5856
 
#10 0x00005606ff9bafb9 in mysql_parse (thd=0x56cf80000d48, rawbuf=0x56cf80013360 "/* WRK-6 QNO 20404 */  LOAD DATA INFILE '/tmp/gentest3386729.tmp' INTO TABLE `dbt3_db`.`r`", length=90, 
    parser_state=0x6f9530c1e340) at /data/for_nikita/bb-11.2-release-patched/sql/sql_parse.cc:7808
 
#11 0x00005606ff9a8f2a in dispatch_command (command=COM_QUERY, thd=0x56cf80000d48, packet=0x56cf8000aff9 "/* WRK-6 QNO 20404 */  LOAD DATA INFILE '/tmp/gentest3386729.tmp' INTO TABLE `dbt3_db`.`r`", 
    packet_length=90, blocking=true) at /data/for_nikita/bb-11.2-release-patched/sql/sql_parse.cc:1893
 
#12 0x00005606ff9a7b27 in do_command (thd=0x56cf80000d48, blocking=true) at /data/for_nikita/bb-11.2-release-patched/sql/sql_parse.cc:1406
 
#13 0x00005606ffb7491f in do_handle_one_connection (connect=0x5607034a48c8, put_in_cache=true) at /data/for_nikita/bb-11.2-release-patched/sql/sql_connect.cc:1418
 
#14 0x00005606ffb746ab in handle_one_connection (arg=0x5607034a48c8) at /data/for_nikita/bb-11.2-release-patched/sql/sql_connect.cc:1320
 
#15 0x0000421662844609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#16 0x000014902e81b133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

The failure happens with and without the patch for MDEV-32771, but its probability (low as it is in the tests) is much lower without the patch, because usually MDEV-32771 happens sooner.

I don't have any good way to reproduce it so far, the random test which triggers it had to be run dozens times without rr and hundreds times with rr.

 Comments   
Comment by Nikita Malyavin [ 2023-11-15 ]

The profile shows that file is detected by mf_iocache, is empty, but cache->end_of_file is non-zero.

(rr) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x000014902e71e859 in __GI_abort () at abort.c:79
 
#2  0x000014902e71e729 in __assert_fail_base (fmt=0x14902e8b4588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", 
    assertion=0x5607009a5850 "total == 0", file=0x5607009a2130 "/data/for_nikita/bb-11.2-release-patched/sql/log.cc", line=7411, 
    function=<optimized out>) at assert.c:92
 
#3  0x000014902e72ffd6 in __GI___assert_fail (assertion=0x5607009a5850 "total == 0", 
    file=0x5607009a2130 "/data/for_nikita/bb-11.2-release-patched/sql/log.cc", line=7411, 
    function=0x5607009a5820 "int Event_log::write_cache_raw(THD*, IO_CACHE*)") at assert.c:101
 
#4  0x00005606ffed8f98 in Event_log::write_cache_raw (this=0x6a338036a8c0, thd=0x56cf80000d48, cache=0x55c704364c20)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/log.cc:7411
 
#5  0x00005606fff66dac in online_alter_end_trans (cache_list=..., thd=0x56cf80000d48, is_ending_transaction=false, commit=false)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/online_alter.cc:238
 
#6  0x00005606fff67330 in online_alter_rollback (hton=0x560702e43538, thd=0x56cf80000d48, all=false)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/online_alter.cc:344
 
#7  0x00005606ffd7b72a in ha_rollback_trans (thd=0x56cf80000d48, all=false) at /data/for_nikita/bb-11.2-release-patched/sql/handler.cc:2264
 
#8  0x00005606ffb90034 in trans_rollback_stmt (thd=0x56cf80000d48) at /data/for_nikita/bb-11.2-release-patched/sql/transaction.cc:535
 
#9  0x00005606ff9b5b53 in mysql_execute_command (thd=0x56cf80000d48, is_called_from_prepared_stmt=false)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/sql_parse.cc:5856
 
#10 0x00005606ff9bafb9 in mysql_parse (thd=0x56cf80000d48, 
    rawbuf=0x56cf80013360 "/* WRK-6 QNO 20404 */  LOAD DATA INFILE '/tmp/gentest3386729.tmp' INTO TABLE `dbt3_db`.`r`", length=90, 
    parser_state=0x6f9530c1e340) at /data/for_nikita/bb-11.2-release-patched/sql/sql_parse.cc:7808
 
#11 0x00005606ff9a8f2a in dispatch_command (command=COM_QUERY, thd=0x56cf80000d48, 
    packet=0x56cf8000aff9 "/* WRK-6 QNO 20404 */  LOAD DATA INFILE '/tmp/gentest3386729.tmp' INTO TABLE `dbt3_db`.`r`", packet_length=90, 
    blocking=true) at /data/for_nikita/bb-11.2-release-patched/sql/sql_parse.cc:1893
 
#12 0x00005606ff9a7b27 in do_command (thd=0x56cf80000d48, blocking=true) at /data/for_nikita/bb-11.2-release-patched/sql/sql_parse.cc:1406
 
#13 0x00005606ffb7491f in do_handle_one_connection (connect=0x5607034a48c8, put_in_cache=true)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/sql_connect.cc:1418
 
#14 0x00005606ffb746ab in handle_one_connection (arg=0x5607034a48c8) at /data/for_nikita/bb-11.2-release-patched/sql/sql_connect.cc:1320
 
#15 0x0000421662844609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#16 0x000014902e81b133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
 
 
(rr) p cache->end_of_file
 
$7 = 24640
 
(rr) p info->read_pos - info->request_pos
 
$5 = 0

There was no flushing made, as seen by disk_writes = 0, before reinit_io_cache, and overall cache doesn't seem corrupted, or inconsistent, except the above.

(rr) b Event_log::write_cache_raw
 
Breakpoint 2 at 0x5606ffed8d98: file /data/for_nikita/bb-11.2-release-patched/sql/log.cc, line 7395.
 
(rr) rc
 
Continuing.
 
 
 
Thread 2 hit Breakpoint 2, Event_log::write_cache_raw (this=0x0, thd=0x6f9530c1daa0, cache=0x55c704364c20)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/log.cc:7395
 
7395	{
 
(rr) p cache->pos_in_file
 
$7 = 24640
 
(rr) p *cache
 
$8 = {pos_in_file = 24640, end_of_file = 18446744073709551615, read_pos = 0x56cf805dacb8 "M\216Se\027\001", 
  read_end = 0x56cf805dace5 "M\216Se\027\001", buffer = 0x56cf805dacb8 "M\216Se\027\001", request_pos = 0x56cf805dacb8 "M\216Se\027\001", 
  write_buffer = 0x56cf805dacb8 "M\216Se\027\001", append_read_pos = 0x0, write_pos = 0x56cf805dacb8 "M\216Se\027\001", 
  write_end = 0x56cf805e2c78 '\245' <repeats 64 times>, "\025 ", append_buffer_lock = {m_mutex = {global = {__data = {__lock = 0, 
          __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, 
        __size = '\000' <repeats 39 times>, __align = 0}, mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, 
          __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, 
        __align = 0}, file = 0x0, name = 0x0, line = 0, count = 0, create_flags = 0, active_flags = 0, id = 0, thread = 0, 
      locked_mutex = 0x0, used_mutex = 0x0, prev = 0x0, next = 0x0}, m_psi = 0x0}, share = 0x0, 
  read_function = 0x560700507a62 <_my_b_cache_read>, write_function = 0x560700509017 <_my_b_cache_write>, type = WRITE_CACHE, 
  disk_writes = 0, file_name = 0x0, dir = 0x560702d90718 "/dev/shm/var-total/trial.78/s1/tmp", prefix = "ML", file = -1, 
  next_file_user = 0x0, seek_not_done = 1, error = 0, buffer_length = 32768, read_length = 32768, myflags = 528, alloced_buffer = 32768}
 
(rr) p 0x56cf805e2c78 - 0x56cf805dacb8
 
$9 = 32704

Following further back by cache->pos_in_file changes shows a hard modification by truncate()

(rr) watch -l cache->pos_in_file 
Hardware watchpoint 3: -location cache->pos_in_file
 
(rr) rc
 
Continuing.
 
 
 
Thread 2 hit Hardware watchpoint 3: -location cache->pos_in_file
 
 
 
Old value = 24640
 
New value = 0
 
0x00005607005075a2 in reinit_io_cache (info=0x55c704364c20, type=WRITE_CACHE, seek_offset=24640, use_async_io=0 '\000', 
    clear_cache=0 '\000') at /data/for_nikita/bb-11.2-release-patched/mysys/mf_iocache.c:483
 
483	    info->pos_in_file=seek_offset;
 
(rr) bt
 
#0  0x00005607005075a2 in reinit_io_cache (info=0x55c704364c20, type=WRITE_CACHE, seek_offset=24640, use_async_io=0 '\000', 
    clear_cache=0 '\000') at /data/for_nikita/bb-11.2-release-patched/mysys/mf_iocache.c:483
 
#1  0x00005606ffee7995 in binlog_cache_data::truncate (this=0x55c704364c20, pos=24640, reset_cache=false)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/log_cache.h:240
 
#2  0x00005606ffee751d in binlog_cache_data::restore_prev_position (this=0x55c704364c20)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/log_cache.h:112
 
#3  0x00005606fff669a5 in online_alter_log_row (table=0x55c7046118d8, before_record=0x0, 
    after_record=0x55c704611ce8 "N\376\231\261\235:B", 
    log_func=0x5606ffd8fb00 <Write_rows_log_event::binlog_row_logging_function(THD*, TABLE*, Event_log*, binlog_cache_data*, bool, unsigned long, unsigned char const*, unsigned char const*)>) at /data/for_nikita/bb-11.2-release-patched/sql/online_alter.cc:176
 
#4  0x00005606ffd890a4 in handler::binlog_log_row (this=0x55c704612100, before_record=0x0, 
    after_record=0x55c704611ce8 "N\376\231\261\235:B", 
    log_func=0x5606ffd8fb00 <Write_rows_log_event::binlog_row_logging_function(THD*, TABLE*, Event_log*, binlog_cache_data*, bool, unsigned long, unsigned char const*, unsigned char const*)>) at /data/for_nikita/bb-11.2-release-patched/sql/handler.cc:7306
 
#5  0x00005606ffd8b126 in handler::ha_write_row (this=0x55c704612100, buf=0x55c704611ce8 "N\376\231\261\235:B")
 
    at /data/for_nikita/bb-11.2-release-patched/sql/handler.cc:7860
 
#6  0x00005606ff962eca in write_record (thd=0x56cf80000d48, table=0x55c7046118d8, info=0x6f9530c1d640, sink=0x0)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/sql_insert.cc:2213
 
#7  0x00005606ff99f449 in read_sep_field (thd=0x56cf80000d48, info=..., table_list=0x56cf80013550, fields_vars=..., set_fields=..., 
    set_values=..., read_info=..., enclosed=..., skip_lines=0, ignore_check_option_errors=false)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/sql_load.cc:1226
 
#8  0x00005606ff99d665 in mysql_load (thd=0x56cf80000d48, ex=0x56cf800134a0, table_list=0x56cf80013550, fields_vars=..., set_fields=..., 
    set_values=..., handle_duplicates=DUP_ERROR, ignore=false, read_file_from_client=false)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/sql_load.cc:689
 
#9  0x00005606ff9b1c4a in mysql_execute_command (thd=0x56cf80000d48, is_called_from_prepared_stmt=false)
 
    at /data/for_nikita/bb-11.2-release-patched/sql/sql_parse.cc:4803
 
#10 0x00005606ff9bafb9 in mysql_parse (thd=0x56cf80000d48, 
    rawbuf=0x56cf80013360 "/* WRK-6 QNO 20404 */  LOAD DATA INFILE '/tmp/gentest3386729.tmp' INTO TABLE `dbt3_db`.`r`", length=90, 
    parser_state=0x6f9530c1e340) at /data/for_nikita/bb-11.2-release-patched/sql/sql_parse.cc:7808
 
...

This is done during the error recovery, after a failed row operation. So far, a reported by mf_iocache size 0 is correct and is expected, where cache->end_of_file is something else after reiniting to CACHE_WRITE, and just shouldn't be used this way.

My solution will be to just remove the assertion in Event_log::write_cache_raw

Comment by Nikita Malyavin [ 2023-11-15 ]

I dug up deeper to the cause of error that leads to a truncate() call: it seems that my conclusion was incorrect.

The error happens during the cache write inside write_data_body, and then inside write_data(m_rows_buf, data_size), having data_size=8171, and then, in my_b_write:

(rr) p Count
 
$21 = 8171
 
(rr) n
 
546	  if (info->pos_in_file + info->buffer_length > info->end_of_file)
 
(rr) n
 
548	    my_errno=errno=EFBIG;

where info->end_of_file is already 45.

I would expect it to be somewhat like LONG_MAX, meaning that there's no limit for out online buffer. Now I have to understand what causes the limit to change.

Comment by Nikita Malyavin [ 2023-11-17 ]

At last, I came across the root cause. The error above happens because the cache we are writing to stands in READ_CACHE state, which is incorrect. The only place it could be left such is online_alter_end_trans, that is, commit/rollback of statement or transaction.

We don't dump the local cache to global cache per-statement when the transaction runs, unless the engine does not support transactions, or more precisely, rollbacks, i.e. myisam/aria. When we dump it, we suppose that it's going to be freed, and in case of innodb it would, since it would have a single write during trx commit. This is the reason, why the local cache wasn't reset back to WRITE_CACHE after dumping.

create or replace table t1 (a int) engine=aria;
 
insert t1 values (5);
 
--connect (con2, localhost, root,,)
 
 
 
 
 
--connection default
 
set debug_sync= 'alter_table_copy_end SIGNAL ended WAIT_FOR end';
 
 
 
send alter table t1 add b int NULL, algorithm= copy, lock= none;
 
 
 
--connection con2
 
set debug_sync= 'now WAIT_FOR ended';
 
begin;
 
insert into t1 values (123);
 
insert into t1 values (456), (789);
 
commit;
 
set debug_sync= 'now SIGNAL end';
 
 
 
--connection default
 
--reap
 
select * from t1;

Comment by Nikita Malyavin [ 2023-11-17 ]

Please review commit 9e7c80f800.

I have based it on top of bb-11.2-release, hoping that it's still possible to catch the last train to the 11.2.2 release.

Generated at Thu Feb 08 10:34:08 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.