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

Assertion `!expl_lock || expl_lock->trx == arg->impl_trx' failed in lock_rec_other_trx_holds_expl_callback

Details

    Description

      10.3 ad647cc84ebf331d59b24e81bffe89be2f5b1ed7

      		 
      mysqld: /home/travis/src/storage/innobase/lock/lock0lock.cc:6182: my_bool lock_rec_other_trx_holds_expl_callback(rw_trx_hash_element_t*, lock_rec_other_trx_holds_expl_arg*): Assertion `!expl_lock || expl_lock->trx == arg->impl_trx' failed.
      		 
      180325  8:25:01 [ERROR] mysqld got signal 6 ;
      		 
       
      		 
      Query (0x7fca1025dda8): INSERT INTO transforms.trigger27372 SELECT `col_enum_utf8_key` FROM `table100_innodb_key_pk_parts_2_int_autoinc` /* QNO 466 CON_ID 16 */
      		 
      Connection ID (thread ID): 16
      		 
      Status: NOT_KILLED
      		 
      Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on


      #6  0x00007fca6f14dbf6 in __assert_fail_base (fmt=0x7fca6f2a2058 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x562e396d4150 "!expl_lock || expl_lock->trx == arg->impl_trx", file=file@entry=0x562e396d1a50 "/home/travis/src/storage/innobase/lock/lock0lock.cc", line=line@entry=6182, function=function@entry=0x562e396d91a0 <lock_rec_other_trx_holds_expl_callback(rw_trx_hash_element_t*, lock_rec_other_trx_holds_expl_arg*)::__PRETTY_FUNCTION__> "my_bool lock_rec_other_trx_holds_expl_callback(rw_trx_hash_element_t*, lock_rec_other_trx_holds_expl_arg*)") at assert.c:92
      		 
      #7  0x00007fca6f14dca2 in __GI___assert_fail (assertion=0x562e396d4150 "!expl_lock || expl_lock->trx == arg->impl_trx", file=0x562e396d1a50 "/home/travis/src/storage/innobase/lock/lock0lock.cc", line=6182, function=0x562e396d91a0 <lock_rec_other_trx_holds_expl_callback(rw_trx_hash_element_t*, lock_rec_other_trx_holds_expl_arg*)::__PRETTY_FUNCTION__> "my_bool lock_rec_other_trx_holds_expl_callback(rw_trx_hash_element_t*, lock_rec_other_trx_holds_expl_arg*)") at assert.c:101
      		 
      #8  0x0000562e38f24ea3 in lock_rec_other_trx_holds_expl_callback (element=0x7fca240e96a0, arg=0x7fca6c0a5e30) at /home/travis/src/storage/innobase/lock/lock0lock.cc:6182
      		 
      #9  0x0000562e38f2a671 in rw_trx_hash_t::debug_iterator (element=0x7fca240e96a0, arg=0x7fca6c0a5df0) at /home/travis/src/storage/innobase/include/trx0sys.h:541
      		 
      #10 0x0000562e39445b87 in l_find (head=0x7fca1c03d000, cs=0x0, hashnr=0, key=0x7fca6c0a5df0 "\321M\362\070.V", keylen=0, cursor=0x7fca6c0a5d90, pins=0x562e3c598600, callback=0x562e38f2a5ea <rw_trx_hash_t::debug_iterator(rw_trx_hash_element_t*, rw_trx_hash_t::debug_iterator_arg*)>) at /home/travis/src/mysys/lf_hash.c:126
      		 
      #11 0x0000562e3944682e in lf_hash_iterate (hash=0x562e39f00a40 <trx_sys+2496>, pins=0x562e3c598600, action=0x562e38f2a5ea <rw_trx_hash_t::debug_iterator(rw_trx_hash_element_t*, rw_trx_hash_t::debug_iterator_arg*)>, argument=0x7fca6c0a5df0) at /home/travis/src/mysys/lf_hash.c:518
      		 
      #12 0x0000562e38f2a88b in rw_trx_hash_t::iterate (this=0x562e39f00a40 <trx_sys+2496>, caller_trx=0x7fca598dd948, action=0x562e38f2a5ea <rw_trx_hash_t::debug_iterator(rw_trx_hash_element_t*, rw_trx_hash_t::debug_iterator_arg*)>, argument=0x7fca6c0a5df0) at /home/travis/src/storage/innobase/include/trx0sys.h:744
      		 
      #13 0x0000562e38f24f97 in lock_rec_other_trx_holds_expl (caller_trx=0x7fca598dd948, trx=0x7fca598ddde0, rec=0x7fca4c5c8283 "\020\200", block=0x7fca4ba45600) at /home/travis/src/storage/innobase/lock/lock0lock.cc:6216
      		 
      #14 0x0000562e38f25282 in lock_rec_convert_impl_to_expl (caller_trx=0x7fca598dd948, block=0x7fca4ba45600, rec=0x7fca4c5c8283 "\020\200", index=0x7fca100ce0a8, offsets=0x7fca6c0a6970) at /home/travis/src/storage/innobase/lock/lock0lock.cc:6258
      		 
      #15 0x0000562e38f25e84 in lock_sec_rec_read_check_and_lock (flags=0, block=0x7fca4ba45600, rec=0x7fca4c5c8283 "\020\200", index=0x7fca100ce0a8, offsets=0x7fca6c0a6970, mode=LOCK_S, gap_mode=0, thr=0x7fca2005a3f0) at /home/travis/src/storage/innobase/lock/lock0lock.cc:6466
      		 
      #16 0x0000562e39026cee in sel_set_rec_lock (pcur=0x7fca20059b28, rec=0x7fca4c5c8283 "\020\200", index=0x7fca100ce0a8, offsets=0x7fca6c0a6970, mode=2, type=0, thr=0x7fca2005a3f0, mtr=0x7fca6c0a6c90) at /home/travis/src/storage/innobase/row/row0sel.cc:1263
      		 
      #17 0x0000562e3902fa3c in row_search_mvcc (buf=0x7fca10261e52 '\245' <repeats 200 times>..., mode=PAGE_CUR_G, prebuilt=0x7fca20059958, match_mode=0, direction=1) at /home/travis/src/storage/innobase/row/row0sel.cc:4931
      		 
      #18 0x0000562e38e9af0f in ha_innobase::general_fetch (this=0x7fca2003d9e8, buf=0x7fca10261e52 '\245' <repeats 200 times>..., direction=1, match_mode=0) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:9854
      		 
      #19 0x0000562e38e9b18c in ha_innobase::index_next (this=0x7fca2003d9e8, buf=0x7fca10261e52 '\245' <repeats 200 times>...) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:9921
      		 
      #20 0x0000562e38c891b6 in handler::ha_index_next (this=0x7fca2003d9e8, buf=0x7fca10261e52 '\245' <repeats 200 times>...) at /home/travis/src/sql/handler.cc:2862
      		 
      #21 0x0000562e393fe971 in ha_partition::handle_ordered_next (this=0x7fca2003be58, buf=0x7fca200402d8 '\245' <repeats 200 times>..., is_next_same=false) at /home/travis/src/sql/ha_partition.cc:7898
      		 
      #22 0x0000562e393f80dc in ha_partition::index_next (this=0x7fca2003be58, buf=0x7fca200402d8 '\245' <repeats 200 times>...) at /home/travis/src/sql/ha_partition.cc:5796
      		 
      #23 0x0000562e38c891b6 in handler::ha_index_next (this=0x7fca2003be58, buf=0x7fca200402d8 '\245' <repeats 200 times>...) at /home/travis/src/sql/handler.cc:2862
      		 
      #24 0x0000562e38a0ae99 in join_read_next (info=0x7fca1025ef90) at /home/travis/src/sql/sql_select.cc:20232
      		 
      #25 0x0000562e38901289 in READ_RECORD::read_record (this=0x7fca1025ef90) at /home/travis/src/sql/records.h:73
      		 
      #26 0x0000562e38a0888c in sub_select (join=0x7fca1025df58, join_tab=0x7fca1025eec8, end_of_records=false) at /home/travis/src/sql/sql_select.cc:19251
      		 
      #27 0x0000562e38a07d4b in do_select (join=0x7fca1025df58, procedure=0x0) at /home/travis/src/sql/sql_select.cc:18772
      		 
      #28 0x0000562e389e0f10 in JOIN::exec_inner (this=0x7fca1025df58) at /home/travis/src/sql/sql_select.cc:3987
      		 
      #29 0x0000562e389e03b0 in JOIN::exec (this=0x7fca1025df58) at /home/travis/src/sql/sql_select.cc:3781
      		 
      #30 0x0000562e389e1624 in mysql_select (thd=0x7fca10015900, tables=0x7fca104e6dd0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=553245477632, result=0x7fca1025deb0, unit=0x7fca104e5730, select_lex=0x7fca104e5ea8) at /home/travis/src/sql/sql_select.cc:4186
      		 
      #31 0x0000562e389d38f7 in handle_select (thd=0x7fca10015900, lex=0x7fca104e5668, result=0x7fca1025deb0, setup_tables_done_option=1073741824) at /home/travis/src/sql/sql_select.cc:382
      		 
      #32 0x0000562e389983be in mysql_execute_command (thd=0x7fca10015900) at /home/travis/src/sql/sql_parse.cc:4826
      		 
      #33 0x0000562e388c682c in sp_instr_stmt::exec_core (this=0x7fca104e5040, thd=0x7fca10015900, nextp=0x7fca6c0a8a9c) at /home/travis/src/sql/sp_head.cc:3595
      		 
      #34 0x0000562e388c5c44 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fca104e5090, thd=0x7fca10015900, nextp=0x7fca6c0a8a9c, open_tables=false, instr=0x7fca104e5040) at /home/travis/src/sql/sp_head.cc:3311
      		 
      #35 0x0000562e388c63e9 in sp_instr_stmt::execute (this=0x7fca104e5040, thd=0x7fca10015900, nextp=0x7fca6c0a8a9c) at /home/travis/src/sql/sp_head.cc:3498
      		 
      #36 0x0000562e388c01d8 in sp_head::execute (this=0x7fca104e35c8, thd=0x7fca10015900, merge_da_on_success=false) at /home/travis/src/sql/sp_head.cc:1349
      		 
      #37 0x0000562e388c132d in sp_head::execute_trigger (this=0x7fca104e35c8, thd=0x7fca10015900, db_name=0x7fca104ea898, table_name=0x7fca104ea8a8, grant_info=0x7fca104f1098) at /home/travis/src/sql/sp_head.cc:1757
      		 
      #38 0x0000562e38a7f42d in Table_triggers_list::process_triggers (this=0x7fca104f0ab8, thd=0x7fca10015900, event=TRG_EVENT_INSERT, time_type=TRG_ACTION_BEFORE, old_row_is_record1=true) at /home/travis/src/sql/sql_trigger.cc:2204
      		 
      #39 0x0000562e38918662 in fill_record_n_invoke_before_triggers (thd=0x7fca10015900, table=0x7fca104eeb70, ptr=0x7fca104ef7c8, values=..., ignore_errors=false, event=TRG_EVENT_INSERT) at /home/travis/src/sql/sql_base.cc:8513
      		 
      #40 0x0000562e3895a489 in mysql_insert (thd=0x7fca10015900, table_list=0x7fca1002c500, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/travis/src/sql/sql_insert.cc:1011
      		 
      #41 0x0000562e38997c5a in mysql_execute_command (thd=0x7fca10015900) at /home/travis/src/sql/sql_parse.cc:4719
      		 
      #42 0x0000562e389a2454 in mysql_parse (thd=0x7fca10015900, rawbuf=0x7fca1002c3c8 "INSERT INTO trigger17372 VALUES (1) /* QNO 528 CON_ID 16 */", length=59, parser_state=0x7fca6c0aa5e0, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:8009
      		 
      #43 0x0000562e3898fb4d in dispatch_command (command=COM_QUERY, thd=0x7fca10015900, packet=0x7fca10068621 "INSERT INTO trigger17372 VALUES (1) /* QNO 528 CON_ID 16 */ ", packet_length=60, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1838
      		 
      #44 0x0000562e3898e599 in do_command (thd=0x7fca10015900) at /home/travis/src/sql/sql_parse.cc:1383
      		 
      #45 0x0000562e38af37c3 in do_handle_one_connection (connect=0x562e3b840050) at /home/travis/src/sql/sql_connect.cc:1402
      		 
      #46 0x0000562e38af3550 in handle_one_connection (arg=0x562e3b840050) at /home/travis/src/sql/sql_connect.cc:1308
      		 
      #47 0x00007fca6fd0f184 in start_thread (arg=0x7fca6c0ab700) at pthread_create.c:312
      		 
      #48 0x00007fca6f21c03d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

      Attachments

        1. MDEV-15658.tgz
          3 kB
          Matthias Leich
        2. mysql.err
          32 kB
          Elena Stepanova
        3. mysql.err
          53 kB
          Elena Stepanova
        4. mysql.log
          847 kB
          Elena Stepanova
        5. mysql.log
          1.17 MB
          Elena Stepanova
        6. threads
          69 kB
          Elena Stepanova

        Issue Links

          is caused by

          Task - A task that needs to be done. MDEV-14638 Replace trx_sys_t::rw_trx_set with LF_HASH

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            mleich Matthias Leich added a comment -

            9 replays within ~1000 RQG runs on
            origin/10.3 c43d11b96e27f25d248f4740a2274f1bfb1d5845 2018-08-21T12:27:29-07:00
            10.3.10-MariaDB-debug-log

            mleich Matthias Leich added a comment - 9 replays within ~1000 RQG runs on origin/10.3 c43d11b96e27f25d248f4740a2274f1bfb1d5845 2018-08-21T12:27:29-07:00 10.3.10-MariaDB-debug-log
            mleich Matthias Leich added a comment - 

            Replay of the problem (same assert hit) on
            		 
               10.4 commit 4edb29380c98058a28e49c826bacee9c83473579 2019-01-18
            		 
            with
            		 
               my "experimental" RQG
            		 
               git clone https://github.com/mleich1/rqg --branch experimental RQG_new2
            		 
            and
            		 
            /work/RQG_new2/rqg.pl \ 
            --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
            		 
            --grammar=conf/mariadb/table_stress.yy \
            		 
            --gendata=conf/mariadb/table_stress.zz \
            		 
            --gendata_sql=conf/mariadb/table_stress.sql \
            		 
            --engine=Innodb \
            		 
            --reporters=Deadlock,ErrorLog,Backtrace \
            		 
            --mysqld=--loose_innodb_use_native_aio=0 \
            		 
            --mysqld=--connect_timeout=60 \
            		 
            --mysqld=--net_read_timeout=30 \
            		 
            --mysqld=--net_write_timeout=60 \
            		 
            --mysqld=--loose-idle_readonly_transaction_timeout=0 \
            		 
            --mysqld=--loose-idle_transaction_timeout=0 \
            		 
            --mysqld=--loose-idle_write_transaction_timeout=0 \
            		 
            --mysqld=--interactive_timeout=28800 \
            		 
            --mysqld=--lock_wait_timeout=86400 \
            		 
            --mysqld=--innodb-lock-wait-timeout=50 \
            		 
            --mysqld=--loose-table_lock_wait_timeout=50 \
            		 
            --mysqld=--wait_timeout=28800 \
            		 
            --mysqld=--slave_net_timeout=60 \
            		 
            --mysqld=--log-output=none \
            		 
            --duration=300 \
            		 
            --seed=random \
            		 
            --sqltrace=MarkErrors \
            		 
            --threads=32 \
            		 
            --mysqld=--innodb-flush-log-at-trx-commit=2 \
            		 
            --mysqld=--transaction-isolation=READ-COMMITTED \
            		 
            --grammar=table_stress.yy \
            		 
            --threads=12 \
            		 
            --workdir=<..> \
            		 
            --vardir=<...> \
            		 
            --mtr-build-thread=<...> \
            		 
            --basedir1=<...>
            		 
            <...> == Setting specific to the testing box and point of time of RQG run.
            		 
            But the likelihood to replay that problem is extreme low
            		 
                  8 CPU box, 1h ~90% CPU busy, 300 RQG runs, 1 replay only

            mleich Matthias Leich added a comment - Replay of the problem (same assert hit) on 10.4 commit 4edb29380c98058a28e49c826bacee9c83473579 2019-01-18 with my "experimental" RQG git clone https://github.com/mleich1/rqg --branch experimental RQG_new2 and /work/RQG_new2/rqg.pl \ --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \ --grammar=conf/mariadb/table_stress.yy \ --gendata=conf/mariadb/table_stress.zz \ --gendata_sql=conf/mariadb/table_stress.sql \ --engine=Innodb \ --reporters=Deadlock,ErrorLog,Backtrace \ --mysqld=--loose_innodb_use_native_aio=0 \ --mysqld=--connect_timeout=60 \ --mysqld=--net_read_timeout=30 \ --mysqld=--net_write_timeout=60 \ --mysqld=--loose-idle_readonly_transaction_timeout=0 \ --mysqld=--loose-idle_transaction_timeout=0 \ --mysqld=--loose-idle_write_transaction_timeout=0 \ --mysqld=--interactive_timeout=28800 \ --mysqld=--lock_wait_timeout=86400 \ --mysqld=--innodb-lock-wait-timeout=50 \ --mysqld=--loose-table_lock_wait_timeout=50 \ --mysqld=--wait_timeout=28800 \ --mysqld=--slave_net_timeout=60 \ --mysqld=--log-output=none \ --duration=300 \ --seed=random \ --sqltrace=MarkErrors \ --threads=32 \ --mysqld=--innodb-flush-log-at-trx-commit=2 \ --mysqld=--transaction-isolation=READ-COMMITTED \ --grammar=table_stress.yy \ --threads=12 \ --workdir=<..> \ --vardir=<...> \ --mtr-build-thread=<...> \ --basedir1=<...> <...> == Setting specific to the testing box and point of time of RQG run. But the likelihood to replay that problem is extreme low 8 CPU box, 1h ~90% CPU busy, 300 RQG runs, 1 replay only
            mleich Matthias Leich added a comment - - edited 

            MDEV-15658.tgz contains my MTR based test for replaying the problem.
            		 
            The replay testcase requires some Linux.
            		 
             
            		 
            cd <source_dir>/mysql-test
            		 
            tar xvzf <path_to_dir_with_archive>/MDEV-15658.tgz
            		 
                   main/MDEV-15658.test 
                   mysqltest_background.sh
            		 
            cd <build_dir>/mysql-test
            		 
            ./mysql-test-run.pl --mem MDEV-15658
            		 
            You will see
            		 
            - a bit SQL 
            - many times the output of SHOW PROCESSLIST
            		 
            hopefully followed finally by the assert.
            		 
             
            		 
            Quite fast replay on
            		 
            10.3.14 commit 51e48b9f8981986257a1cfbdf75e4fc29a5959c1
            		 
            10.4.4    commit 514b305dfb2839c619a623bbdae5f21cf0077672 2019-02-20
            		 
            I had several attempts to replay the problem on
            		 
            10.2 commit 1caec9c8982a73f3db78fabc570934b837658109 2019-03-21
            		 
            without success.
            		 
             
            		 
            Sorry for the properties of mysqltest_background.sh but up till today
            		 
            I have not found a better way for MTR based brute force tests which
            		 
            replay problems found with RQG.

            mleich Matthias Leich added a comment - - edited MDEV-15658.tgz contains my MTR based test for replaying the problem. The replay testcase requires some Linux.   cd <source_dir>/mysql-test tar xvzf <path_to_dir_with_archive>/MDEV-15658.tgz main/MDEV-15658.test mysqltest_background.sh cd <build_dir>/mysql-test ./mysql-test-run.pl --mem MDEV-15658 You will see - a bit SQL - many times the output of SHOW PROCESSLIST hopefully followed finally by the assert.   Quite fast replay on 10.3.14 commit 51e48b9f8981986257a1cfbdf75e4fc29a5959c1 10.4.4 commit 514b305dfb2839c619a623bbdae5f21cf0077672 2019-02-20 I had several attempts to replay the problem on 10.2 commit 1caec9c8982a73f3db78fabc570934b837658109 2019-03-21 without success.   Sorry for the properties of mysqltest_background.sh but up till today I have not found a better way for MTR based brute force tests which replay problems found with RQG.
            marko Marko Mäkelä added a comment -

            This turned out to be a bug in the debug check only. Non-debug executables were not affected.

            marko Marko Mäkelä added a comment - This turned out to be a bug in the debug check only. Non-debug executables were not affected.

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 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.