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.
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
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
Nikita Malyavin
added a comment - - edited 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
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.
Nikita Malyavin
added a comment - - edited 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.
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.
createorreplacetable 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 altertable t1 add b intNULL, algorithm= copy, lock= none;
--connection con2
set debug_sync= 'now WAIT_FOR ended';
begin;
insertinto t1 values (123);
insertinto t1 values (456), (789);
commit;
set debug_sync= 'now SIGNAL end';
--connection default
--reap
select * from t1;
Nikita Malyavin
added a comment - 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;
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.
Nikita Malyavin
added a comment - 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.
People
Nikita Malyavin
Elena Stepanova
Votes:
0Vote for this issue
Watchers:
5Start watching this issue
Dates
Created:
Updated:
Resolved:
Git Integration
Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.
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