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

Assertion `log_descriptor.bc.buffer->prev_last_lsn == ((LSN)0)' failed in translog_flush_buffers

    XMLWordPrintable

    Details

      Description

      10.3 b9b279ec

      mysqld: /data/src/10.3/storage/maria/ma_loghandler.c:8005: translog_flush_buffers: Assertion `log_descriptor.bc.buffer->prev_last_lsn == ((LSN)0)' failed.
      200624 18:53:35 [ERROR] mysqld got signal 6 ;
       
      #6  0x00007f21d546ee67 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x55dbbdf871e0 "log_descriptor.bc.buffer->prev_last_lsn == ((LSN)0)", file=file@entry=0x55dbbdf818c8 "/data/src/10.3/storage/maria/ma_loghandler.c", line=line@entry=8005, function=function@entry=0x55dbbdf88b70 <__PRETTY_FUNCTION__.17199> "translog_flush_buffers") at assert.c:92
      #7  0x00007f21d546ef12 in __GI___assert_fail (assertion=0x55dbbdf871e0 "log_descriptor.bc.buffer->prev_last_lsn == ((LSN)0)", file=0x55dbbdf818c8 "/data/src/10.3/storage/maria/ma_loghandler.c", line=8005, function=0x55dbbdf88b70 <__PRETTY_FUNCTION__.17199> "translog_flush_buffers") at assert.c:101
      #8  0x000055dbbd9bd54f in translog_flush_buffers (lsn=0x7f21cb57b458, sent_to_disk=0x7f21cb57b468, flush_horizon=0x7f21cb57b470) at /data/src/10.3/storage/maria/ma_loghandler.c:8004
      #9  0x000055dbbd9bdcfc in translog_flush (lsn=4301389853) at /data/src/10.3/storage/maria/ma_loghandler.c:8173
      #10 0x000055dbbda19da7 in flush_log_for_bitmap (args=0x7f21cb57b580) at /data/src/10.3/storage/maria/ma_bitmap.c:3114
      #11 0x000055dbbd9c12f8 in pagecache_fwrite (pagecache=0x55dbbf0f3000 <maria_pagecache_var>, filedesc=0x7f21d01a8038, buffer=0x7f21d0733080 "", pageno=0, type=PAGECACHE_PLAIN_PAGE, flags=36) at /data/src/10.3/storage/maria/ma_pagecache.c:660
      #12 0x000055dbbd9ccdbe in flush_cached_blocks (pagecache=0x55dbbf0f3000 <maria_pagecache_var>, file=0x7f21b003de58, cache=0x7f21cb57b750, end=0x7f21cb57b758, type=FLUSH_KEEP, first_errno=0x7f21cb57b6b4) at /data/src/10.3/storage/maria/ma_pagecache.c:4419
      #13 0x000055dbbd9cd8cd in flush_pagecache_blocks_int (pagecache=0x55dbbf0f3000 <maria_pagecache_var>, file=0x7f21b003de58, type=FLUSH_KEEP, filter=0x55dbbda142e7 <filter_flush_bitmap_pages>, filter_arg=0x7f21b003dfa8) at /data/src/10.3/storage/maria/ma_pagecache.c:4715
      #14 0x000055dbbd9cdd1d in flush_pagecache_blocks_with_filter (pagecache=0x55dbbf0f3000 <maria_pagecache_var>, file=0x7f21b003de58, type=FLUSH_KEEP, filter=0x55dbbda142e7 <filter_flush_bitmap_pages>, filter_arg=0x7f21b003dfa8) at /data/src/10.3/storage/maria/ma_pagecache.c:4830
      #15 0x000055dbbda14535 in _ma_bitmap_flush_all (share=0x7f21b003d2e0) at /data/src/10.3/storage/maria/ma_bitmap.c:550
      #16 0x000055dbbd9d9b05 in _ma_tmp_disable_logging_for_table (info=0x7f21b00460a0, log_incomplete=1 '\001') at /data/src/10.3/storage/maria/ma_recovery.c:3566
      #17 0x000055dbbd99c444 in ha_maria::start_bulk_insert (this=0x7f21b003cb48, rows=0, flags=0) at /data/src/10.3/storage/maria/ha_maria.cc:2112
      #18 0x000055dbbcfabef1 in handler::ha_start_bulk_insert (this=0x7f21b003cb48, rows=0, flags=0) at /data/src/10.3/sql/handler.h:3163
      #19 0x000055dbbcfa7ef8 in select_insert::prepare (this=0x7f21b0012d00, values=..., u=0x7f21b00049b8) at /data/src/10.3/sql/sql_insert.cc:3806
      #20 0x000055dbbd028001 in JOIN::prepare (this=0x7f21b0012db0, tables_init=0x7f21b00122c8, wild_num=0, conds_init=0x0, og_num=1, order_init=0x7f21b0012c18, skip_order_by=false, group_init=0x0, having_init=0x0, proc_param_init=0x0, select_lex_arg=0x7f21b0005140, unit_arg=0x7f21b00049b8) at /data/src/10.3/sql/sql_select.cc:1382
      #21 0x000055dbbd032656 in mysql_select (thd=0x7f21b0000af0, tables=0x7f21b00122c8, wild_num=0, fields=..., conds=0x0, og_num=1, order=0x7f21b0012c18, group=0x0, having=0x0, proc_param=0x0, select_options=3489925889, result=0x7f21b0012d00, unit=0x7f21b00049b8, select_lex=0x7f21b0005140) at /data/src/10.3/sql/sql_select.cc:4290
      #22 0x000055dbbd023cf8 in handle_select (thd=0x7f21b0000af0, lex=0x7f21b00048f8, result=0x7f21b0012d00, setup_tables_done_option=1073741824) at /data/src/10.3/sql/sql_select.cc:370
      #23 0x000055dbbcfe46b4 in mysql_execute_command (thd=0x7f21b0000af0) at /data/src/10.3/sql/sql_parse.cc:4570
      #24 0x000055dbbcfef995 in mysql_parse (thd=0x7f21b0000af0, rawbuf=0x7f21b0011458 "INSERT INTO transforms.insert_select_13191  SELECT DISTINCT ( COS( ( POW( NULL, `col_date_nokey` ) ) ) ) ^ NULL AS field1 FROM `B` ORDER BY @A := ( `col_datetime_key` )", length=168, parser_state=0x7f21cb5805e0, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7818
      #25 0x000055dbbcfdc1dd in dispatch_command (command=COM_QUERY, thd=0x7f21b0000af0, packet=0x7f21b0008c71 "INSERT INTO transforms.insert_select_13191  SELECT DISTINCT ( COS( ( POW( NULL, `col_date_nokey` ) ) ) ) ^ NULL AS field1 FROM `B` ORDER BY @A := ( `col_datetime_key` )", packet_length=168, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1856
      #26 0x000055dbbcfdaaf5 in do_command (thd=0x7f21b0000af0) at /data/src/10.3/sql/sql_parse.cc:1401
      #27 0x000055dbbd153bad in do_handle_one_connection (connect=0x55dbc0a994d0) at /data/src/10.3/sql/sql_connect.cc:1403
      #28 0x000055dbbd15390f in handle_one_connection (arg=0x55dbc0a994d0) at /data/src/10.3/sql/sql_connect.cc:1308
      #29 0x000055dbbdb09924 in pfs_spawn_thread (arg=0x55dbc0b73ac0) at /data/src/10.3/storage/perfschema/pfs.cc:1869
      #30 0x00007f21d73f74a4 in start_thread (arg=0x7f21cb581700) at pthread_create.c:456
      #31 0x00007f21d552bd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
      

      The best test case that I currently have is attached. It's an extremely ugly test case, most of its contents should have nothing to do with the problem, but I can't remove anything else without reducing the probability of reproducing to almost none. It already requires on average a hundred repetitions, but it's totally unpredictable – sometimes it happens in first 10 attempts, sometimes after 400.

      Run as

       perl ./mtr bug.lsn8 --repeat=500 --ps-protocol --mem
      

      ps-protocol is not necessary, the test might still fail without it, but it seems to make the failure more probable.
      mem is not necessary, but it makes things faster.
      repeat=500 is arbitrary if not a guarantee. If you can, set even a higher number, or run several times if it doesn't happen right away.

      No visible effect on a non-debug build.

      10.3 and 10.4 are affected. It might well be that 10.2 and earlier versions are also affected, but the test contains some 10.3-specific stuff, and since I can't change anything there, I can't check if the problem exists in earlier versions.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              vlad.lesin Vladislav Lesin
              Reporter:
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Dates

                Created:
                Updated:

                  Git Integration