| Bug #83560 | InnoDB FTS - output from mysqldump extremely slow and blocks unrelated inserts | ||
|---|---|---|---|
| Submitted: | 27 Oct 2016 4:28 | Modified: | 1 Mar 2022 20:51 |
| Reporter: | Brett Gardner | Email Updates: | |
| Status: | Duplicate | Impact on me: | |
| Category: | MySQL Server: FULLTEXT search | Severity: | S2 (Serious) |
| Version: | 5.6.34 | OS: | CentOS (7.2.1511 (Core)) |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | innodb fts | ||
[27 Oct 2016 4:28]
Brett Gardner
[27 Oct 2016 4:29]
Brett Gardner
Engine InnoDB status
Attachment: slow-fts-load.log (text/x-log), 6.07 KiB.
[27 Oct 2016 4:30]
Brett Gardner
Note that there was no other select / insert activity into the deepindex table whilst the bulk insert was occurring.
[1 Nov 2016 13:26]
MySQL Verification Team
Thank you for the bug report. Does difference first to create the table without the FTS indexes, load the data and after that to create the indexes?. Thanks.
[8 Nov 2016 4:27]
Brett Gardner
Re adding the indexes after the data, in this case I did not attempt this, however this caused similar problems under mysql 5.6.23 Note that this would not be a feasible solution though as 1. mysqldump does not output its data in this manner 2. A bulk import of data, eg just importing 10,000 rows could potentially block all other inserts into any other table in any database on that server
[30 Nov 2016 11:47]
MySQL Verification Team
Hi, I'm having issues reproducing this ?! If I understood the problem properly you do have disable keys before inserts and enable keys after them while you are experiencing the problem? thanks Bogdan
[1 Dec 2016 20:47]
Brett Gardner
I am not using "disable keys". The documentation states that "disable keys" only works for MyISAM tables. http://dev.mysql.com/doc/refman/5.6/en/alter-table.html
[1 Dec 2016 20:51]
Brett Gardner
Also, "disable keys" would not work in a production sense as the user who is importing the data does not have "alter table" rights Also note that I am not using FTS_DOC_ID due to the problems with large gaps. eg 1. 100,000 rows are inserted 2. rows with ids 200 -> 80,000 are deleted 3. The output from mysqldump cannot be used without the FTS_DOC_ID values being written as there would be a gap of more than the allowed 65535 between 199 and 80,001
[6 Dec 2016 12:09]
MySQL Verification Team
Hi, yes, that is true, the way innodb handles fts, disable keys won't help. I did a simple test and using extended insert reduced the import speed of a test table by 80%. You can export data like that directly with mysqldump -e. As for the suggestion Miguel gave, this increased speed even more (total of more then 20x faster). As for the comment that "mysqldump is not generating output like that", you can generate the table structure only with mysqldump, edit it manually and then dump data (with -e ) and then execute alter to add all indexes. Little bit of manual work but you will get a lot of speed out of it... I know it is not perfect but it is a decent work around. Now, none of this is a bug. What I see as a bug in your report is that your "other tables" are locked while this import takes place. I created a test table with some test data where insert lasts 40 minutes and while the whole system becomes super slow (io limited) nothing is locked. Can you please help me reproduce the bug part of this issue as the performance issue you describe, while ugly, is not really a bug. kind regards Bogdan
[6 Dec 2016 22:25]
Brett Gardner
I can only recreate it with client data, which I cannot copy into here. Below is the InnoDB status which shows the semaphores ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 161886 --Thread 140701197281024 has waited at srv0srv.cc line 2006 for 954.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x139a8e0 created in file dict0dict.cc line 1066 a writer (thread id 140701197281024) has reserved it in mode wait exclusive number of readers 1, waiters flag 1, lock_word: ffffffffffffffff Last time read locked in file fts0opt.cc line 2980 Last time write locked in file /export/home2/pb2/build/sb_1-20604842-1475255145.52/rpm/BUILD/mysql-5.6.34/mysql-5.6.34/storage/innobase/srv/srv0srv.cc line 2006 --Thread 140701138532096 has waited at dict0stats.cc line 2388 for 838.00 seconds the semaphore: X-lock on RW-latch at 0x139a8e0 created in file dict0dict.cc line 1066 a writer (thread id 140701197281024) has reserved it in mode wait exclusive number of readers 1, waiters flag 1, lock_word: ffffffffffffffff Last time read locked in file fts0opt.cc line 2980 Last time write locked in file /export/home2/pb2/build/sb_1-20604842-1475255145.52/rpm/BUILD/mysql-5.6.34/mysql-5.6.34/storage/innobase/srv/srv0srv.cc line 2006 --Thread 140701094143744 has waited at row0mysql.cc line 1743 for 886.00 seconds the semaphore: S-lock on RW-latch at 0x139a8e0 created in file dict0dict.cc line 1066 a writer (thread id 140701197281024) has reserved it in mode wait exclusive number of readers 1, waiters flag 1, lock_word: ffffffffffffffff Last time read locked in file fts0opt.cc line 2980 Last time write locked in file /export/home2/pb2/build/sb_1-20604842-1475255145.52/rpm/BUILD/mysql-5.6.34/mysql-5.6.34/storage/innobase/srv/srv0srv.cc line 2006 --Thread 140701102802688 has waited at fts0fts.cc line 4052 for 25.00 seconds the semaphore: X-lock on RW-latch at 0x7ff7645a71c8 created in file fts0fts.cc line 632 a writer (thread id 140701093345024) 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 /export/home2/pb2/build/sb_1-20604842-1475255145.52/rpm/BUILD/mysql-5.6.34/mysql-5.6.34/storage/innobase/fts/fts0fts.cc line 3542 --Thread 140701093611264 has waited at ha_innodb.cc line 9729 for 400.00 seconds the semaphore: X-lock on RW-latch at 0x139a8e0 created in file dict0dict.cc line 1066 a writer (thread id 140701197281024) has reserved it in mode wait exclusive number of readers 1, waiters flag 1, lock_word: ffffffffffffffff Last time read locked in file fts0opt.cc line 2980 Last time write locked in file /export/home2/pb2/build/sb_1-20604842-1475255145.52/rpm/BUILD/mysql-5.6.34/mysql-5.6.34/storage/innobase/srv/srv0srv.cc line 2006 OS WAIT ARRAY INFO: signal count 158155 Mutex spin waits 383500, rounds 2407449, OS waits 62999 RW-shared spins 23839, rounds 417406, OS waits 13436 RW-excl spins 382856, rounds 4940348, OS waits 80448 Spin rounds per wait: 6.28 mutex, 17.51 RW-shared, 12.90 RW-excl ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf: size 1, free list len 0, seg size 2, 62 merges merged operations: insert 125, delete mark 27, delete 20 discarded operations: insert 0, delete mark 0, delete 0 Hash table size 9025073, node heap has 338 buffer(s) 0.00 hash searches/s, 0.00 non-hash searches/s And the log re the crash initiated by MySQL itself InnoDB: ###### Diagnostic info printed to the standard error stream InnoDB: Error: semaphore wait has lasted > 600 seconds InnoDB: We intentionally crash the server, because it appears to be hung. 2016-10-27 13:16:42 7ff78be20700 InnoDB: Assertion failure in thread 140701180495616 in file srv0srv.cc line 1756 InnoDB: We intentionally generate a memory trap. InnoDB: Submit a detailed bug report to http://bugs.mysql.com. InnoDB: If you get repeated assertion failures or crashes, even InnoDB: immediately after the mysqld startup, there may be InnoDB: corruption in the InnoDB tablespace. Please refer to InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html InnoDB: about forcing recovery. 02:16:42 UTC - 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. 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.
[7 Dec 2016 3:39]
MySQL Verification Team
Hi, > I can only recreate it with client data, which I cannot copy into here. weird behavior :( I tried reproducing with dummy data without luck. Can you test please how it behaves with "regular" load of data (one record per insert) and with extended-insert (multiple records per insert)? Do you see any difference in load time. And do you see a difference in that locking of other tables. Thanks Bogdan
[7 Dec 2016 3:42]
Brett Gardner
Unfortunately not. I was doing this on a spare production server that has since been placed into use and so I have no easy way to recreate this problem. For the moment, we have gone back to using MyISAM for our full text searches.
[7 Dec 2016 3:52]
MySQL Verification Team
Hi, Too bad :( would have confirmed my findings. I'm setting this bug to "verified" since doing the testing in past couple of days trying to figure out what's going on, from the original report: > After approximately 1GB, each "INSERT" statement > starts getting exponentially slower, up to 130 seconds. This I do reproduce quite easily. I do understand "why" this happens and why it might not be considered a bug, but I personally consider this a showstopper for upgrading from MyISAM to InnoDB for tables with big FTS index so I do consider it a bug. I did see a significant improvement by using extended (bulk) insert (more then 10x speedup of a total import of data) but I still see that it gets slower as the table increases, way slower then MyISAM. Also, I see that 5.7 handles this lot better then 5.6. Now the part of the report where you claim "Also, an insert into an InnoDB table on the same server, but in a separate database, is also blocked whilst the INSERT into the full text index table is occurring." This I cannot reproduce, not in 5.6 nor in 5.7. I loaded 10G table, on a slow box, load took more then 24 hours to finish, and I was normally using all other tables on the server without a problem. kind regards Bogdan Kecman
[4 Feb 2019 6:04]
MySQL Verification Team
I'm seeing this on tests on 8.0.13 on a table with fulltext indexes too. Seems long semaphore waits will eventually let InnoDB to kill itself. Here's the starting of a problem, take note the "doing SYNC index" takes longer and longer, but also the server is NOT hanging, so it's really just slow. ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 97999 --Thread 11008 has waited at fts0fts.cc line 3673 for 22.00 seconds the semaphore: X-lock on RW-latch at 000000005FED2228 created in file fts0fts.cc line 538 a writer (thread id 11328) 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 G:\ade\build\sb_0-30892416-1538906989.33\mysql-8.0.13\storage\innobase\fts\fts0fts.cc line 4106 --Thread 7244 has waited at fts0fts.cc line 3673 for 22.00 seconds the semaphore: X-lock on RW-latch at 000000005FED2228 created in file fts0fts.cc line 538 a writer (thread id 11328) 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 G:\ade\build\sb_0-30892416-1538906989.33\mysql-8.0.13\storage\innobase\fts\fts0fts.cc line 4106 OS WAIT ARRAY INFO: signal count 95368 RW-shared spins 13384, rounds 14700, OS waits 1346 RW-excl spins 363267, rounds 5139869, OS waits 91019 RW-sx spins 141, rounds 4230, OS waits 138 Spin rounds per wait: 1.10 RW-shared, 14.15 RW-excl, 30.00 RW-sx ------------ TRANSACTIONS ------------ Trx id counter 60724 Purge done for trx's n:o < 59032 undo n:o < 0 state: running but idle History list length 2 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 281475325759888, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 60723, ACTIVE 22 sec committing 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 10 MySQL thread id 7, OS thread handle 7244, query id 475531 localhost ::1 root waiting for handler commit commit ---TRANSACTION 60721, ACTIVE 22 sec committing 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 10 MySQL thread id 8, OS thread handle 11008, query id 475478 localhost ::1 root waiting for handler commit commit ---TRANSACTION 58517, ACTIVE 38 sec doing SYNC index 10 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 205686 -------- FILE I/O -------- I/O thread 0 state: wait Windows aio (insert buffer thread) I/O thread 1 state: wait Windows aio (log thread) I/O thread 2 state: wait Windows aio (read thread) I/O thread 3 state: wait Windows aio (read thread) I/O thread 4 state: wait Windows aio (read thread) I/O thread 5 state: wait Windows aio (read thread) I/O thread 6 state: wait Windows aio (write thread) I/O thread 7 state: wait Windows aio (write thread) I/O thread 8 state: wait Windows aio (write thread) I/O thread 9 state: wait Windows aio (write thread) Pending normal aio reads: [0, 0, 0, 0] , aio writes: [31, 0, 15, 4] , ibuf aio reads:, log i/o's:, sync i/o's: Pending flushes (fsync) log: 1; buffer pool: 3 6920 OS file reads, 2577636 OS file writes, 7178 OS fsyncs 0.00 reads/s, 0 avg bytes/read, 4878.27 writes/s, 15.74 fsyncs/s
[20 May 2019 10:41]
Aakanksha Verma
Closing as duplicate of bug#84237 which is fixed now
[1 Mar 2022 20:51]
Brett Gardner
This is marked as a duplicate of https://bugs.mysql.com/bug.php?id=84237 However, I cannot see the details of that bug so have no way of knowing the details of the fix, when it was fixed etc. Can these details please be linked into this issue.
