[MDEV-23416] innodb.innodb_mutexes failed in buildbot with extra warning Created: 2020-08-06  Updated: 2021-03-22  Resolved: 2021-03-22

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.5
Fix Version/s: N/A

Type: Bug Priority: Minor
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Cannot Reproduce Votes: 0
Labels: need_rr

Issue Links:
Relates
relates to MDEV-15053 Reduce buf_pool_t::mutex contention Closed
relates to MDEV-24391 heap-use-after-free in fil_space_t::f... Closed

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/4383

10.5 1247b36bad

 
innodb.innodb_mutexes 'innodb'           w1 [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2020-06-25 12:10:57
 
line
 
2020-06-25 12:10:39 4 [Warning] InnoDB: Trying to delete tablespace 'test/t1' but there are 0 flushes and 1 pending i/o's on it.
 
^ Found warnings in /dev/shm/var/1/log/mysqld.1.err
 
ok



 Comments   
Comment by Marko Mäkelä [ 2020-08-07 ]

I think that these messages started to appear more often after MDEV-15053. Maybe we should demote it to a note if it is not a permanent hang?

If we can repeat this under rr replay, it should be possible to debug the cause and see if the logic can be revised.

Comment by Marko Mäkelä [ 2020-08-19 ]

I changed the message to a note, so that it will not trigger random failures on our CI systems. As far as I can tell, the first message should be displayed after 1 second of waiting, and a subsequent message after 11 seconds, and so on. As far as I understand, we are seeing one message every now and then.

I think that we must still find the root cause of these performance glitches. Hence, I am not closing this bug yet.

Comment by Marko Mäkelä [ 2020-12-20 ]

In 10.6, the test innodb.innodb_mutexes was removed by MDEV-24142.

This problem could be timing-related, and maybe the first warnings should be changed to a note. Another occurrence:

10.5 ee69c153d9a20675dcfb368ab52b7a63d15f112d

 
innodb.innodb-page_compression_lzma 'innodb' w1 [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2020-12-15 09:48:10
 
line
 
2020-12-15  9:48:10 3 [Warning] InnoDB: Trying to delete tablespace 'test/innodb_page_compressed2' but there are 4 pending operations on it.

This failure occurred after the fix of MDEV-24391 was applied but before MDEV-24442. Failures of this kind seem very sporadic; the previous one was

10.5 897b51db434d58e5cfe0079195bb81b7ff624fce

 
encryption.innodb_encryption-page-compression 'innodb' w1 [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2020-09-10 16:30:38
 
line
 
2020-09-10 16:30:36 3 [Warning] InnoDB: Trying to delete tablespace 'test/innodb_page_compressed5' but there are 1 pending operations on it.
 
^ Found warnings in /dev/shm/var/1/log/mysqld.1.err

The reason of that failure might have been fixed since then. The server error log contained the following:

2020-09-10 16:30:35 3 [Note] InnoDB: Writing table metadata to './test/innodb_page_compressed9.cfg'
 
2020-09-10 16:30:35 3 [Note] InnoDB: Table `test`.`innodb_page_compressed9` flushed to disk
 
2020-09-10 16:30:35 3 [Note] InnoDB: Deleting the meta-data file './test/innodb_page_compressed1.cfg'
 
2020-09-10 16:30:35 3 [Note] InnoDB: Deleting the meta-data file './test/innodb_page_compressed2.cfg'
 
2020-09-10 16:30:35 3 [Note] InnoDB: Deleting the meta-data file './test/innodb_page_compressed3.cfg'
 
2020-09-10 16:30:35 3 [Note] InnoDB: Deleting the meta-data file './test/innodb_page_compressed4.cfg'
 
2020-09-10 16:30:35 3 [Note] InnoDB: Deleting the meta-data file './test/innodb_page_compressed5.cfg'
 
2020-09-10 16:30:35 3 [Note] InnoDB: Deleting the meta-data file './test/innodb_page_compressed6.cfg'
 
2020-09-10 16:30:35 3 [Note] InnoDB: Deleting the meta-data file './test/innodb_page_compressed7.cfg'
 
2020-09-10 16:30:35 3 [Note] InnoDB: Deleting the meta-data file './test/innodb_page_compressed8.cfg'
 
2020-09-10 16:30:35 3 [Note] InnoDB: Deleting the meta-data file './test/innodb_page_compressed9.cfg'
 
2020-09-10 16:30:35 3 [Note] InnoDB: Resuming purge
 
2020-09-10 16:30:36 3 [Warning] InnoDB: Trying to delete tablespace 'test/innodb_page_compressed5' but there are 1 pending operations on it.
 
CURRENT_TEST: encryption.innodb_encryption-page-compression
 
2020-09-10 16:30:38 0 [Note] /usr/sbin/mariadbd (mysqld 10.5.6-MariaDB-1:10.5.6+maria~xenial-log) starting as process 10191 ...

So, it appears that the server was killed and restarted after the unexpected message was found.

Comment by Marko Mäkelä [ 2021-03-22 ]

The very last failures for main trees are as follows, both for the test innodb.innodb-page_compression_lzma:

version builder date setup
10.6 f02c8ffa340cf8b1cb6e7530dbaa95a6 kvm-rpm-fedora32-amd64 2020-12-23 15:24:28 815 nm
10.5 39378e1366f78b38c05e45103b9fb9c8 kvm-rpm-centos74-amd64 2020-12-21 20:24:42 17250 nm
Generated at Thu Feb 08 09:22:14 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.