[MDEV-28110] FLUSH TABLE ... WITH READ LOCK output excessively verbose - Jira

XML

Word

Printable

Details

Type: Bug
Status: Open (View Workflow)
Priority: Major
Resolution: Unresolved
Affects Version/s: 10.5, 10.6, 10.2(EOL), 10.3(EOL), 10.4(EOL), 10.7(EOL), 10.8(EOL), 10.9(EOL)
Fix Version/s: 10.5, 10.6
Component/s: Storage Engine - InnoDB
Labels:

Description

The attached SQL file in.sql has two lines of SQL which do:

CREATE TABLE t (c INT) ENGINE=InnoDB PARTITION BY LIST (c) (PARTITION p0 VALUES IN (0,1,2,3), PARTITION p1 VALUES IN (4,5,6,7), PARTITION p2 VALUES IN (8,9,10,11), PARTITION p3 VALUES IN (12,13,14,15),.........., PARTITION p8191 VALUES IN (32764,32765,32766,32767));

FLUSH TABLE t WITH READ LOCK;

Even though only a single table is being flushed/read locked (with 8191 partitions), there are over 32000 lines in the error log (information only) being written:

10.9.0 5be92887c2caacb45af87b1131db952ce627e83a (Optimized)
2022-03-17 15:59:35 0 [Note] /test/MD160322-mariadb-10.9.0-linux-x86_64-opt/bin/mysqld: ready for connections.
Version: '10.9.0-MariaDB' socket: '/test/MD160322-mariadb-10.9.0-linux-x86_64-opt/socket.sock' port: 10640 MariaDB Server
2022-03-17 16:00:06 4 [Note] InnoDB: Cannot close file ./mysql/innodb_index_stats.ibd because of pending fsync
2022-03-17 16:00:13 4 [Note] InnoDB: Cannot close file ./mysql/innodb_index_stats.ibd because of 1 pending operations and pending fsync
2022-03-17 16:00:20 4 [Note] InnoDB: Cannot close file ./mysql/innodb_index_stats.ibd because of pending fsync
2022-03-17 16:00:26 4 [Note] InnoDB: Cannot close file ./mysql/innodb_index_stats.ibd because of pending fsync
2022-03-17 16:00:31 4 [Note] InnoDB: Cannot close file ./mysql/innodb_index_stats.ibd because of pending fsync
2022-03-17 16:00:37 4 [Note] InnoDB: Cannot close file ./mysql/innodb_index_stats.ibd because of pending fsync
2022-03-17 16:00:45 4 [Note] InnoDB: Sync to disk of `test`.`t` /* Partition `p0` */ started.
2022-03-17 16:00:45 4 [Note] InnoDB: Stopping purge
2022-03-17 16:00:45 4 [Note] InnoDB: Writing table metadata to './test/t#P#p0.cfg'
2022-03-17 16:00:45 4 [Note] InnoDB: Table `test`.`t` /* Partition `p0` */ flushed to disk
2022-03-17 16:00:45 4 [Note] InnoDB: Sync to disk of `test`.`t` /* Partition `p1` */ started.
2022-03-17 16:00:45 4 [Note] InnoDB: Writing table metadata to './test/t#P#p1.cfg'
2022-03-17 16:00:45 4 [Note] InnoDB: Table `test`.`t` /* Partition `p1` */ flushed to disk
2022-03-17 16:00:45 4 [Note] InnoDB: Sync to disk of `test`.`t` /* Partition `p2` */ started.
2022-03-17 16:00:45 4 [Note] InnoDB: Writing table metadata to './test/t#P#p2.cfg'
2022-03-17 16:00:45 4 [Note] InnoDB: Table `test`.`t` /* Partition `p2` */ flushed to disk
...
2022-03-17 16:00:54 4 [Note] InnoDB: Table `test`.`t` /* Partition `p8191` */ flushed to disk
2022-03-17 16:01:40 4 [Note] InnoDB: Deleting the meta-data file './test/t#P#p0.cfg'
2022-03-17 16:01:40 4 [Note] InnoDB: Deleting the meta-data file './test/t#P#p1.cfg'
2022-03-17 16:01:40 4 [Note] InnoDB: Deleting the meta-data file './test/t#P#p2.cfg'
2022-03-17 16:01:40 4 [Note] InnoDB: Deleting the meta-data file './test/t#P#p3.cfg'
...
2022-03-17 16:01:41 4 [Note] InnoDB: Deleting the meta-data file './test/t#P#p8190.cfg'
2022-03-17 16:01:41 4 [Note] InnoDB: Deleting the meta-data file './test/t#P#p8191.cfg'
2022-03-17 16:01:41 4 [Note] InnoDB: Resuming purge

This also happens on optimized builds. The error log was 2.9M as a result of just these two commands + startup/shutdown.

MySQL 5.6 and 5.7 also show this behavior but not 8.0.

Also of interest is the "because of pending fsync" messages which only appeared in 10.5, 10.6, 10.7, 10.8 and 10.9, in both optimized and debug builds and apparently consistently too. Added 'regression-10.5' tag for this component.

Also interesting is that MySQL 5.7 runs into a long semaphore wait with this testcase, whereas none of the others (MariaDB or MySQL) do;

MySQL 5.7.37 build 26 feb 2022 (Optimized)
2022-03-17T06:01:50.311192Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 22623402583808 has waited at srv0srv.cc line 1989 for 241 seconds the semaphore:
X-lock on RW-latch at 0x559cbf06d528 created in file dict0dict.cc line 1227
a writer (thread id 22623606298368) 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 /test/5.7_dbg/storage/innobase/handler/ha_innopart.cc line 2811
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
2022-03-17 17:02:00 0x14936bfff700 INNODB MONITOR OUTPUT
=====================================
...

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

in.sql
412 kB
2022-03-17 05:41

Issue Links

relates to

MDEV-25215 Excessive logging "Cannot close file ./test/FTS_xxx.ibd because of n pending operations and pending fsync

Closed

Activity

People

Assignee:: Marko Mäkelä

Reporter:: Roel Van de Paar

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Dates

Created:: 2022-03-17 05:38

Updated:: 2024-09-10 14:58

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.