Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Incomplete
-
10.5.12, 10.5.15
-
None
-
Debian 11.1, Debian 11.3
Description
I got about 1 GB of these messages in the logfile:
2021-10-27 14:41:28 17998619 [ERROR] InnoDB: Clustered record for sec rec not found index `fs_mtime` of table `nextcloud`.`oc_filecache`
|
InnoDB: sec index record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
|
0: len 8; hex 80000000609b9914; asc ` ;;
|
1: len 8; hex 800000000269a5e6; asc i ;;
|
|
|
InnoDB: clust index record PHYSICAL RECORD: n_fields 18; compact format; info bits 0
|
0: len 8; hex 800000000269a5e4; asc i ;;
|
1: len 6; hex 000000000000; asc ;;
|
2: len 7; hex 80000000000000; asc ;;
|
3: len 8; hex 8000000000000002; asc ;;
|
4: len 30; hex 617070646174615f6f6378316f37396f786e69702f707265766965772f63; asc appdata_ocx1o79oxnip/preview/c; (total 51 bytes);
|
5: len 30; hex 363233306533373536316561343864656463373035363934393837646538; asc 6230e37561ea48dedc705694987de8; (total 32 bytes);
|
6: len 8; hex 800000000269a5e3; asc i ;;
|
7: len 8; hex 3430343539393336; asc 40459936;;
|
8: len 8; hex 8000000000000002; asc ;;
|
9: len 8; hex 8000000000000001; asc ;;
|
10: len 8; hex 8000000000000000; asc ;;
|
11: len 8; hex 8000000060ae224d; asc ` "M;;
|
12: len 8; hex 8000000060ae224d; asc ` "M;;
|
13: len 4; hex 80000000; asc ;;
|
14: len 8; hex 8000000000000000; asc ;;
|
15: len 13; hex 36303962393839653739333532; asc 609b989e79352;;
|
16: len 4; hex 8000001f; asc ;;
|
17: len 0; hex ; asc ;;
|
|
|
TRANSACTION 421825623286288, ACTIVE 38 sec fetching rows
|
mysql tables in use 1, locked 0
|
0 lock struct(s), heap size 1128, 0 row lock(s)
|
MySQL thread id 17998619, OS thread handle 140350620571392, query id 731677120 172.21.243.109 nextcloud Sending data
|
SELECT `f`.* FROM `oc_filecache` `f` WHERE (((`f`.`storage` = '1594') AND (`f`.`path` LIKE 'files/...%')) OR ((`f`.`storage` = '2947') AND (`f`.`path` LIKE 'files/...%')) OR ((`f`.`storage` = '2947') AND (`f`.`path` LIKE 'files/...%')) OR...
|
|
|
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
|
(I shortend the filenames in the query for data protection reasons)
The error message contains always the same table and index name, the sql differs in the searched data, but is always the same structure.
CHECK TABLE oc_filecache gives only a "Ok".
OPTIMIZE TABLE worked, but there the errors are still there.
Dropping and re-creating the fs_mtime index worked, but the error messages are still there.
I also tried to export the whole table with mysqldump, dropping the table and re-importing the dump, but after this operation the errors are back again.
Server config:
[mysqld]
|
user = mysql
|
pid-file = /var/run/mysqld/mysqld.pid
|
socket = /var/run/mysqld/mysqld.sock
|
port = 3306
|
basedir = /usr
|
datadir = /data/mysql
|
tmpdir = /data/mysqltmp
|
lc-messages-dir = /usr/share/mysql
|
skip-external-locking
|
key_buffer_size = 16M
|
max_allowed_packet = 16M
|
thread_stack = 192K
|
thread_cache_size = 8
|
myisam_recover_options = BACKUP
|
query_cache_size = 0
|
query_cache_type = OFF
|
log_error = /data/log/mysql/error.log
|
slow_query_log_file = /data/log/mysql/slow.log
|
long_query_time = 10
|
log_slow_rate_limit = 1000
|
log_slow_verbosity = query_plan
|
server-id = 1
|
disable-log-bin
|
innodb_file_per_table=true
|
ssl-ca=/etc/mysql/nc1-db-ca-cert.pem
|
ssl-cert=/etc/mysql/nc1-db-server-cert.pem
|
ssl-key=/etc/mysql/nc1-db-server-key.pem
|
ssl=on
|
character-set-server = utf8mb4
|
collation-server = utf8mb4_general_ci
|
skip-name-resolve = 1
|
join_buffer_size = 1M
|
transaction-isolation = READ-COMMITTED
|
max_connections = 128 # (> 151)
|
wait_timeout = 3600 # (< 28800)
|
interactive_timeout = 3600 # (< 28800)
|
join_buffer_size = 2M #(> 1.0M, or always use indexes with joins)
|
table_open_cache = 4096 # (> 2000)
|
innodb_buffer_pool_size = 724M # (>= 724M) if possible.
|
tmp_table_size = 32M
|
max_heap_table_size = 32M
|
innodb_flush_method=O_DIRECT
|
max_statement_time = 90
|
performance_schema = OFF
|
thread_handling=pool-of-threads
|
innodb_log_file_size=192M
|
thread_pool_max_threads=128
|
Create table:
CREATE TABLE `oc_filecache` (
|
`fileid` bigint(20) NOT NULL AUTO_INCREMENT,
|
`storage` bigint(20) NOT NULL DEFAULT 0,
|
`path` varchar(4000) COLLATE utf8mb4_bin DEFAULT NULL,
|
`path_hash` varchar(32) COLLATE utf8mb4_bin NOT NULL DEFAULT '',
|
`parent` bigint(20) NOT NULL DEFAULT 0,
|
`name` varchar(250) COLLATE utf8mb4_bin DEFAULT NULL,
|
`mimetype` bigint(20) NOT NULL DEFAULT 0,
|
`mimepart` bigint(20) NOT NULL DEFAULT 0,
|
`size` bigint(20) NOT NULL DEFAULT 0,
|
`mtime` bigint(20) NOT NULL DEFAULT 0,
|
`storage_mtime` bigint(20) NOT NULL DEFAULT 0,
|
`encrypted` int(11) NOT NULL DEFAULT 0,
|
`unencrypted_size` bigint(20) NOT NULL DEFAULT 0,
|
`etag` varchar(40) COLLATE utf8mb4_bin DEFAULT NULL,
|
`permissions` int(11) DEFAULT 0,
|
`checksum` varchar(255) COLLATE utf8mb4_bin DEFAULT NULL,
|
PRIMARY KEY (`fileid`),
|
UNIQUE KEY `fs_storage_path_hash` (`storage`,`path_hash`),
|
KEY `fs_parent_name_hash` (`parent`,`name`),
|
KEY `fs_storage_mimetype` (`storage`,`mimetype`),
|
KEY `fs_storage_mimepart` (`storage`,`mimepart`),
|
KEY `fs_storage_size` (`storage`,`size`,`fileid`),
|
KEY `fs_size` (`size`),
|
KEY `fs_mtime` (`mtime`)
|
) ENGINE=InnoDB AUTO_INCREMENT=46263064 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin ROW_FORMAT=COMPRESSED
|
Attachments
Issue Links
- duplicates
-
-
- Closed
-
- is blocked by
-
-
- Closed
-
- is duplicated by
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
MDEV-27734 Set innodb_change_buffering=none by default
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
(6 relates to)
Activity
mleich provided an even more juicy rr replay trace than the one that I previously analyzed, with a slightly different scenario:
mysqld: /data/Server/bb-10.6-MDEV-30009A/storage/innobase/ibuf/ibuf0ibuf.cc:3615: dberr_t ibuf_insert_to_index_page_low(const dtuple_t*, rec_offs**, mem_heap_t*, mtr_t*, page_cur_t*): Assertion `!__builtin_expect(((page_cur->block)->page.zip.data) != 0, 0)' failed.
|
#4 0x000055d5889b3120 in ibuf_insert_to_index_page_low (entry=entry@entry=0x61600482bfc0, offsets=offsets@entry=0x7f12df525c40, heap=0x613000427400, mtr=mtr@entry=0x7f12df526250, page_cur=page_cur@entry=0x7f12df525ce0)
|
at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/ibuf/ibuf0ibuf.cc:3615
|
#5 0x000055d5889b7a9f in ibuf_insert_to_index_page (entry=entry@entry=0x61600482bfc0, block=block@entry=0x7f12f9d58650, index=0x616004823808, mtr=mtr@entry=0x7f12df526250) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/ibuf/ibuf0ibuf.cc:3779
|
#6 0x000055d5889c95f4 in ibuf_merge_or_delete_for_page (block=block@entry=0x7f12f9d58650, page_id=..., zip_size=zip_size@entry=4096) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/ibuf/ibuf0ibuf.cc:4312
|
#7 0x000055d588f3ca3e in buf_page_get_low (page_id=<error reading variable: Cannot access memory at address 0xfa0>, zip_size=zip_size@entry=4096, rw_latch=rw_latch@entry=2, guess=<optimized out>, guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7f12df5282b0,
|
err=<optimized out>, allow_ibuf_merge=<optimized out>) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/include/buf0buf.h:1014
|
#8 0x000055d588f3e20f in buf_page_get_gen (page_id=..., zip_size=zip_size@entry=4096, rw_latch=rw_latch@entry=2, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7f12df5282b0, err=0x7f12df5269f0, allow_ibuf_merge=true)
|
at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/buf/buf0buf.cc:2962
|
#9 0x000055d588eda70d in btr_cur_search_to_nth_level (level=level@entry=0, tuple=tuple@entry=0x619000b37008, mode=mode@entry=PAGE_CUR_LE, latch_mode=latch_mode@entry=BTR_MODIFY_LEAF, cursor=cursor@entry=0x7f12df527e10, mtr=mtr@entry=0x7f12df5282b0,
|
autoinc=<optimized out>) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/btr/btr0cur.cc:1565
|
#10 0x000055d588ee0634 in btr_cur_t::search_leaf (this=this@entry=0x7f12df527e10, tuple=tuple@entry=0x619000b37008, mode=mode@entry=PAGE_CUR_LE, latch_mode=latch_mode@entry=BTR_MODIFY_LEAF, mtr=mtr@entry=0x7f12df5282b0, autoinc=autoinc@entry=0)
|
at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/btr/btr0cur.cc:1206
|
#11 0x000055d588cb78f3 in btr_pcur_open (mtr=0x7f12df5282b0, autoinc=0, cursor=0x7f12df527e10, latch_mode=BTR_MODIFY_LEAF, mode=PAGE_CUR_LE, tuple=0x619000b37008) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/include/btr0pcur.inl:325
|
#12 row_search_index_entry (entry=entry@entry=0x619000b37008, mode=mode@entry=BTR_MODIFY_LEAF, pcur=pcur@entry=0x7f12df527e10, mtr=mtr@entry=0x7f12df5282b0) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/row/row0row.cc:1286
|
#13 0x000055d5891f11fd in row_undo_mod_del_unmark_sec_and_undo_update (mode=mode@entry=BTR_MODIFY_LEAF, thr=thr@entry=0x6160048415c0, index=index@entry=0x61600767d708, entry=entry@entry=0x619000b37008)
|
at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/row/row0umod.cc:689
|
This fails in a rollback. This time, the dummy_index that was reconstructed from the change buffer record contains the same number of fields as the real index that row_undo_mod_del_unmark_sec_and_undo_update() is using (and which matches the PAGE_INDEX_ID in the secondary index leaf page). The code before the assertion expression includes a comment:
if (page_cur_tuple_insert(page_cur, entry, offsets, &heap, 0, mtr)) |
return DB_SUCCESS; |
|
|
/* Page reorganization or recompression should already have been |
attempted by page_cur_tuple_insert(). Besides, per
|
ibuf_index_page_calc_free_zip() the page should not have been
|
recompressed or reorganized. */
|
ut_ad(!is_buf_block_get_page_zip(page_cur->block));
|
So, we end up having some extra records in the page. Because this is an rr replay trace, it is possible to set a data watchpoint on the change buffer bitmap bits and {{reverse-continue} to find out when the buffered changes should have been deleted:
…
|
(rr) reverse-finish
|
Run back to call of #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
0x00007f130dafc854 in __GI_abort () at abort.c:79
|
79 abort.c: No such file or directory.
|
…
|
(rr) reverse-finish
|
Run back to call of #0 0x000055d5889c95ef in ibuf_merge_or_delete_for_page (block=block@entry=0x7f12f9d58650, page_id={m_id = 47244640274}, zip_size=zip_size@entry=4096) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/ibuf/ibuf0ibuf.cc:4312
|
0x000055d588f3ca39 in buf_page_get_low (page_id=<error reading variable: Cannot access memory at address 0xfa0>, zip_size=zip_size@entry=4096, rw_latch=rw_latch@entry=2, guess=<optimized out>, guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7f12df5282b0,
|
err=<optimized out>, allow_ibuf_merge=<optimized out>) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/include/buf0buf.h:1014
|
1014 ulint zip_size() const { return page.zip_size(); }
|
(rr) step
|
ibuf_merge_or_delete_for_page (block=block@entry=0x7f12f9d58650, page_id=<error reading variable: Cannot access memory at address 0x3ffffb01>, zip_size=zip_size@entry=4096) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/ibuf/ibuf0ibuf.cc:4132
|
4132 {
|
(rr) next
|
…
|
4173 bitmap_bits = ibuf_bitmap_page_get_bits(
|
(rr) step
|
ibuf_bitmap_page_get_bits_low (page=page@entry=0x7f12fa2ee000 "", page_id=<optimized out>, zip_size=zip_size@entry=4096, latch_type=latch_type@entry=2, mtr=mtr@entry=0x7f12df526250, bit=bit@entry=2)
|
at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/ibuf/ibuf0ibuf.cc:542
|
542 {
|
(rr) next
|
…
|
562 map_byte = mach_read_from_1(page + IBUF_BITMAP + byte_offset);
|
(rr) step
|
mach_read_from_1 (b=0x7f12fa2ee067 "\004\060") at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/include/mach0data.inl:73
|
73 return(uint8_t(*b));
|
(rr) watch -l *b
|
Hardware watchpoint 4: -location *b
|
(rr) reverse-continue
|
…
|
Continuing.
|
|
|
Thread 3 hit Hardware watchpoint 4: -location *b
|
|
|
Old value = 48 '0'
|
New value = 51 '3'
|
…
|
(rr) set print frame-arguments none
|
(rr) backtrace
|
#0 0x000055d5889d728c in mtr_t::write<1u, (mtr_t::write_type)1, unsigned char> (this=..., block=..., ptr=..., val=...) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/include/mtr0log.h:202
|
#1 0x000055d5889c32d6 in ibuf_bitmap_page_set_bits<0> (block=..., page_id=..., physical_size=..., val=..., mtr=...) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/include/buf0types.h:135
|
#2 0x000055d5889c9e3c in ibuf_set_bitmap_for_bulk_load (block=..., mtr=..., reset=...) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/include/buf0buf.h:665
|
#3 0x000055d588e8529b in PageBulk::commit (this=..., success=...) at /data/Server/bb-10.6-MDEV-30009A/storage/innobase/btr/btr0bulk.cc:567
|
CREATE INDEX is resetting the change buffer bitmap bits for the newly initialized page, but it fails to delete the previously buffered records. Thus, the "garbage" records that were destined to a since-then freed page (I think after DROP INDEX but I did not check it) may be inserted later.
The failure scenario that I mentioned today was fixed in MDEV-30009.
Following test case can fail to remove the change buffer entries from ibuf index. It leads to hang in slow shutdown
--source include/have_innodb.inc
|
--source include/have_debug.inc
|
--source include/have_sequence.inc
|
|
|
CREATE TABLE t1(
|
a INT AUTO_INCREMENT PRIMARY KEY,
|
b CHAR(1),
|
c INT,
|
INDEX idx(b))
|
ENGINE=InnoDB STATS_PERSISTENT=0;
|
|
|
# The flag innodb_change_buffering_debug is only available in debug builds.
|
# It instructs InnoDB to try to evict pages from the buffer pool when
|
# change buffering is possible, so that the change buffer will be used
|
# whenever possible.
|
SET GLOBAL innodb_change_buffering_debug = 1;
|
SET GLOBAL innodb_change_buffering=all;
|
|
|
# Create enough rows for the table, so that the change buffer will be
|
# used for modifying the secondary index page. There must be multiple
|
# index pages, because changes to the root page are never buffered.
|
INSERT INTO t1 SELECT 0,'x',1 FROM seq_1_to_4096;
|
let MYSQLD_DATADIR=`select @@datadir`;
|
let PAGE_SIZE=`select @@innodb_page_size`;
|
|
|
ALTER TABLE t1 DROP INDEX idx;
|
|
|
set global innodb_fast_shutdown=0;
|
--source include/restart_mysqld.inc
|
|
|
# Cleanup
|
DROP TABLE t1;
|
InnoDB reset the bitmap bit while applying the change buffer merge for the freed page and it fails to
remove the record from ibuf index
if (bitmap_bits
|
&& DB_SUCCESS
|
== fseg_page_is_allocated(space, page_id.page_no())) {
|
ibuf_mtr_start(&mtr);
|
mtr.set_named_space(space);
|
ibuf_reset_bitmap(block, page_id, zip_size, &mtr);
|
ibuf_mtr_commit(&mtr);
|
bitmap_bits = 0;
|
}
|
|
|
if (!bitmap_bits) {
|
/* No changes are buffered for this page. */
|
space->release();
|
return DB_SUCCESS;
|
}
|
During slow shutdown, InnoDB iterates through change buffer index again and again. It leads to hang
In 10.3 the following test case can do the same. But in 10.3, change buffer merge is happening in freed page (ie wrong though during slow shutdown)
|
|
set global innodb_disable_background_merge=1;
|
CREATE TABLE t1(
|
a INT AUTO_INCREMENT PRIMARY KEY,
|
b CHAR(1),
|
c INT,
|
INDEX idx(b))
|
ENGINE=InnoDB STATS_PERSISTENT=0;
|
|
|
connect(con1,localhost,root,,,);
|
start transaction with consistent snapshot;
|
|
|
# The flag innodb_change_buffering_debug is only available in debug builds.
|
# It instructs InnoDB to try to evict pages from the buffer pool when
|
# change buffering is possible, so that the change buffer will be used
|
# whenever possible.
|
SET GLOBAL innodb_change_buffering=all;
|
|
|
# Create enough rows for the table, so that the change buffer will be
|
# used for modifying the secondary index page. There must be multiple
|
# index pages, because changes to the root page are never buffered.
|
INSERT INTO t1 SELECT 0,'x',1 FROM seq_1_to_4096;
|
let MYSQLD_DATADIR=`select @@datadir`;
|
let PAGE_SIZE=`select @@innodb_page_size`;
|
|
|
ALTER TABLE t1 DROP INDEX idx;
|
|
|
INSERT INTO t1 SELECT 0,'y',2 FROM seq_1_to_8192;
|
connection con1;
|
commit;
|
set global innodb_disable_background_merge=0;
|
set global innodb_fast_shutdown=0;
|
--source include/restart_mysqld.inc
|
|
|
# Cleanup
|
DROP TABLE t1;
|
During slow shutdown, InnoDB does apply the change buffer values to the freed page.
Until MDEV-30134 has been fixed, it is unsafe to use innodb_change_buffering=purges or innodb_change_buffering=all.
We are still looking for the following feedback:
MDEV-27734disabled it by default).MDEV-30009is fixed.Due to the difficulty of reproducing this corruption, I think that we will have to keep waiting several months after the fix of
MDEV-30009is available.