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

Assertion w==OPT failed in trx_purge_add_undo_to_history()

    XMLWordPrintable

    Details

      Description

      10.5 c8ae3573

      mysqld: /data/src/10.5/storage/innobase/include/mtr0log.h:203: bool mtr_t::write(const buf_block_t&, void*, V) [with unsigned int l = 8u; mtr_t::write_type w = (mtr_t::write_type)0u; V = long unsigned int]: Assertion `w == OPT' failed.
      200315 13:51:49 [ERROR] mysqld got signal 6 ;
       
      #15 0x00007fc06260ef12 in __GI___assert_fail (assertion=0x5650284f6e32 "w == OPT", file=0x5650284f5060 "/data/src/10.5/storage/innobase/include/mtr0log.h", line=203, function=0x5650284f72e0 <bool mtr_t::write<8u, (mtr_t::write_type)0, unsigned long>(buf_block_t const&, void*, unsigned long)::__PRETTY_FUNCTION__> "bool mtr_t::write(const buf_block_t&, void*, V) [with unsigned int l = 8u; mtr_t::write_type w = (mtr_t::write_type)0u; V = long unsigned int]") at assert.c:101
      #16 0x0000565027d08bf6 in mtr_t::write<8u, (mtr_t::write_type)0, unsigned long> (this=0x7fc03c063c60, block=..., ptr=0x7fc040aa8517, val=2048) at /data/src/10.5/storage/innobase/include/mtr0log.h:203
      #17 0x0000565027e38bfd in trx_purge_add_undo_to_history (trx=0x7fc058a683c0, undo=@0x7fc058a693f0: 0x7fc0080f2418, mtr=0x7fc03c063c60) at /data/src/10.5/storage/innobase/trx/trx0purge.cc:301
      #18 0x0000565027e67477 in trx_write_serialisation_history (trx=0x7fc058a683c0, mtr=0x7fc03c063c60) at /data/src/10.5/storage/innobase/trx/trx0trx.cc:1120
      #19 0x0000565027e6989f in trx_commit_low (trx=0x7fc058a683c0, mtr=0x7fc03c063c60) at /data/src/10.5/storage/innobase/trx/trx0trx.cc:1557
      #20 0x0000565027e699ff in trx_commit (trx=0x7fc058a683c0) at /data/src/10.5/storage/innobase/trx/trx0trx.cc:1625
      #21 0x0000565027e69ee6 in trx_commit_for_mysql (trx=0x7fc058a683c0) at /data/src/10.5/storage/innobase/trx/trx0trx.cc:1771
      #22 0x0000565027bd785f in innobase_commit_low (trx=0x7fc058a683c0) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4150
      #23 0x0000565027bd7c85 in innobase_commit_ordered_2 (trx=0x7fc058a683c0, thd=0x7fbfc4000b18) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4272
      #24 0x0000565027bd82c8 in innobase_commit (hton=0x56502ab06c18, thd=0x7fbfc4000b18, commit_trx=false) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4389
      #25 0x000056502778858e in commit_one_phase_2 (thd=0x7fbfc4000b18, all=false, trans=0x7fbfc4004110, is_real_trans=true) at /data/src/10.5/sql/handler.cc:1872
      #26 0x000056502778848a in ha_commit_one_phase (thd=0x7fbfc4000b18, all=false) at /data/src/10.5/sql/handler.cc:1852
      #27 0x000056502778762c in ha_commit_trans (thd=0x7fbfc4000b18, all=false) at /data/src/10.5/sql/handler.cc:1653
      #28 0x00005650275eba37 in trans_commit_stmt (thd=0x7fbfc4000b18) at /data/src/10.5/sql/transaction.cc:460
      #29 0x000056502743fc39 in mysql_execute_command (thd=0x7fbfc4000b18) at /data/src/10.5/sql/sql_parse.cc:5946
      #30 0x00005650274459ce in mysql_parse (thd=0x7fbfc4000b18, rawbuf=0x7fbfc4012460 "DELETE /* QNO 896 CON_ID 9 */ FROM `t9` WHERE `col_date` = 17105", length=64, parser_state=0x7fc03c065520, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7926
      #31 0x00005650274314d7 in dispatch_command (command=COM_QUERY, thd=0x7fbfc4000b18, packet=0x7fbfc4008809 "DELETE /* QNO 896 CON_ID 9 */ FROM `t9` WHERE `col_date` = 17105", packet_length=64, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1840
      #32 0x000056502742fc0d in do_command (thd=0x7fbfc4000b18) at /data/src/10.5/sql/sql_parse.cc:1359
      #33 0x00005650275d15f9 in do_handle_one_connection (connect=0x56502b961688, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1422
      #34 0x00005650275d1328 in handle_one_connection (arg=0x56502b961688) at /data/src/10.5/sql/sql_connect.cc:1319
      #35 0x0000565027b007a2 in pfs_spawn_thread (arg=0x56502b853dd8) at /data/src/10.5/storage/perfschema/pfs.cc:2201
      #36 0x00007fc0645974a4 in start_thread (arg=0x7fc03c066700) at pthread_create.c:456
      #37 0x00007fc0626cbd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
      

      rr profile and mysqld binary obtained on Debian 9 (Stretch) x86_64:

      Linux 4.9.0-11-amd64 #1 SMP Debian 4.9.189-3+deb9u2 (2019-11-11) x86_64 GNU/Linux
      Distributor ID:	Debian
      Description:	Debian GNU/Linux 9.12 (stretch)
      Release:	9.12
      Codename:	stretch
      

      The workflow is a simple 2-thread test which only performs this:

      query:
          INSERT IGNORE INTO _table ( _field_pk ) VALUES ( NULL ) |
          DELETE FROM _table WHERE _field_pk = _smallint_unsigned
      ;
      

      To reproduce from scratch:

      git clone https://github.com/MariaDB/randgen --branch mdev21945 rqg-mdev21945
      cd rqg-mdev21945
      . ./mdev21945.cmd <your basedir>
      

      But the probability appears to be very low. The test above runs 50 test runs, ~4 min each, until the first time this failure occurs (if ever). It usually fails for me, but it can take any number of runs from 1 to 40+. Probably rr profile gives a better chance for debugging.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              marko Marko Mäkelä
              Reporter:
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: