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

fil_rename_tablespace() times out and crashes server during table-rebuilding ALTER TABLE

    XMLWordPrintable

Details

    Description

      We are getting periodic crashes on our staging server, whilst adding a column and an index. to a table. There are about 200 databases in the server and these are updated to our latest development schemas nightly ready for testing. We will typically get a crash every other day or so. The database that fails varies, but each typically has several hundred thousand rows. The table update that triggers the crash is always:

       ALTER TABLE order_line_items
              ADD COLUMN `is_bundle_parent` tinyint(1) NOT NULL default 0,
              ADD INDEX `index_order_line_items_on_is_bundle_parent` (`is_bundle_parent`)
      

      Immediately before this alter table we update pretty much all the rows the table. which I suspect may be relevant,

      UPDATE order_line_items SET bundle_line_item_id=id WHERE bundle_line_item_id IS NULL
      

      In the mysql error log we see:

      2018-05-08 22:43:00 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 1000 times. There are either pending IOs or flushes or the file is being extended.
      2018-05-08 22:43:20 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 2000 times. There are either pending IOs or flushes or the file is being extended.
      2018-05-08 22:43:40 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 3000 times. There are either pending IOs or flushes or the file is being extended.
      2018-05-08 22:44:00 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 4000 times. There are either pending IOs or flushes or the file is being extended.
      2018-05-08 22:44:20 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 5000 times. There are either pending IOs or flushes or the file is being extended.
      2018-05-08 22:44:40 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 6000 times. There are either pending IOs or flushes or the file is being extended.
      2018-05-08 22:45:00 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 7000 times. There are either pending IOs or flushes or the file is being extended.
      2018-05-08 22:45:20 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 8000 times. There are either pending IOs or flushes or the file is being extended.
      2018-05-08 22:45:40 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 9000 times. There are either pending IOs or flushes or the file is being extended.
      2018-05-08 22:46:00 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 10000 times. There are either pending IOs or flushes or the file is being extended.
      2018-05-08 22:46:21 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 11000 times. There are either pending IOs or flushes or the file is being extended.
      

      followed by

      --Thread 140184803284736 has waited at row0purge.cc line 853 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x563589733d10 created in file dict0dict.cc line 1107
      a writer (thread id 140184283293440) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0purge.cc line 853
      Last time write locked in file handler0alter.cc line 8546
      2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
      --Thread 140184278025984 has waited at dict0dict.cc line 1160 for 116.00 seconds the semaphore:
      Mutex at 0x563589733d90, Mutex DICT_SYS created dict0dict.cc:1096, lock var 2
       
      2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
      --Thread 140184736397056 has waited at ibuf0ibuf.cc line 4578 for 240.00 seconds the semaphore:
      S-lock on RW-latch at 0x7f805f7eaf48 created in file buf0buf.cc line 1471
      a writer (thread id 140184744789760) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ibuf0ibuf.cc line 4578
      Last time write locked in file mtr0mtr.ic line 147
      2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
      --Thread 140184728004352 has waited at ibuf0ibuf.cc line 4578 for 240.00 seconds the semaphore:
      S-lock on RW-latch at 0x7f805f7eaf48 created in file buf0buf.cc line 1471
      a writer (thread id 140184744789760) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ibuf0ibuf.cc line 4578
      Last time write locked in file mtr0mtr.ic line 147
      2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
      --Thread 140184803284736 has waited at row0purge.cc line 853 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x563589733d10 created in file dict0dict.cc line 1107
      a writer (thread id 140184283293440) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0purge.cc line 853
      Last time write locked in file handler0alter.cc line 8546
      2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
      --Thread 140184783165184 has waited at row0mysql.cc line 1780 for 240.00 seconds the semaphore:
      S-lock on RW-latch at 0x563589733d10 created in file dict0dict.cc line 1107
      a writer (thread id 140184283293440) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0purge.cc line 853
      Last time write locked in file handler0alter.cc line 8546
      2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
      --Thread 140184270636800 has waited at dict0dict.cc line 1160 for 233.00 seconds the semaphore:
      Mutex at 0x563589733d90, Mutex DICT_SYS created dict0dict.cc:1096, lock var 2
       
      2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
      --Thread 140184853640960 has waited at srv0srv.cc line 2089 for 240.00 seconds the semaphore:
      X-lock on RW-latch at 0x563589733d10 created in file dict0dict.cc line 1107
      a writer (thread id 140184283293440) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0purge.cc line 853
      Last time write locked in file handler0alter.cc line 8546
      2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
      --Thread 140184753182464 has waited at ibuf0ibuf.cc line 4578 for 240.00 seconds the semaphore:
      S-lock on RW-latch at 0x7f805f7eaf48 created in file buf0buf.cc line 1471
      a writer (thread id 140184744789760) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ibuf0ibuf.cc line 4578
      Last time write locked in file mtr0mtr.ic line 147
      2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
      --Thread 140184744789760 has waited at mtr0mtr.ic line 147 for 240.00 seconds the semaphore:
      X-lock on RW-latch at 0x7f805f8749d8 created in file buf0buf.cc line 1471
      a writer (thread id 0) has reserved it in mode  SX
      number of readers 0, waiters flag 1, lock_word: 10000000
      Last time read locked in file ibuf0ibuf.cc line 4578
      Last time write locked in file buf0flu.cc line 1213
      2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
      --Thread 140184820070144 has waited at dict0stats_bg.cc line 341 for 235.00 seconds the semaphore:
      Mutex at 0x563589733d90, Mutex DICT_SYS created dict0dict.cc:1096, lock var 2
       
      2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
      --Thread 140184648525568 has waited at dict0dict.cc line 1160 for 35.00 seconds the semaphore:
      Mutex at 0x563589733d90, Mutex DICT_SYS created dict0dict.cc:1096, lock var 2
      

      The engine innodb status is the dumped. This is attached.

      We have experimented with setting the following, but this has has no affect.

      innodb_purge_threads           = 1
      innodb_adaptive_hash_index_parts = 1
      

      Attachments

        1. engine_status.log
          20 kB
        2. crash.log
          34 kB
        3. common.cnf
          6 kB

        Issue Links

          Activity

            People

              marko Marko Mäkelä
              Whitehouse Steve
              Votes:
              0 Vote for this issue
              Watchers:
              4 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.