3

This is a bit of a strange one (and a big post, sorry), i am working with a customer who runs MariaDB on Windows (Server 2008 R2). They have several large MyISAM tables (up to 30 GB each, 200+ million rows) and for several reasons i'm converting them to InnoDB. Most tables converted fine, however a handful of them are fully locking up the InnoDB engine. When i say fully locking up, i mean that the progress % stops increasing, all CPU/Disk activity for mysqld stops, and most tasks that are InnoDB related stop working. Even running "SHOW ENGINE InnoDB STATUS" hangs. I have let it sit for up to a day and it remains at the same percentage.

A few things to note:

  • This runs in a ESXi VM and is a clone of their production VM, so there is absolutely zero traffic (separate hardware, no clients connected).
  • The VM has 8 CPU cores and 16 GB of RAM, neither of which are being stressed at all.
  • I have tried disabling the query cache, no change in results
  • As mentioned before, the conversion process will hang somewhere in the middle of phase 1 (copying to tmp table), and the percentage will stop increasing. At that point, there is no CPU or Disk activity associated with mysqld.
  • There is nothing logged at the time of the hang, only messages prior to it about long semaphore waits.
  • We are running innodb_file_per_table.
  • On a hunch, i verified that the temporary .ibd file is not getting too fragmented, on the last conversion attempt it was in 99 fragments.
  • This did not happen to all tables, and it also didn't happen to just the largest tables. I had a 7 GB one (with 100m rows) fail and a 30 GB one (with 200m rows) succeed.
  • It always fails around the same spot on the table in question.
  • All tables have had full MyISAM checks/repairs done
  • No errors are logged to the Windows System log
  • We are running the latest 10.2 branch (stable). I considered going to 10.3 but i did not see anything that sounded like it could be related in the release notes.
  • Checking procexp, there are two threads active in mysqld that are both showing ntoskrnl.exe!KeWaitForMultipleObjects+0xc0a. Screenshots of both stacks are below.
  • Checking procmon, there is absolutely zero activity in mysqld.exe.
  • While it is hung, MyISAM tables can be queried against, but any InnoDB query hangs.
  • I did find this thread and set innodb_adaptive_hash_index=0 but it did not make any difference.
  • All other aspects of the system are functioning fine (though it is nothing but a SQL server), and it has been rebooted several times.
  • Some may notice that i have doublewrite turned off, this is for testing only and will be disabled for production.

A few screenshots: process stats thread stack 1 thread stack 2

Excerpt of possibly important data from the log: (this is repeated several times)

InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 0, writes 0

=====================================
2017-12-28 15:54:44 0x3c8 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 17 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1788 srv_active, 0 srv_shutdown, 67 srv_idle
srv_master_thread log flush and writes: 1854
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 59085
--Thread 3892 has waited at ibuf0ibuf.cc line 3460 for 247.00 seconds the semaphore:
S-lock on RW-latch at 00000000975EFC68 created in file buf0buf.cc line 1471
a writer (thread id 3800) 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 3460
Last time write locked in file mtr0mtr.ic line 147
--Thread 2944 has waited at ibuf0ibuf.cc line 4578 for 247.00 seconds the semaphore:
S-lock on RW-latch at 00000000975EFC68 created in file buf0buf.cc line 1471
a writer (thread id 3800) 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 3460
Last time write locked in file mtr0mtr.ic line 147
--Thread 3700 has waited at buf0flu.cc line 1246 for 246.00 seconds the semaphore:
SX-lock on RW-latch at 00000000975EFC68 created in file buf0buf.cc line 1471
a writer (thread id 3800) 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 3460
Last time write locked in file mtr0mtr.ic line 147
--Thread 3800 has waited at buf0buf.cc line 4136 for 247.00 seconds the semaphore:
S-lock on RW-latch at 000000018299B078 created in file buf0buf.cc line 1471
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file buf0buf.cc line 5363
--Thread 2564 has waited at ibuf0ibuf.cc line 4578 for 247.00 seconds the semaphore:
S-lock on RW-latch at 00000000975EFC68 created in file buf0buf.cc line 1471
a writer (thread id 3800) 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 3460
Last time write locked in file mtr0mtr.ic line 147
--Thread 3484 has waited at ibuf0ibuf.cc line 4578 for 247.00 seconds the semaphore:
S-lock on RW-latch at 00000000975EFC68 created in file buf0buf.cc line 1471
a writer (thread id 3800) 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 3460
Last time write locked in file mtr0mtr.ic line 147
--Thread 3200 has waited at ibuf0ibuf.cc line 2720 for 246.00 seconds the semaphore:
Mutex at 00000001406064F8, Mutex IBUF created ibuf0ibuf.cc:516, lock var 2

OS WAIT ARRAY INFO: signal count 46563
RW-shared spins 0, rounds 53529, OS waits 24403
RW-excl spins 0, rounds 480664, OS waits 7825
RW-sx spins 2641, rounds 24044, OS waits 184
Spin rounds per wait: 53529.00 RW-shared, 480664.00 RW-excl, 9.10 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 94794
Purge done for trx's n:o < 94152 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 281476765058824, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 94793, ACTIVE 247 sec inserting
mysql tables in use 1, locked 1
1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1930
MySQL thread id 8, OS thread handle 3892, query id 1 ::1 root copy to tmp table
alter table dbname.table_being_converted engine=innodb
--------
FILE I/O
--------
I/O thread 0 state: complete io for buf page (insert buffer thread)
I/O thread 1 state: complete io for buf page (log thread)
I/O thread 2 state: complete io for buf page (read thread)
I/O thread 3 state: complete io for buf page (read thread)
I/O thread 4 state: native aio handle (read thread)
I/O thread 5 state: native aio handle (read thread)
I/O thread 6 state: native aio handle (write thread)
I/O thread 7 state: native aio handle (write thread)
I/O thread 8 state: native aio handle (write thread)
I/O thread 9 state: native aio handle (write thread)
Pending normal aio reads: [0, 0, 2, 4] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
108072 OS file reads, 2437337 OS file writes, 23912 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
InnoDB: ###### Diagnostic info printed to the standard error stream
2017-12-28 15:55:09 3240 [Warning] InnoDB: A long semaphore wait:
--Thread 3892 has waited at ibuf0ibuf.cc line 3460 for 272.00 seconds the semaphore:
S-lock on RW-latch at 00000000975EFC68 created in file buf0buf.cc line 1471
a writer (thread id 3800) 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 3460
Last time write locked in file mtr0mtr.ic line 147
(snip, above data is repeated a lot)

my.ini contents:

[mysqld]
datadir=D:/SQLData
port=3306
default-storage-engine=InnoDB
innodb_buffer_pool_size=4096M
innodb_log_file_size=256M
innodb_doublewrite = 0
innodb_file_per_table
innodb_force_recovery=1

max_connections=500
query_cache_size=4096M
skip-name-resolve
slow_query_log
log-error=Errors.log

myisam_sort_buffer_size=768M
tmp_table_size=768M
key_buffer_size=2048M
read_rnd_buffer_size=5M
sort_buffer_size=32M
  • if you like an authoritative answer, and possibly a fix, take a minidump of the process, file a bug into MariaDB's JIRA jira.mariadb.org, and attach this minidump. The callstacks you have posted are not accurate, the debug symbols path is not set correctly. – Vladislav Vaintroub Jan 14 '18 at 22:34

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.