Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-28110

FLUSH TABLE ... WITH READ LOCK output excessively verbose

    XMLWordPrintable

Details

    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

        1. in.sql
          412 kB
          Roel Van de Paar

        Issue Links

          Activity

            People

              marko Marko Mäkelä
              Roel Roel Van de Paar
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

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