linux-block.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: Daniel Black <daniel@mariadb.org>
To: Pavel Begunkov <asml.silence@gmail.com>
Cc: linux-block@vger.kernel.org, io-uring@vger.kernel.org
Subject: Re: uring regression - lost write request
Date: Mon, 25 Oct 2021 22:09:28 +1100	[thread overview]
Message-ID: <CABVffEOMVbQ+MynbcNfD7KEA5Mwqdwm1YuOKgRWnpySboQSkSg@mail.gmail.com> (raw)
In-Reply-To: <8cd3d258-91b8-c9b2-106c-01b577cc44d4@gmail.com>

On Mon, Oct 25, 2021 at 8:59 PM Pavel Begunkov <asml.silence@gmail.com> wrote:
>
> On 10/22/21 10:10, Pavel Begunkov wrote:
> > On 10/22/21 04:12, Daniel Black wrote:
> >> Sometime after 5.11 and is fixed in 5.15-rcX (rc6 extensively tested
> >> over last few days) is a kernel regression we are tracing in
> >> https://jira.mariadb.org/browse/MDEV-26674 and
> >> https://jira.mariadb.org/browse/MDEV-26555
> >> 5.10 and early across many distros and hardware appear not to have a problem.
> >>
> >> I'd appreciate some help identifying a 5.14 linux stable patch
> >> suitable as I observe the fault in mainline 5.14.14 (built
> >
> > Cc: io-uring@vger.kernel.org
> >
> > Let me try to remember anything relevant from 5.15,
> > Thanks for letting know
>
> Daniel, following the links I found this:
>
> "From: Daniel Black <daniel@mariadb.org>
> ...
> The good news is I've validated that the linux mainline 5.14.14 build
> from https://kernel.ubuntu.com/~kernel-ppa/mainline/v5.14.14/ has
> actually fixed this problem."
>
> To be clear, is the mainline 5.14 kernel affected with the issue?
> Or does the problem exists only in debian/etc. kernel trees?
>
> --
> Pavel Begunkov


Thanks Pavel for looking.

I'm retesting https://kernel.ubuntu.com/~kernel-ppa/mainline/v5.14.14/
in earnest. I did get some assertions, but they may have been
unrelated. The testing continues...

The problem with debian trees on 5.14.12 (as
linux-image-5.14.0-3-amd64_5.14.12-1_amd64.deb) was quite real
https://jira.mariadb.org/browse/MDEV-26674?focusedCommentId=203155&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-203155


What is concrete is the fc34 package of 5.14.14 (which obviously does
have a Red Hat delta
https://src.fedoraproject.org/rpms/kernel/blob/f34/f/patch-5.14-redhat.patch),
but unsure of significance. Output below:

https://koji.fedoraproject.org/koji/buildinfo?buildID=1847210

$ uname -a
Linux localhost.localdomain 5.14.14-200.fc34.x86_64 #1 SMP Wed Oct 20
16:15:12 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

~/repos/mariadb-server-10.6 10.6
$ bd

~/repos/build-mariadb-server-10.6
$ mysql-test/mtr  --parallel=4 encryption.innochecksum{,,,,,}
Logging: /home/dan/repos/mariadb-server-10.6/mysql-test/mariadb-test-run.pl
 --parallel=4 encryption.innochecksum encryption.innochecksum
encryption.innochecksum encryption.innochecksum
encryption.innochecksum encryption.innochecksum
vardir: /home/dan/repos/build-mariadb-server-10.6/mysql-test/var
Removing old var directory...
 - WARNING: Using the 'mysql-test/var' symlink
The destination for symlink
/home/dan/repos/build-mariadb-server-10.6/mysql-test/var does not
exist; Removing it and creating a new var directory
Creating var directory
'/home/dan/repos/build-mariadb-server-10.6/mysql-test/var'...
Checking supported features...
MariaDB Version 10.6.5-MariaDB
 - SSL connections supported
 - binaries built with wsrep patch
Collecting tests...
Installing system database...

==============================================================================

TEST                                  WORKER RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
worker[3] Using MTR_BUILD_THREAD 302, with reserved ports 16040..16059
worker[2] Using MTR_BUILD_THREAD 301, with reserved ports 16020..16039
worker[4] Using MTR_BUILD_THREAD 303, with reserved ports 16060..16079
encryption.innochecksum '16k,cbc,innodb,strict_crc32' w3 [ pass ]   5460
encryption.innochecksum '16k,cbc,innodb,strict_crc32' w2 [ pass ]   5418
encryption.innochecksum '16k,cbc,innodb,strict_crc32' w1 [ pass ]   9391
encryption.innochecksum '16k,cbc,innodb,strict_crc32' w3 [ pass ]   8682
encryption.innochecksum '16k,cbc,innodb,strict_crc32' w3 [ pass ]   3873
encryption.innochecksum '8k,cbc,innodb,strict_crc32' w1 [ pass ]   9133
encryption.innochecksum '4k,cbc,innodb,strict_crc32' w2 [ pass ]  11074
encryption.innochecksum '8k,cbc,innodb,strict_crc32' w1 [ pass ]   5253
encryption.innochecksum '16k,cbc,innodb,strict_full_crc32' w3 [ pass ]   4019
encryption.innochecksum '4k,cbc,innodb,strict_crc32' w2 [ pass ]   6318
encryption.innochecksum '16k,cbc,innodb,strict_full_crc32' w3 [ pass ]   6176
encryption.innochecksum '8k,cbc,innodb,strict_crc32' w1 [ pass ]   7305
encryption.innochecksum '16k,cbc,innodb,strict_full_crc32' w3 [ pass ]   4430
encryption.innochecksum '4k,cbc,innodb,strict_crc32' w2 [ pass ]  10005
encryption.innochecksum '8k,cbc,innodb,strict_crc32' w1 [ pass ]   6878
encryption.innochecksum '16k,cbc,innodb,strict_full_crc32' w3 [ pass ]   3613
encryption.innochecksum '16k,cbc,innodb,strict_full_crc32' w3 [ pass ]   3875
encryption.innochecksum '4k,cbc,innodb,strict_crc32' w2 [ pass ]   6612
encryption.innochecksum '8k,cbc,innodb,strict_crc32' w1 [ pass ]   4901
encryption.innochecksum '16k,cbc,innodb,strict_full_crc32' w3 [ pass ]   3853
encryption.innochecksum '8k,cbc,innodb,strict_crc32' w1 [ pass ]   5080
encryption.innochecksum '4k,cbc,innodb,strict_crc32' w2 [ pass ]   7072
encryption.innochecksum '4k,cbc,innodb,strict_crc32' w2 [ pass ]   6774
encryption.innochecksum '4k,cbc,innodb,strict_full_crc32' w3 [ pass ]   7037
encryption.innochecksum '8k,cbc,innodb,strict_full_crc32' w1 [ pass ]   4961
encryption.innochecksum '8k,cbc,innodb,strict_full_crc32' w1 [ pass ]   5692
encryption.innochecksum '4k,cbc,innodb,strict_full_crc32' w3 [ pass ]   8449
encryption.innochecksum '16k,ctr,innodb,strict_crc32' w2 [ pass ]   5515
encryption.innochecksum '8k,cbc,innodb,strict_full_crc32' w1 [ pass ]   5650
encryption.innochecksum '16k,ctr,innodb,strict_crc32' w2 [ pass ]   3722
encryption.innochecksum '4k,cbc,innodb,strict_full_crc32' w3 [ pass ]   6691
encryption.innochecksum '8k,cbc,innodb,strict_full_crc32' w1 [ pass ]   4611
encryption.innochecksum '16k,ctr,innodb,strict_crc32' w2 [ pass ]   4587
encryption.innochecksum '16k,ctr,innodb,strict_crc32' w2 [ pass ]   5465
encryption.innochecksum '8k,cbc,innodb,strict_full_crc32' w1 [ pass ]   6900
encryption.innochecksum '4k,cbc,innodb,strict_full_crc32' w3 [ pass ]   8333
encryption.innochecksum '16k,ctr,innodb,strict_crc32' w2 [ pass ]   4691
encryption.innochecksum '8k,cbc,innodb,strict_full_crc32' w1 [ pass ]   5077
encryption.innochecksum '4k,cbc,innodb,strict_full_crc32' w3 [ pass ]   6319
encryption.innochecksum '16k,ctr,innodb,strict_crc32' w2 [ pass ]   4590
encryption.innochecksum '4k,ctr,innodb,strict_crc32' w1 [ pass ]   9683
encryption.innochecksum '8k,ctr,innodb,strict_crc32' w2 [ pass ]   5404
encryption.innochecksum '4k,ctr,innodb,strict_crc32' w1 [ pass ]   6775
encryption.innochecksum '8k,ctr,innodb,strict_crc32' w2 [ pass ]   6190
encryption.innochecksum '4k,ctr,innodb,strict_crc32' w1 [ pass ]   9354
encryption.innochecksum '8k,ctr,innodb,strict_crc32' w2 [ pass ]   7734
encryption.innochecksum '8k,ctr,innodb,strict_crc32' w2 [ pass ]   4993
encryption.innochecksum '4k,ctr,innodb,strict_crc32' w1 [ pass ]   6280
encryption.innochecksum '8k,ctr,innodb,strict_crc32' w2 [ pass ]   4487
encryption.innochecksum '4k,ctr,innodb,strict_crc32' w1 [ pass ]   6971
encryption.innochecksum '8k,ctr,innodb,strict_crc32' w2 [ pass ]   5172
encryption.innochecksum '4k,ctr,innodb,strict_crc32' w1 [ pass ]   6317
encryption.innochecksum '16k,ctr,innodb,strict_full_crc32' w2 [ pass ]   3371
encryption.innochecksum '16k,ctr,innodb,strict_full_crc32' w2 [ pass ]   3472
encryption.innochecksum '16k,ctr,innodb,strict_full_crc32' w2 [ pass ]   6707
encryption.innochecksum '4k,ctr,innodb,strict_full_crc32' w1 [ pass ]   9337
encryption.innochecksum '16k,ctr,innodb,strict_full_crc32' w2 [ pass ]   9176
encryption.innochecksum '4k,ctr,innodb,strict_full_crc32' w1 [ pass ]  11817
encryption.innochecksum '16k,ctr,innodb,strict_full_crc32' w2 [ pass ]   3419
encryption.innochecksum '16k,ctr,innodb,strict_full_crc32' w2 [ pass ]   5256
encryption.innochecksum '4k,ctr,innodb,strict_full_crc32' w1 [ pass ]   9291
encryption.innochecksum '4k,ctr,innodb,strict_full_crc32' w1 [ pass ]   6508
encryption.innochecksum '4k,ctr,innodb,strict_full_crc32' w2 [ pass ]   6294
encryption.innochecksum '4k,ctr,innodb,strict_full_crc32' w1 [ pass ]   6327
encryption.innochecksum '8k,ctr,innodb,strict_full_crc32' w2 [ pass ]   4579
encryption.innochecksum '8k,ctr,innodb,strict_full_crc32' w1 [ pass ]   4764
encryption.innochecksum '8k,ctr,innodb,strict_full_crc32' w2 [ pass ]   4469
encryption.innochecksum '8k,ctr,innodb,strict_full_crc32' w1 [ pass ]   4677
encryption.innochecksum '8k,ctr,innodb,strict_full_crc32' w2 [ pass ]   4696
encryption.innochecksum '8k,ctr,innodb,strict_full_crc32' w1 [ pass ]   3898
encryption.innochecksum '4k,cbc,innodb,strict_full_crc32' w3 [ pass ]  127358
encryption.innochecksum '16k,cbc,innodb,strict_crc32' w4 [ fail ]
        Test ended at 2021-10-25 21:39:13

CURRENT_TEST: encryption.innochecksum
mysqltest: At line 41: query 'INSERT INTO t3 SELECT * FROM t1' failed:
<Unknown> (2013): Lost connection to server during query

The result from queries just before the failure was:
SET GLOBAL innodb_file_per_table = ON;
set global innodb_compression_algorithm = 1;
# Create and populate a tables
CREATE TABLE t1 (a INT AUTO_INCREMENT PRIMARY KEY, b TEXT)
ENGINE=InnoDB ENCRYPTED=YES ENCRYPTION_KEY_ID=4;
CREATE TABLE t2 (a INT AUTO_INCREMENT PRIMARY KEY, b TEXT)
ENGINE=InnoDB ROW_FORMAT=COMPRESSED ENCRYPTED=YES ENCRYPTION_KEY_ID=4;
CREATE TABLE t3 (a INT AUTO_INCREMENT PRIMARY KEY, b TEXT)
ENGINE=InnoDB ROW_FORMAT=COMPRESSED ENCRYPTED=NO;
CREATE TABLE t4 (a INT AUTO_INCREMENT PRIMARY KEY, b TEXT)
ENGINE=InnoDB PAGE_COMPRESSED=1;
CREATE TABLE t5 (a INT AUTO_INCREMENT PRIMARY KEY, b TEXT)
ENGINE=InnoDB PAGE_COMPRESSED=1 ENCRYPTED=YES ENCRYPTION_KEY_ID=4;
CREATE TABLE t6 (a INT AUTO_INCREMENT PRIMARY KEY, b TEXT) ENGINE=InnoDB;


Server [mysqld.1 - pid: 15380, winpid: 15380, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
$ /home/dan/repos/build-mariadb-server-10.6/sql/mariadbd
--defaults-group-suffix=.1
--defaults-file=/home/dan/repos/build-mariadb-server-10.6/mysql-test/var/4/my.cnf
--log-output=file --innodb-page-size=16K
--skip-innodb-read-only-compressed
--innodb-checksum-algorithm=strict_crc32 --innodb-flush-sync=OFF
--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx
--innodb-locks --innodb-lock-waits --innodb-metrics
--innodb-buffer-pool-stats --innodb-buffer-page
--innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields
--innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes
--innodb-sys-tables --innodb-sys-virtual
--plugin-load-add=file_key_management.so --loose-file-key-management
--loose-file-key-management-filename=/home/dan/repos/mariadb-server-10.6/mysql-test/std_data/keys.txt
--file-key-management-encryption-algorithm=aes_cbc
--skip-innodb-read-only-compressed --core-file
--loose-debug-sync-timeout=300
2021-10-25 21:28:56 0 [Note]
/home/dan/repos/build-mariadb-server-10.6/sql/mariadbd (server
10.6.5-MariaDB-log) starting as process 15381 ...
2021-10-25 21:28:56 0 [Warning] Could not increase number of
max_open_files to more than 1024 (request: 32190)
2021-10-25 21:28:56 0 [Warning] Changed limits: max_open_files: 1024
max_connections: 151 (was 151)  table_cache: 421 (was 2000)
2021-10-25 21:28:56 0 [Note] Plugin 'partition' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'SEQUENCE' is disabled.
2021-10-25 21:28:56 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2021-10-25 21:28:56 0 [Note] InnoDB: Number of pools: 1
2021-10-25 21:28:56 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2021-10-25 21:28:56 0 [Note] InnoDB: Using liburing
2021-10-25 21:28:56 0 [Note] InnoDB: Initializing buffer pool, total
size = 8388608, chunk size = 8388608
2021-10-25 21:28:56 0 [Note] InnoDB: Completed initialization of buffer pool
2021-10-25 21:28:56 0 [Note] InnoDB: 128 rollback segments are active.
2021-10-25 21:28:56 0 [Note] InnoDB: Creating shared tablespace for
temporary tables
2021-10-25 21:28:56 0 [Note] InnoDB: Setting file './ibtmp1' size to
12 MB. Physically writing the file full; Please wait ...
2021-10-25 21:28:56 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2021-10-25 21:28:56 0 [Note] InnoDB: 10.6.5 started; log sequence
number 43637; transaction id 17
2021-10-25 21:28:56 0 [Note] InnoDB: Loading buffer pool(s) from
/home/dan/repos/build-mariadb-server-10.6/mysql-test/var/4/mysqld.1/data/ib_buffer_pool
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_CMP' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'THREAD_POOL_WAITS' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'THREAD_POOL_QUEUES' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'FEEDBACK' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'THREAD_POOL_GROUPS' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'user_variables' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'THREAD_POOL_STATS' is disabled.
2021-10-25 21:28:56 0 [Note] Plugin 'unix_socket' is disabled.
2021-10-25 21:28:56 0 [Warning]
/home/dan/repos/build-mariadb-server-10.6/sql/mariadbd: unknown
variable 'loose-feedback-debug-startup-interval=20'
2021-10-25 21:28:56 0 [Warning]
/home/dan/repos/build-mariadb-server-10.6/sql/mariadbd: unknown
variable 'loose-feedback-debug-first-interval=60'
2021-10-25 21:28:56 0 [Warning]
/home/dan/repos/build-mariadb-server-10.6/sql/mariadbd: unknown
variable 'loose-feedback-debug-interval=60'
2021-10-25 21:28:56 0 [Warning]
/home/dan/repos/build-mariadb-server-10.6/sql/mariadbd: unknown option
'--loose-pam-debug'
2021-10-25 21:28:56 0 [Warning]
/home/dan/repos/build-mariadb-server-10.6/sql/mariadbd: unknown option
'--loose-aria'
2021-10-25 21:28:56 0 [Warning]
/home/dan/repos/build-mariadb-server-10.6/sql/mariadbd: unknown
variable 'loose-debug-sync-timeout=300'
2021-10-25 21:28:56 0 [Note] Server socket created on IP: '127.0.0.1'.
2021-10-25 21:28:56 0 [Note]
/home/dan/repos/build-mariadb-server-10.6/sql/mariadbd: ready for
connections.
Version: '10.6.5-MariaDB-log'  socket:
'/home/dan/repos/build-mariadb-server-10.6/mysql-test/var/tmp/4/mysqld.1.sock'
 port: 16060  Source distribution
2021-10-25 21:28:56 0 [Note] InnoDB: Buffer pool(s) load completed at
211025 21:28:56
2021-10-25 21:39:11 0 [ERROR] [FATAL] InnoDB:
innodb_fatal_semaphore_wait_threshold was exceeded for dict_sys.latch

  reply	other threads:[~2021-10-25 11:09 UTC|newest]

Thread overview: 36+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2021-10-22  3:12 uring regression - lost write request Daniel Black
2021-10-22  9:10 ` Pavel Begunkov
2021-10-25  9:57   ` Pavel Begunkov
2021-10-25 11:09     ` Daniel Black [this message]
2021-10-25 11:25       ` Pavel Begunkov
2021-10-30  7:30         ` Salvatore Bonaccorso
2021-11-01  7:28           ` Daniel Black
2021-11-09 22:58             ` Daniel Black
2021-11-09 23:24               ` Jens Axboe
2021-11-10 18:01                 ` Jens Axboe
2021-11-11  6:52                   ` Daniel Black
2021-11-11 14:30                     ` Jens Axboe
2021-11-11 14:58                       ` Jens Axboe
2021-11-11 15:29                         ` Jens Axboe
2021-11-11 16:19                           ` Jens Axboe
2021-11-11 16:55                             ` Jens Axboe
2021-11-11 17:28                               ` Jens Axboe
2021-11-11 23:44                                 ` Jens Axboe
2021-11-12  6:25                                   ` Daniel Black
2021-11-12 19:19                                     ` Salvatore Bonaccorso
2021-11-14 20:33                                   ` Daniel Black
2021-11-14 20:55                                     ` Jens Axboe
2021-11-14 21:02                                       ` Salvatore Bonaccorso
2021-11-14 21:03                                         ` Jens Axboe
2021-11-24  3:27                                       ` Daniel Black
2021-11-24 15:28                                         ` Jens Axboe
2021-11-24 16:10                                           ` Jens Axboe
2021-11-24 16:18                                             ` Greg Kroah-Hartman
2021-11-24 16:22                                               ` Jens Axboe
2021-11-24 22:52                                                 ` Stefan Metzmacher
2021-11-25  0:58                                                   ` Jens Axboe
2021-11-25 16:35                                                     ` Stefan Metzmacher
2021-11-25 17:11                                                       ` Jens Axboe
2022-02-09 23:01                                                       ` Stefan Metzmacher
2022-02-10  0:10                                                         ` Daniel Black
2021-11-24 22:57                                                 ` Daniel Black

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=CABVffEOMVbQ+MynbcNfD7KEA5Mwqdwm1YuOKgRWnpySboQSkSg@mail.gmail.com \
    --to=daniel@mariadb.org \
    --cc=asml.silence@gmail.com \
    --cc=io-uring@vger.kernel.org \
    --cc=linux-block@vger.kernel.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body. 
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).