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

innodb.innodb_mutexes failed in buildbot with extra warning

Details

    • Bug
    • Status: Closed (View Workflow)
    • Minor
    • Resolution: Cannot Reproduce
    • 10.5
    • N/A
    • Tests

    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
      

      Attachments

        Issue Links

          Activity

            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.

            marko Marko Mäkelä added a comment - 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.

            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.

            marko Marko Mäkelä added a comment - 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.

            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.

            marko Marko Mäkelä added a comment - 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.

            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
            marko Marko Mäkelä added a comment - 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

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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