Details
-
Bug
-
Status: Open (View Workflow)
-
Minor
-
Resolution: Unresolved
-
13.1
Description
--source include/have_innodb.inc
|
# Interrupting a statement on an InnoDB FULLTEXT table must not write [ERROR] to the error log. |
# Every interrupt below is reported to the client and leaves correct data, so there is nothing to log. |
SET SESSION max_recursive_iterations=100000; |
CREATE TABLE t1 (c1 INT PRIMARY KEY, c2 TEXT, FULLTEXT(c2)) ENGINE=InnoDB; |
SET SESSION max_statement_time=0.0001; |
--error 0,ER_STATEMENT_TIMEOUT
|
INSERT INTO t1 VALUES (1,'aaa b c'); |
SET SESSION max_statement_time=0.0005; |
--error 0,ER_STATEMENT_TIMEOUT
|
INSERT INTO t1 VALUES (2,'aaa b c'); |
SET SESSION max_statement_time=0.001; |
--error 0,ER_STATEMENT_TIMEOUT
|
INSERT INTO t1 VALUES (3,'aaa b c'); |
SET SESSION max_statement_time=0.002; |
--error 0,ER_STATEMENT_TIMEOUT
|
INSERT INTO t1 VALUES (4,'aaa b c'); |
SET SESSION max_statement_time=0; |
INSERT INTO t1 WITH RECURSIVE s AS (SELECT 5 n UNION ALL SELECT n+1 FROM s WHERE n<5000) SELECT n,CONCAT('aaa w',n) FROM s; |
SET GLOBAL innodb_optimize_fulltext_only=ON; |
OPTIMIZE TABLE t1; |
SET SESSION max_statement_time=0.001; |
--disable_result_log
|
--error 0,188,ER_STATEMENT_TIMEOUT
|
SELECT COUNT(*) FROM t1 WHERE MATCH(c2) AGAINST('aaa'); |
--enable_result_log
|
SET SESSION max_statement_time=0; |
SET GLOBAL innodb_optimize_fulltext_only=OFF; |
DROP TABLE t1; |
--let SEARCH_FILE = $MYSQLTEST_VARDIR/log/mysqld.1.err
|
--let SEARCH_PATTERN = \[ERROR\] InnoDB: \(Operation interrupted\)
|
--let SEARCH_ABORT = FOUND
|
--source include/search_pattern_in_file.inc
|
Leads to:
|
CS 13.1.0 0ee34e07bdc10abf32a535d7234c6f5e0bb9ed55 (Debug, Clang 22.1.8-20260622) Build 14/08/2026 |
2026-08-18 14:53:45 4 [ERROR] InnoDB: (Operation interrupted) while getting next doc id for table `test`.`t1`
|
2026-08-18 14:53:56 4 [ERROR] InnoDB: (Operation interrupted) while reading FTS index.
|
Nothing is wrong at the point these lines are written. The interrupt came from the user, the client was told about it, and the data is correct. The same statements run through the client, with the counts left visible:
ERROR 1969 (70100): Query was interrupted: execution time limit 0.0001 sec exceeded
|
ERROR 1969 (70100): Query was interrupted: execution time limit 0.0005 sec exceeded
|
ERROR 188 (HY000): Operation was interrupted by end user (probably kill command?)
|
COUNT(*)
|
4998
|
COUNT(*)
|
4998
|
The two interrupted inserts rolled back, the two that were not interrupted are present, and the interrupted SELECT left the index intact: 4998 rows in the table and 4998 rows matching MATCH(c2) AGAINST('aaa'). So the server writes [ERROR] for a condition it has already handled correctly and already reported.
The five sites seen so far:
fts_cmp_set_sync_doc_id() fts0fts.cc:2481 "while getting next doc id for table X"
|
fts_index_fetch_nodes() fts0opt.cc:332 "while reading FTS index."
|
fts_index_fetch_words() fts0opt.cc:620 "while reading words."
|
fts_sync_commit() fts0fts.cc:3522 "during SYNC of table X"
|
fts_query_match_document() fts0que.cc:2200 "matching document."
|
The third one needs an interrupted OPTIMIZE TABLE with innodb_optimize_fulltext_only=ON. It behaves the same way: the same run gives the same client errors on both builds, with 6 log lines after the commit and none before.
The fourth one is the sharper case, because the client is told nothing at all. An OPTIMIZE TABLE ladder on a 20000 row table, with innodb_optimize_fulltext_only=ON, innodb_ft_num_word_optimize=20000 and max_statement_time raised in steps, reports status OK for every statement and returns no client error, while the log takes one during SYNC of table line and one while getting next doc id line. FTS OPTIMIZE is incremental by design, so OK after partial work may well be intended, but it leaves an [ERROR] in the log with nothing on the client side to match it against. The same run on a build from before the commit gives the same client output and no such lines in the log.
The fifth site needs an optimised build. On a debug build the same phrase searches are cut off earlier and reach fts0opt.cc:332 instead. That is where the interrupt lands, not a second defect. On an optimised build with the commit, every interrupted phrase search writes one matching document. line and returns ERROR 188 to the client. On an optimised build from before the commit the same searches return ERROR 188 and write nothing.
Four of the five log statements are older than the change that makes them fire. The one at fts0opt.cc:620 is new in the same commit, and fts_index_fetch_words() logged nothing on an error before it. None of the five filters out DB_INTERRUPTED. fts0opt.cc:324 already shows the pattern that is missing: a lock wait timeout is logged as a warning and retried, so the code does distinguish an expected condition from a real failure. A user interrupt is simply not in that set.
MDEV-28730, commit 81c3836bb2ba0823fe69fd6953c21fccf6476b92, moved this InnoDB FTS work off the internal parser and onto FTSQueryExecutor, which reads through row_search_mvcc(). That function checks trx_is_interrupted() at row0sel.cc:5022 and returns DB_INTERRUPTED. The old que layer held no interrupt check, so the error code never appeared and the log statements were never reached.
The same testcase against a CS 13.1.0 build from before that commit passes, and against a build that has it, fails on FOUND 2. Everything else is the same on both. Only the error log differs:
before the commit after the commit
|
client errors 1969, 1969, 188 1969, 1969, 188
|
rows in the table 4998 4998
|
rows matching aaa 4998 4998
|
a new row is found yes yes
|
synced_doc_id 4999 4999
|
use_stopword 1 1
|
CHECK TABLE OK OK
|
error log lines 0 2
|
trx_is_interrupted() in ha_innodb.cc:3621 is true for any statement whose kill level is set, so KILL QUERY and a lost client connection reach the same path. max_statement_time is only the easiest way to show it.
Three more InnoDB FTS sites print an error code the same way and have the same gap. These have not been seen to fire yet, but they sit on the same refactored paths:
fts0opt.cc:1071 "during optimize, when ..."
|
fts0opt.cc:1091 "during optimize, when ..."
|
fts0opt.cc:1379 "while updating last optimized word!"
|
Two of the three, fts0opt.cc:1071 and fts0opt.cc:1091, are in the OPTIMIZE word write-back loop, and on a build that does not yet carry the MDEV-40621 fix that loop asserts before the write is reached.
The impact is that a routine, user-caused, fully-handled interrupt now raises [ERROR] in the server error log. Monitoring reads that as a server fault, and a busy server with max_statement_time set produces one line per interrupted full-text statement.
|
Bug Detection Matrix |
Rel o/d Build Commit UniqueID observed
|
CS 10.6 dbg 220726 5520c9aac5b6a5a9ea60d78582ddffa5349e2d0f No bug found
|
CS 10.6 opt 220726 5520c9aac5b6a5a9ea60d78582ddffa5349e2d0f No bug found
|
CS 10.11 dbg 220726 6268f6023fe3e8dc8ec81869dea711e14cbb28c3 No bug found
|
CS 10.11 opt 220726 6268f6023fe3e8dc8ec81869dea711e14cbb28c3 No bug found
|
CS 11.4 dbg 220726 2cbce592c39dd39902c8f03db2b35069832fd10b No bug found
|
CS 11.4 opt 220726 2cbce592c39dd39902c8f03db2b35069832fd10b No bug found
|
CS 11.8 dbg 220726 1d23deff797ab448f091e39756434903d81a98c2 No bug found
|
CS 11.8 opt 220726 1d23deff797ab448f091e39756434903d81a98c2 No bug found
|
CS 12.3 dbg 220726 9b075b2cb53338f67e7230cc585e02d2d34514ed No bug found
|
CS 12.3 opt 220726 9b075b2cb53338f67e7230cc585e02d2d34514ed No bug found
|
CS 13.0 dbg 220726 84c246ca5387c0611f75097136ff4f4bea092aa3 No bug found
|
CS 13.0 opt 220726 84c246ca5387c0611f75097136ff4f4bea092aa3 No bug found
|
CS 13.1 dbg 140826 0ee34e07bdc10abf32a535d7234c6f5e0bb9ed55 INNODB_ERROR|(Operation interrupted) while getting next doc id for table X
|
CS 13.1 opt 140826 0ee34e07bdc10abf32a535d7234c6f5e0bb9ed55 INNODB_ERROR|(Operation interrupted) while getting next doc id for table X
|
ES 10.6 dbg 220726 fcecb2620f25965723d640decede7c018bcb1dcc No bug found
|
ES 10.6 opt 220726 fcecb2620f25965723d640decede7c018bcb1dcc No bug found
|
ES 11.4 dbg 220726 3b34189bfe675c18c4ced3ef531d016ea74c76f4 No bug found
|
ES 11.4 opt 220726 3b34189bfe675c18c4ced3ef531d016ea74c76f4 No bug found
|
ES 11.8 dbg 220726 4694e931d10fecf733c34f83ea2146d31b708eb3 No bug found
|
ES 11.8 opt 220726 4694e931d10fecf733c34f83ea2146d31b708eb3 No bug found
|
ES 12.3 dbg 220726 9d8abb61e913bec023cd8caeccad4b42717151cb No bug found
|
ES 12.3 opt 220726 9d8abb61e913bec023cd8caeccad4b42717151cb No bug found
|
Attachments
Issue Links
- is caused by
-
MDEV-28730 Remove internal parser usage from InnoDB fts
-
- Closed
-
- relates to
-
-
- Open
-
