Bug #83560 InnoDB FTS - output from mysqldump extremely slow and blocks unrelated inserts
Submitted: 27 Oct 2016 4:28 Modified: 7 Dec 2016 3:52
Reporter: Brett Gardner Email Updates:
Status: Verified Impact on me:
None 
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
Description:
Attempting to load an InnoDB table with a FULLTEXT index results in exceptionally slow inserts and blocks inserts into other databases.

The data size in question is approximately 4GB, spread across 100,000 entries

After approximately 1GB, each "INSERT" statement starts getting exponentially slower, up to 130 seconds.

There are semaphore wait notices in the error log, and at a wait of 600 seconds, the server can crash on purpose by inserting a memory trap.

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.

The schema of the table in question is as follows

CREATE TABLE `deepindex` (
  `ObjectTypeID` int(10) unsigned NOT NULL,
  `ObjectID` int(10) unsigned NOT NULL,
  `FromDate` datetime NOT NULL,
  `ToDate` datetime DEFAULT NULL,
  `Name` varchar(255) NOT NULL,
  `Content` mediumtext,
  `LastModDate` datetime NOT NULL,
  PRIMARY KEY (`ObjectTypeID`,`ObjectID`),
  FULLTEXT KEY `Name` (`Name`),
  FULLTEXT KEY `Content` (`Content`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8

This does not have the FTS_DOC_ID column, however changing to add one one will not help when using the output from mysqldump as mysqldump creates the index in the CREATE TABLE statement, rather than delaying the index till after all data has been inserted.

How to repeat:
Attempt to insert 4GB of data across 100,000 inserts into the following table schema

CREATE TABLE `deepindex` (
  `ObjectTypeID` int(10) unsigned NOT NULL,
  `ObjectID` int(10) unsigned NOT NULL,
  `FromDate` datetime NOT NULL,
  `ToDate` datetime DEFAULT NULL,
  `Name` varchar(255) NOT NULL,
  `Content` mediumtext,
  `LastModDate` datetime NOT NULL,
  PRIMARY KEY (`ObjectTypeID`,`ObjectID`),
  FULLTEXT KEY `Name` (`Name`),
  FULLTEXT KEY `Content` (`Content`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8

Whilst this insert is occurring, attempt a simple single line insert into another InnoDB table on the same server but into a different database
[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] Miguel Solorzano
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] Bogdan Kecman
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] Bogdan Kecman
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] Bogdan Kecman
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] Bogdan Kecman
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