MySQL Bugs: #110592: InnoDB FULLTEXT search result lost a record when recovery from a crash

Bug #110592	InnoDB FULLTEXT search result lost a record when recovery from a crash
Submitted:	3 Apr 2023 10:00	Modified:	11 May 2023 12:52
Reporter:	fei yang	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: FULLTEXT search	Severity:	S3 (Non-critical)
Version:	8.0.30	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	fulltext innodb, recovery crash

Description:
we insert a lots of records into a table with fulltext index and then hit a crash, when restart the mysql server, the results of fulltext search lost a record.

How to repeat:
step1 add 'innodb-ft-cache-size=0' into my.cnf before start mysql server to make sure the configuration of the innodb-ft-cache-size is the minimum value

step2 execute the following statement
drop PROCEDURE if exists insert_values_procedure;
DELIMITER $$
CREATE PROCEDURE insert_values_procedure(in row_count int)
begin
declare num_temp int;
set num_temp=0;
while num_temp<row_count do
insert into common values('abcd');
set num_temp=num_temp+1;
end while;
end;
$$
DELIMITER ;

drop table if exists common;
create table common(
c_text TEXT,
fulltext key idx(c_text))engine=innodb;

call insert_values_procedure(9000);

step3 execute 'kill -9 ${mysqld}' to make mysql server crash, where ${mysqld} is the pid of mysql server

step4 restart the mysql server and execute the following statement
select count(*) from test.common where C_TEXT like '%abcd%';
+----------+
| count(*) |
+----------+
|     9000 |
+----------+

select count(*) from test.common where match(C_TEXT) against('abcd');
+----------+
| count(*) |
+----------+
|     8999 |
+----------+

Hi Mr. ma,

Thank you for your bug report.

We were not able to repeat the bug that you are reporting.

A difference is that we have setup our MySQL server to be fully ACID compliant.

It is obvious that your setup is not ACID compliant.

This is all described in our Reference Manual.

Can't repeat.

This problem occurs probabilistically with the above steps. To make sure repeat this problem, we should add a debug sync point, the steps can be described as follows:

step1 add 'innodb-ft-cache-size=0' into my.cnf before start mysql server to make sure the configuration of the innodb-ft-cache-size is the minimum value, and start mysql server with option '--debug'. 
After these settings, The value of innodb_ft_cache_size should be 1600000. And the value of transaction_isolation is the same as default. You can execute the following statement to check it:
show variables like 'innodb_ft_cache_size';
+----------------------+---------+
| Variable_name        | Value   |
+----------------------+---------+
| innodb_ft_cache_size | 1600000 |
+----------------------+---------+

show variables like 'transaction_isolation';
+-----------------------+-----------------+
| Variable_name         | Value           |
+-----------------------+-----------------+
| transaction_isolation | REPEATABLE-READ |
+-----------------------+-----------------+

step2 execute the following statement to set debug sync point
set debug='d,fts_instrument_sync_write';
select@@debug;
+-----------------------------+
| @@debug                     |
+-----------------------------+
| d,fts_instrument_sync_write |
+-----------------------------+

step3 execute the following statement
create database test;
use test;
drop PROCEDURE if exists insert_values_procedure;
DELIMITER $$
CREATE PROCEDURE insert_values_procedure(in row_count int)
begin
declare num_temp int;
set num_temp=0;
while num_temp<row_count do
insert into common values('abcd');
set num_temp=num_temp+1;
end while;
end;
$$
DELIMITER ;

drop table if exists common;
create table common(
c_text TEXT,
fulltext key idx(c_text))engine=innodb;

call insert_values_procedure(9000);

step4 execute 'kill -9 ${mysqld}' to make mysql server crash after step3 finished, where ${mysqld} is the pid of mysql server

step5 restart the mysql server and execute the following statement
select count(*) from test.common where C_TEXT like '%abcd%';
+----------+
| count(*) |
+----------+
|     9000 |
+----------+

select count(*) from test.common where match(C_TEXT) against('abcd');
+----------+
| count(*) |
+----------+
|     8999 |
+----------+

Hi,

Please, re-read our previous comment .....

I'm sorry for my previous mistake,  In fact,  this problem is caused by race condition. I've generated a mysql-test case to make sure to repeat this problem.

#step1 Apply the following patch to 8.0.32

# Changes to be committed:
#   (use "git reset HEAD <file>..." to unstage)
#
#	new file:   mysql-test/t/fulltext_cache_recovery.test
#
# Changes not staged for commit:
#   (use "git add <file>..." to update what will be committed)
#   (use "git checkout -- <file>..." to discard changes in working directory)
#
#	modified:   storage/innobase/fts/fts0fts.cc

diff --git a/storage/innobase/fts/fts0fts.cc b/storage/innobase/fts/fts0fts.cc
index 2e36fac..00d79b0 100644
--- a/storage/innobase/fts/fts0fts.cc
+++ b/storage/innobase/fts/fts0fts.cc
@@ -2861,6 +2861,8 @@ retry:
     cache->synced_doc_id = std::max(doc_id_cmp, *doc_id);
   }
 
+  DBUG_EXECUTE_IF("fts_sync_add_next_doc_id_sleep",
+                        std::this_thread::sleep_for(std::chrono::seconds(10)););
   mutex_enter(&cache->doc_id_lock);
   /* For each sync operation, we will add next_doc_id by 1,
   so to mark a sync operation */

cat mysql-test/t/fulltext_cache_recovery.test
--disable_warnings
drop table if exists fts_t1;
--enable_warnings

CREATE TABLE fts_t1 (c1 TEXT,
fulltext key idx(c1))engine=innodb;

insert into fts_t1 values('abcd');
insert into fts_t1 values('abcd');
insert into fts_t1 values('abcd');

--source include/have_debug.inc
set global debug='+d,fts_sync_add_next_doc_id_sleep';
set debug='+d,fts_instrument_sync_request';
select @@debug;
insert into fts_t1 values('abcd');

connect (con1,localhost,root,,);
connection con1;
insert into fts_t1 values('abcd');

connection default;
--source include/kill_and_restart_mysqld.inc

select count(*) from fts_t1 where c1 like '%abcd%';
select count(*) from fts_t1 where match(c1) against('abcd');

drop tables fts_t1;

#step2 make a debug version of mysql-server

#step3 run this mysql-test case, and the output can be seen as follow:
----------- MYSQLTEST OUTPUT START -----------

drop table if exists fts_t1;
CREATE TABLE fts_t1 (c1 TEXT,
fulltext key idx(c1))engine=innodb;
insert into fts_t1 values('abcd');
insert into fts_t1 values('abcd');
insert into fts_t1 values('abcd');
set global debug='+d,fts_sync_add_next_doc_id_sleep';
set debug='+d,fts_instrument_sync_request';
select @@debug;
@@debug
d,fts_sync_add_next_doc_id_sleep,fts_instrument_sync_request
insert into fts_t1 values('abcd');
insert into fts_t1 values('abcd');
# Kill and restart
select count(*) from fts_t1 where c1 like '%abcd%';
count(*)
5
select count(*) from fts_t1 where match(c1) against('abcd');
count(*)
4
drop tables fts_t1;

------------ MYSQLTEST OUTPUT END -----------

as we can see, i have inserted 5 records, while 4 are finded by fulltext serach.

Hi,

We repeat that our original comment still stands. You have not provided any evidence that your setup is 100 % ACID compliant.

Next, code has changed a lot between your release and 8.0.33.

Last, but not least, we do not see why we should include sleeping of the said thread in order to expose a bug. You can add sleep() in many places in our code and have a bug as a net result.

Can't repeat.

I'm sorry for my not clear description because of my poor english, for the first comment, could you tell me what detail acid setups i shoud set.

And for the second comment, in 8.0.33 is also have this problem,  you can add the debug-sync at the corresponding place.

And for the last comment,  this sleep just a debug sync to make sure the bug occurs because of this bug is occurs probabilistically . And This bug is because of race condition of cache->next_doc_id. When we insert a row while the background sync is executing, if the insert thread have get the cache->next_doc_id while have not been commited, and the sync thread is try to update the cache->sync_doc_id, it will find cache->next_doc_id equal cache->sync_doc_id,  while in the normal scene, the cache->next_doc_id will equal to cache->sync_doc_id + 1.

In fact, if a user thread insert a record while the background sync thread is flush the fulltext cache to disk, this proble will occur

Hi,

Making MySQL installation ACID compliant is described in detail in our Manual, in the chapters on InnoDB.

Hence, all you need is to read properly our Manual, which is available on http://dev.mysql.com.

Next, we do have debug_sync commands in many of  our our MTR cases, but we do not use delays that freely, as it changed the behaviour of the server. In order to verify the  bug, it must be observed without any changes in the code.

Last, 8.0.33 is significantly changed relative to 8.0.30, so it is not as simple as you state. Still, introducing sleep in the thread is not acceptable for the test cases.

Can't repeat.

Hi, theoretically, this problem occurs certainly,
and 'delet from t1' for step1 and 'kill -9' for step2 are the key point. I have
provided a mysql-test case as following, you can have a try:

cat t/mytest1.test:
drop table if exists t1;
create table t1(name text(10), fulltext index idx(name))engine=innodb;
insert into t1 values('aaaaa');
insert into t1 values('bbbbb'); 
delete from t1;

--source include/kill_and_restart_mysqld.inc

insert into t1 values('ccccc');
insert into t1 values('ddddd');
select * from t1 where name like '%ccccc%';
select * from t1 where match(name) against('ccccc');
select * from t1 where name like '%ddddd%';

The output can be seen as follows:

drop table if exists t1;
Warnings:
Note	1051	Unknown table 'test.t1'
create table t1(name text(10), fulltext index idx(name))engine=innodb;
insert into t1 values('aaaaa');
insert into t1 values('bbbbb');
delete from t1;
# Kill and restart
insert into t1 values('ccccc');
insert into t1 values('ddddd');
select * from t1 where name like '%ccccc%';
name
ccccc
select * from t1 where match(name) against('ccccc');
name
select * from t1 where name like '%ddddd%';
name
ddddd
select * from t1 where match(name) against('ddddd');
name

Sorry, not this problem, please ignore

Hi,

We have to repeat what we wrote in our previous comment.

The key event in the test case is a kill command. When you are 100 % ACID compliant (like in our installation), then no problem can occur when you kill -9 a daemon. 

Can't repeat.