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

Long semaphore wait upon DROP DATABASE with XA holding locks

    XMLWordPrintable

    Details

      Description

      When an uncommitted XA is using a table, DROP DATABASE executed in another connection doesn't respect lock_wait_timeout, it hangs until the server does not get killed by long semaphore wait.

      It looks quite similar to MDEV-22733, except that there is no shutdown here, and this one is reproducible on 10.2+, it's not 10.5-specific. So I guess it's somehow different.

      --source include/have_innodb.inc
       
      CREATE DATABASE db;
      USE db;
      CREATE TABLE t1 (a INT) ENGINE=InnoDB;
      XA BEGIN 'x';
      UPDATE t1 SET a = 1;
      --error ER_XAER_RMFAIL
      ALTER TABLE t2;
       
      --connect (con1,localhost,root,,test)
      SET lock_wait_timeout= 1;
      --error ER_LOCK_WAIT_TIMEOUT
      DROP DATABASE db;
       
      # Cleanup
      --disconnect con1
      --connection default
      XA END 'x';
      XA ROLLBACK 'x';
      DROP DATABASE db;
      

      The test case above hangs on DROP DATABASE db instead of aborting it with ER_LOCK_WAIT_TIMEOUT.
      innodb_lock_wait_timeout doesn't have any effect either (I've removed it from the test case, as it probably shouldn't affect it anyway).

      Stack trace from the hanging server:

      10.2 4832b751

      Thread 28 (Thread 0x7fab6cba6700 (LWP 12848)):
      #0  0x0000563c93a77eb5 in rw_lock_validate (lock=0x563c961d2e50) at /data/src/10.2/storage/innobase/sync/sync0rw.cc:860
      #1  0x0000563c93a78278 in rw_lock_own (lock=0x563c961d2e50, lock_type=4) at /data/src/10.2/storage/innobase/sync/sync0rw.cc:998
      #2  0x0000563c93b29c93 in buf_pool_watch_is_sentinel (buf_pool=0x563c9617ffb0, bpage=0x7fab6cec1a58) at /data/src/10.2/storage/innobase/buf/buf0buf.cc:3343
      #3  0x0000563c93b2c640 in buf_page_get_low (page_id=..., page_size=..., rw_latch=1, guess=0x0, mode=10, file=0x563c94080920 "/data/src/10.2/storage/innobase/row/row0sel.cc", line=1338, mtr=0x7fab6cba2720, err=0x7fab6cba1598) at /data/src/10.2/storage/innobase/buf/buf0buf.cc:4283
      #4  0x0000563c93b2df72 in buf_page_get_gen (page_id=..., page_size=..., rw_latch=1, guess=0x7fab6cec1a58, mode=10, file=0x563c94080920 "/data/src/10.2/storage/innobase/row/row0sel.cc", line=1338, mtr=0x7fab6cba2720, err=0x7fab6cba1598) at /data/src/10.2/storage/innobase/buf/buf0buf.cc:4882
      #5  0x0000563c93af410a in btr_cur_search_to_nth_level_func (index=0x7fab44013890, level=0, tuple=0x7fab1803dc00, mode=PAGE_CUR_GE, latch_mode=1, cursor=0x7fab1803d910, has_search_latch=0, file=0x563c94080920 "/data/src/10.2/storage/innobase/row/row0sel.cc", line=1338, mtr=0x7fab6cba2720, autoinc=0) at /data/src/10.2/storage/innobase/btr/btr0cur.cc:1261
      #6  0x0000563c93a28fa0 in btr_pcur_open_with_no_init_func (index=0x7fab44013890, tuple=0x7fab1803dc00, mode=PAGE_CUR_GE, latch_mode=1, cursor=0x7fab1803d910, has_search_latch=0, file=0x563c94080920 "/data/src/10.2/storage/innobase/row/row0sel.cc", line=1338, mtr=0x7fab6cba2720) at /data/src/10.2/storage/innobase/include/btr0pcur.ic:521
      #7  0x0000563c93a2c973 in row_sel_open_pcur (plan=0x7fab1803d900, has_search_latch=0, mtr=0x7fab6cba2720) at /data/src/10.2/storage/innobase/row/row0sel.cc:1338
      #8  0x0000563c93a2d3c8 in row_sel (node=0x7fab1803d810, thr=0x7fab1803dd50) at /data/src/10.2/storage/innobase/row/row0sel.cc:1715
      #9  0x0000563c93a2e7ae in row_sel_step (thr=0x7fab1803dd50) at /data/src/10.2/storage/innobase/row/row0sel.cc:2399
      #10 0x0000563c939aecd4 in que_thr_step (thr=0x7fab1803dd50) at /data/src/10.2/storage/innobase/que/que0que.cc:1020
      #11 0x0000563c939aefee in que_run_threads_low (thr=0x7fab1803dd50) at /data/src/10.2/storage/innobase/que/que0que.cc:1104
      #12 0x0000563c939af1a3 in que_run_threads (thr=0x7fab1803dd50) at /data/src/10.2/storage/innobase/que/que0que.cc:1144
      #13 0x0000563c939af44c in que_eval_sql (info=0x7fab18041c10, sql=0x563c94108c48 "PROCEDURE DELETE_FROM_TABLE_STATS () IS\nBEGIN\nDELETE FROM \"mysql/innodb_table_stats\" WHERE\ndatabase_name = :database_name AND\ntable_name = :table_name;\nEND;\n", reserve_dict_mutex=0, trx=0x7fab6d7b94b8) at /data/src/10.2/storage/innobase/que/que0que.cc:1221
      #14 0x0000563c93b97e99 in dict_stats_exec_sql (pinfo=0x7fab18041c10, sql=0x563c94108c48 "PROCEDURE DELETE_FROM_TABLE_STATS () IS\nBEGIN\nDELETE FROM \"mysql/innodb_table_stats\" WHERE\ndatabase_name = :database_name AND\ntable_name = :table_name;\nEND;\n", trx=0x7fab6d7b94b8) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:305
      #15 0x0000563c93b9ebed in dict_stats_delete_from_table_stats (database_name=0x7fab6cba2e30 "db", table_name=0x7fab6cba2f00 "#mysql50##sql-ib19") at /data/src/10.2/storage/innobase/dict/dict0stats.cc:3469
      #16 0x0000563c93b9ee0a in dict_stats_drop_table (db_and_table=0x7fab18031dd0 "db/#sql-ib19", errstr=0x7fab6cba33e0 "", errstr_sz=1024) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:3554
      #17 0x0000563c93a03308 in row_drop_table_for_mysql (name=0x7fab18031dd0 "db/#sql-ib19", trx=0x7fab6d7b8390, sqlcom=SQLCOM_DROP_DB, create_failed=false, nonatomic=true) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3399
      #18 0x0000563c93a04b6b in row_drop_database_for_mysql (name=0x7fab18041a80 "db/", trx=0x7fab6d7b8390, found=0x7fab6cba4240) at /data/src/10.2/storage/innobase/row/row0mysql.cc:4008
      #19 0x0000563c938c9c24 in innobase_drop_database (hton=0x563c960cc6c0, path=0x7fab6cba47c0 "./db/") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13542
      #20 0x0000563c936c02f3 in dropdb_handlerton (unused1=0x0, plugin=0x7fab1803ce80, path=0x7fab6cba47c0) at /data/src/10.2/sql/handler.cc:742
      #21 0x0000563c9346201d in plugin_foreach_with_mask (thd=0x0, func=0x563c936c029a <dropdb_handlerton(THD*, plugin_ref, void*)>, type=1, state_mask=8, arg=0x7fab6cba47c0) at /data/src/10.2/sql/sql_plugin.cc:2402
      #22 0x0000563c936c0328 in ha_drop_database (path=0x7fab6cba47c0 "./db/") at /data/src/10.2/sql/handler.cc:749
      #23 0x0000563c93413571 in mysql_rm_db_internal (thd=0x7fab18000af0, db=0x7fab18011120 "db", if_exists=false, silent=false) at /data/src/10.2/sql/sql_db.cc:937
      #24 0x0000563c93413c4d in mysql_rm_db (thd=0x7fab18000af0, db=0x7fab18011120 "db", if_exists=false) at /data/src/10.2/sql/sql_db.cc:1071
      #25 0x0000563c9344ab65 in mysql_execute_command (thd=0x7fab18000af0) at /data/src/10.2/sql/sql_parse.cc:4736
      #26 0x0000563c9345427b in mysql_parse (thd=0x7fab18000af0, rawbuf=0x7fab18011088 "DROP DATABASE db", length=16, parser_state=0x7fab6cba5610, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7741
      #27 0x0000563c934425a8 in dispatch_command (command=COM_QUERY, thd=0x7fab18000af0, packet=0x7fab180088a1 "DROP DATABASE db", packet_length=16, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1832
      #28 0x0000563c93441023 in do_command (thd=0x7fab18000af0) at /data/src/10.2/sql/sql_parse.cc:1385
      #29 0x0000563c93596259 in do_handle_one_connection (connect=0x563c96675a00) at /data/src/10.2/sql/sql_connect.cc:1336
      #30 0x0000563c93595fc4 in handle_one_connection (arg=0x563c96675a00) at /data/src/10.2/sql/sql_connect.cc:1241
      #31 0x0000563c93dabc64 in pfs_spawn_thread (arg=0x563c965d1c30) at /data/src/10.2/storage/perfschema/pfs.cc:1869
      #32 0x00007fab7452c4a4 in start_thread (arg=0x7fab6cba6700) at pthread_create.c:456
      #33 0x00007fab72660d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
      

      All threads are attached.

      Eventually it ends up with this:

      =====================================
      2020-06-02 03:12:49 0x7fab5f7fe700 INNODB MONITOR OUTPUT
      =====================================
      Per second averages calculated from the last 20 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 1 srv_active, 0 srv_shutdown, 0 srv_idle
      srv_master_thread log flush and writes: 0
      ----------
      SEMAPHORES
      ----------
      -------------
      RW-LATCH INFO
      -------------
      RW-LOCK: 0x7fab44012468 
      RW-LOCK: 0x563c94808300 
      Locked: thread 140374240290560 file row0mysql.cc line 3921  X-LOCK
      RW-LOCK: 0x7fab6cea61b0 
      Total number of rw-locks 1075
      OS WAIT ARRAY INFO: reservation count 26
      --Thread 140374009960192 has waited at dict0dict.cc line 997 for 899.00 seconds the semaphore:
      Mutex at 0x563c96273b70, Mutex DICT_SYS created dict0dict.cc:1087, lock var 2
      Last time reserved in file /data/src/10.2/storage/innobase/row/row0mysql.cc line 2185
      OS WAIT ARRAY INFO: signal count 22
      RW-shared spins 4, rounds 36, OS waits 1
      RW-excl spins 5, rounds 93, OS waits 3
      RW-sx spins 0, rounds 0, OS waits 0
      Spin rounds per wait: 9.00 RW-shared, 18.60 RW-excl, 0.00 RW-sx
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 23867771
      Purge done for trx's n:o < 1289 undo n:o < 0 state: running but idle
      History list length 0
      Total number of lock structs in row lock hash table 1
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 23867768, ACTIVE 0 sec dropping table
      0 lock struct(s), heap size 1152, 0 row lock(s)
      MySQL thread id 10, OS thread handle 140374240290560, query id 26 localhost root Unlocking tables
      DROP DATABASE db
      ---TRANSACTION 421849229652584, not started
      0 lock struct(s), heap size 1152, 0 row lock(s)
      ---TRANSACTION 1284, ACTIVE 899 sec
      2 lock struct(s), heap size 1152, 1 row lock(s)
      MySQL thread id 9, OS thread handle 140374240597760, query id 24 localhost root 
      ---TRANSACTION 23867770, ACTIVE 0 sec
      0 lock struct(s), heap size 1152, 0 row lock(s)
      --------
      FILE I/O
      --------
      I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
      I/O thread 1 state: waiting for completed aio requests (log thread)
      I/O thread 2 state: waiting for completed aio requests (read thread)
      I/O thread 3 state: waiting for completed aio requests (read thread)
      I/O thread 4 state: waiting for completed aio requests (write thread)
      I/O thread 5 state: waiting for completed aio requests (write thread)
      Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
       ibuf aio reads:, log i/o's:, sync i/o's:
      Pending flushes (fsync) log: 0; buffer pool: 0
      188 OS file reads, 173 OS file writes, 14 OS fsyncs
      0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
      -------------------------------------
      INSERT BUFFER AND ADAPTIVE HASH INDEX
      -------------------------------------
      Ibuf: size 1, free list len 0, seg size 2, 0 merges
      merged operations:
       insert 0, delete mark 0, delete 0
      discarded operations:
       insert 0, delete mark 0, delete 0
      Hash table size 2267, node heap has 0 buffer(s)
      Hash table size 2267, node heap has 0 buffer(s)
      Hash table size 2267, node heap has 0 buffer(s)
      Hash table size 2267, node heap has 0 buffer(s)
      Hash table size 2267, node heap has 0 buffer(s)
      Hash table size 2267, node heap has 0 buffer(s)
      Hash table size 2267, node heap has 1 buffer(s)
      Hash table size 2267, node heap has 0 buffer(s)
      8915.60 hash searches/s, 17831.11 non-hash searches/s
      ---
      LOG
      ---
      Log sequence number 2595218
      Log flushed up to   1708106
      Pages flushed up to 1708106
      Last checkpoint at  1628870
      0 pending log flushes, 0 pending chkp writes
      14 log i/o's done, 0.00 log i/o's/second
      ----------------------
      BUFFER POOL AND MEMORY
      ----------------------
      Total large memory allocated 8798208
      Dictionary memory allocated 29184
      Buffer pool size   512
      Free buffers       201
      Database pages     310
      Old database pages 0
      Modified db pages  1
      Percent of dirty pages(LRU & free pages): 0.195
      Max dirty pages percent: 75.000
      Pending reads 0
      Pending writes: LRU 0, flush list 0, single page 0
      Pages made young 0, not young 0
      0.00 youngs/s, 0.00 non-youngs/s
      Pages read 174, created 136, written 162
      0.00 reads/s, 0.00 creates/s, 0.00 writes/s
      Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
      Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
      LRU len: 310, unzip_LRU len: 0
      I/O sum[0]:cur[0], unzip sum[0]:cur[0]
      --------------
      ROW OPERATIONS
      --------------
      0 queries inside InnoDB, 0 queries in queue
      0 read views open inside InnoDB
      Process ID=12816, Main thread ID=140374009960192, state: doing background drop tables
      Number of rows inserted 0, updated 0, deleted 0, read 0
      0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
      Number of system rows inserted 0, updated 0, deleted 0, read 0
      0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
      ----------------------------
      END OF INNODB MONITOR OUTPUT
      ============================
      2020-06-02  3:12:50 140374240597760 [Warning] Aborted connection 9 to db: 'db' user: 'root' host: 'localhost' (Got an error reading communication packets)
      200602  3:12:50 [ERROR] mysqld got signal 6 ;
      This could be because you hit a bug. It is also possible that this binary
      or one of the libraries it was linked against is corrupt, improperly built,
      or misconfigured. This error can also be caused by malfunctioning hardware.
       
      To report this bug, see https://mariadb.com/kb/en/reporting-bugs
       
      We will try our best to scrape up some info that will hopefully help
      diagnose the problem, but since we have already crashed, 
      something is definitely wrong and this may fail.
       
      Server version: 10.2.33-MariaDB-debug-log
      key_buffer_size=1048576
      read_buffer_size=131072
      max_used_connections=2
      max_threads=153
      thread_count=8
      It is possible that mysqld could use up to 
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63103 K  bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.
       
      Thread pointer: 0x0
      Attempting backtrace. You can use the following information to find out
      where mysqld died. If you see no messages after this, something went
      terribly wrong...
      stack_bottom = 0x0 thread_stack 0x49000
      mysys/stacktrace.c:267(my_print_stacktrace)[0x563c93e0885b]
      sql/signal_handler.cc:209(handle_fatal_signal)[0x563c936bda94]
      /lib/x86_64-linux-gnu/libpthread.so.0(+0x110e0)[0x7fab745360e0]
      unix/syscall-template.S:84(__poll)[0x7fab726578bd]
      2020-06-02  3:12:50 140374240290560 [Warning] Aborted connection 10 to db: 'test' user: 'root' host: 'localhost' (Got an error writing communication packets)
      sql/mysqld.cc:6667(handle_connections_sockets())[0x563c93359b50]
      sql/mysqld.cc:6138(mysqld_main(int, char**))[0x563c93358e32]
      sql/main.cc:26(main)[0x563c9334d6d0]
      csu/libc-start.c:325(__libc_start_main)[0x7fab725982e1]
      /data/bld/10.2-debug/bin/mysqld(_start+0x2a)[0x563c9334d5aa]
      The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
      information that should help you find out what is causing the crash.
      Writing a core file...
      Working directory at /data/bld/10.2-debug/mysql-test/var/mysqld.1/data
      Resource Limits:
      Limit                     Soft Limit           Hard Limit           Units     
      Max cpu time              unlimited            unlimited            seconds   
      Max file size             unlimited            unlimited            bytes     
      Max data size             unlimited            unlimited            bytes     
      Max stack size            8388608              unlimited            bytes     
      Max core file size        unlimited            unlimited            bytes     
      Max resident set          unlimited            unlimited            bytes     
      Max processes             128123               128123               processes 
      Max open files            1024                 1024                 files     
      Max locked memory         65536                65536                bytes     
      Max address space         unlimited            unlimited            bytes     
      Max file locks            unlimited            unlimited            locks     
      Max pending signals       128123               128123               signals   
      Max msgqueue size         819200               819200               bytes     
      Max nice priority         0                    0                    
      Max realtime priority     0                    0                    
      Max realtime timeout      unlimited            unlimited            us        
      Core pattern: core
      

        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: