Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-32803

Assertion `total == 0' failed in Event_log::write_cache_raw

Details

    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.

      Attachments

        Activity

          nikitamalyavin 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

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

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

          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;
          

          nikitamalyavin 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;

          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.

          nikitamalyavin 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

            nikitamalyavin Nikita Malyavin
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start 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.