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

MariaDB unresponsive and in error log file --Thread 139894688810752 has waited at srv0srv.cc line 1554

Details

    • Bug
    • Status: Open (View Workflow)
    • Critical
    • Resolution: Unresolved
    • 10.5.9
    • None
    • Data Definition - Alter Table
    • None

    Description

      The MariaDB is very slow and at times it is unresponsive., while working on Database Encryption.

      After updated below MariaDB encryption variables , initiated the mariadb service. while few tables are getting auto encrypted there are errors in mariadb error log file

      plugin_dir=<MariaDB_Bin>/lib/plugin
      plugin_load_add=file_key_management.so

      file_key_management_filename=/<PATH>/keyfile.enc
      file_key_management_filekey=FILE:/<PATH>/keyfile.passwd
      file_key_management_encryption_algorithm=aes_cbc

      encrypt_binlog=ON

      innodb_encrypt_log=ON
      innodb_encryption_threads=7
      innodb_encrypt_tables=FORCE
      innodb_encrypt_temporary_tables=ON
      encrypt_tmp_disk_tables=ON
      encrypt_tmp_files=ON
      aria_encrypt_tables=ON
      innodb_encryption_rotate_key_age=1024
      innodb_encryption_rotation_iops=1024

      === MariaDb Error Log ============

      2024-03-12 9:57:58 0 [Note] /data/HCL/mariadb/bin/mariadbd: ready for connections.
      Version: '10.5.9-MariaDB-log' socket: '/tmp/mysql.sock' port: 3306 MariaDB Server
      2024-03-12 10:23:03 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:24:55 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:26:27 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:27:15 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:31:06 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:31:46 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 2 pending operations
      2024-03-12 10:32:22 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:33:21 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:33:44 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:34:16 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:35:17 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 2 pending operations
      2024-03-12 10:39:15 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:50:21 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:51:47 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 10:58:09 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 11:11:22 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 11:11:43 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 11:24:04 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 11:31:38 4 [Note] InnoDB: Cannot close file ./platform/usm_opt_lock.ibd because of 1 pending operations
      2024-03-12 11:35:43 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 139894688810752 has waited at srv0srv.cc line 1554 for 245.00 seconds the semaphore:
      X-lock on RW-latch at 0x55d36855e338 created in file dict0dict.cc line 1041
      a writer (thread id 139906278823680) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time write locked in file handler0alter.cc line 6255
      2024-03-12 11:35:43 0 [Note] InnoDB: A semaphore wait:

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-26055 Adaptive flushing is still not getting invoked in 10.5.11

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-32977 InnoDB Cannot close file Pending operations and pending fsync

          • Major - Major loss of function.
          • Open

          Activity

            Ascending order - Click to sort in descending order
            marko Marko Mäkelä added a comment -

            The page flushing was last revised in MDEV-26055. Also MDEV-32977 has been filed for similar symptoms.

            MariaDB Server 10.5.9 was released 3 years ago. Can you try to upgrade to a later version?

            marko Marko Mäkelä added a comment - The page flushing was last revised in MDEV-26055 . Also MDEV-32977 has been filed for similar symptoms. MariaDB Server 10.5.9 was released 3 years ago. Can you try to upgrade to a later version?
            MurthyRamachandrula R S N Murthy added a comment -

            Ramachandrula Sriman narayana murthy <ramachandrula.srima@hcl-software.com>
            8:02 PM (1 minute ago)
            to Marko

            Hi Marko Makela

            Thank you for quick response. I find those two MDEV-26055. Also MDEV-32977 are not related to the issue we have here. The tickets mentioned are not part of encryption and there is no error relating to semaphore that is noticed in my error log file.

            2024-03-12 11:36:13 0 [Warning] InnoDB: A long semaphore wait:
            --Thread 139894688810752 has waited at srv0srv.cc line 1554 for 275.00 seconds the semaphore:

            The present application support that we hold is Mariadb10.5.9. so we can not move out of these version until we get confirmation from application support. Kindly guide me, to resolve in these regards.

            MurthyRamachandrula R S N Murthy added a comment - Ramachandrula Sriman narayana murthy <ramachandrula.srima@hcl-software.com> 8:02 PM (1 minute ago) to Marko Hi Marko Makela Thank you for quick response. I find those two MDEV-26055 . Also MDEV-32977 are not related to the issue we have here. The tickets mentioned are not part of encryption and there is no error relating to semaphore that is noticed in my error log file. 2024-03-12 11:36:13 0 [Warning] InnoDB: A long semaphore wait: --Thread 139894688810752 has waited at srv0srv.cc line 1554 for 275.00 seconds the semaphore: The present application support that we hold is Mariadb10.5.9. so we can not move out of these version until we get confirmation from application support. Kindly guide me, to resolve in these regards.
            danblack Daniel Black added a comment -

            The messages "Cannot close file" are due to [https://mariadb.com/kb/en/innodb-system-variables/#innodb_open_files|innodb_open_files] being reached. Could it be the autosizing isn't sufficient for the workload?

            Is the usm_opt_lock table of sufficient size that taking over an hour to encrypt would seem unlikely (at 1000iops).

            Was the ALTER TABLE being performed on the usm_opt_lock table?

            What exact encryption variables where updated? And was the same behaviour observed with an ALTER TABLE under the same condition before the variables where updated?

            As this is a bug tracker more than support ticket system, look to recreate your issue with a self contained test case, and then test on the latest 10.5 instance.

            Also look at the status measurement and recommendations taken in MDEV-26055 and MDEV-32977 before dismissing them so quickly. Encryption maybe holding the table open, but the cause of the problem may be elsewhere.

            danblack Daniel Black added a comment - The messages "Cannot close file" are due to [https://mariadb.com/kb/en/innodb-system-variables/#innodb_open_files|innodb_open_files] being reached. Could it be the autosizing isn't sufficient for the workload? Is the usm_opt_lock table of sufficient size that taking over an hour to encrypt would seem unlikely (at 1000iops). Was the ALTER TABLE being performed on the usm_opt_lock table? What exact encryption variables where updated? And was the same behaviour observed with an ALTER TABLE under the same condition before the variables where updated? As this is a bug tracker more than support ticket system, look to recreate your issue with a self contained test case, and then test on the latest 10.5 instance. Also look at the status measurement and recommendations taken in MDEV-26055 and MDEV-32977 before dismissing them so quickly. Encryption maybe holding the table open, but the cause of the problem may be elsewhere.
            MurthyRamachandrula R S N Murthy added a comment -

            Yes , Thank you , As advised, i did a test to recreate the issue .

             The type of encryption is Data At Rest Encryption using "file_key_management" with algorithm "aes_cbc"

            plugin_load_add=file_key_management.so
            file_key_management_encryption_algorithm=aes_cbc

            After updating my.cnf file with the Encryption Variables. started MariaDB service, and checked the status with below query . after 5 min there is no change for the rows in below query.

            MariaDB [(none)]> select name, KEY_ROTATION_PAGE_NUMBER, KEY_ROTATION_MAX_PAGE_NUMBER from information_schema.innodb_tablespaces_encryption where min_key_version = 0 or ROTATING_OR_FLUSHING = 1;
            --------------------------------------------------------------------------

            name KEY_ROTATION_PAGE_NUMBER KEY_ROTATION_MAX_PAGE_NUMBER

            --------------------------------------------------------------------------

            innodb_system 504901924 1104256
            *plan/uap_event_queue 0 0 **
            --------------------------------------------------------------------------
            2 rows in set (0.038 sec)

            There are no issues noticed in ErrorLog file . Started manual encryption for other schema tables in parallel using "alter table TABLENAME encrypted=yes" .

            The execution was slow, so altered the global variable as below. Later after changing innodb_encryption_rotation_iops there are errors noticed in ErrorLog file.

            MariaDB [(none)]> select @@innodb_encryption_threads;
            -----------------------------

            @@innodb_encryption_threads

            -----------------------------

            4

            -----------------------------
            1 row in set (0.000 sec)

            MariaDB [(none)]> select @@innodb_encryption_rotation_iops;
            -----------------------------------

            @@innodb_encryption_rotation_iops

            -----------------------------------

            2000

            -----------------------------------
            1 row in set (0.000 sec)

            MariaDB [(none)]> set global innodb_encryption_rotation_iops=10000;
            Query OK, 0 rows affected (0.000 sec)

            MariaDB [(none)]> select @@innodb_encryption_rotation_iops;
            -----------------------------------

            @@innodb_encryption_rotation_iops

            -----------------------------------

            10000

            -----------------------------------
            1 row in set (0.000 sec)

            Error Logfile:

            [root@duuscn1ahxunwcldbs1001 mariadb]# tail -f /data/HCL/mariadb/Error_logs/duuscn1ahxunwcldbs1001.err
            2024-03-13 5:42:13 0 [Note] Server socket created on IP: '10.210.2.131'.
            2024-03-13 5:42:13 0 [Note] Reading of all Master_info entries succeeded
            2024-03-13 5:42:13 0 [Note] Added new Master_info '' to hash table
            2024-03-13 5:42:13 0 [Note] /data/HCL/mariadb/bin/mariadbd: ready for connections.
            Version: '10.5.9-MariaDB-log' socket: '/tmp/mysqld.sock' port: 3306 MariaDB Server
            2024-03-13 5:42:16 0 [Note] InnoDB: Buffer pool(s) load completed at 240313 5:42:16
            2024-03-13 6:10:40 4 [Note] InnoDB: Cannot close file ./plan/uap_event_queue.ibd because of 1 pending operations
            2024-03-13 6:11:55 4 [Note] InnoDB: Cannot close file ./plan/uap_event_queue.ibd because of 1 pending operations
            2024-03-13 6:16:52 4 [Note] InnoDB: Cannot close file ./plan/uap_event_queue.ibd because of 1 pending operations
            2024-03-13 6:29:06 4 [Note] InnoDB: Cannot close file ./plan/uap_event_queue.ibd because of 1 pending operations

            MurthyRamachandrula R S N Murthy added a comment - Yes , Thank you , As advised, i did a test to recreate the issue .  The type of encryption is Data At Rest Encryption using "file_key_management" with algorithm "aes_cbc" plugin_load_add=file_key_management.so file_key_management_encryption_algorithm=aes_cbc After updating my.cnf file with the Encryption Variables. started MariaDB service, and checked the status with below query . after 5 min there is no change for the rows in below query. MariaDB [(none)] > select name, KEY_ROTATION_PAGE_NUMBER, KEY_ROTATION_MAX_PAGE_NUMBER from information_schema.innodb_tablespaces_encryption where min_key_version = 0 or ROTATING_OR_FLUSHING = 1; --------------------- ------------------------ ----------------------------- name KEY_ROTATION_PAGE_NUMBER KEY_ROTATION_MAX_PAGE_NUMBER --------------------- ------------------------ ----------------------------- innodb_system 504901924 1104256 *plan/uap_event_queue 0 0 ** --------------------- ------------------------ ----------------------------- 2 rows in set (0.038 sec) There are no issues noticed in ErrorLog file . Started manual encryption for other schema tables in parallel using "alter table TABLENAME encrypted=yes" . The execution was slow, so altered the global variable as below. Later after changing innodb_encryption_rotation_iops there are errors noticed in ErrorLog file. MariaDB [(none)] > select @@innodb_encryption_threads; ----------------------------- @@innodb_encryption_threads ----------------------------- 4 ----------------------------- 1 row in set (0.000 sec) MariaDB [(none)] > select @@innodb_encryption_rotation_iops; ----------------------------------- @@innodb_encryption_rotation_iops ----------------------------------- 2000 ----------------------------------- 1 row in set (0.000 sec) MariaDB [(none)] > set global innodb_encryption_rotation_iops=10000; Query OK, 0 rows affected (0.000 sec) MariaDB [(none)] > select @@innodb_encryption_rotation_iops; ----------------------------------- @@innodb_encryption_rotation_iops ----------------------------------- 10000 ----------------------------------- 1 row in set (0.000 sec) Error Logfile: [root@duuscn1ahxunwcldbs1001 mariadb] # tail -f /data/HCL/mariadb/Error_logs/duuscn1ahxunwcldbs1001.err 2024-03-13 5:42:13 0 [Note] Server socket created on IP: '10.210.2.131'. 2024-03-13 5:42:13 0 [Note] Reading of all Master_info entries succeeded 2024-03-13 5:42:13 0 [Note] Added new Master_info '' to hash table 2024-03-13 5:42:13 0 [Note] /data/HCL/mariadb/bin/mariadbd: ready for connections. Version: '10.5.9-MariaDB-log' socket: '/tmp/mysqld.sock' port: 3306 MariaDB Server 2024-03-13 5:42:16 0 [Note] InnoDB: Buffer pool(s) load completed at 240313 5:42:16 2024-03-13 6:10:40 4 [Note] InnoDB: Cannot close file ./plan/uap_event_queue.ibd because of 1 pending operations 2024-03-13 6:11:55 4 [Note] InnoDB: Cannot close file ./plan/uap_event_queue.ibd because of 1 pending operations 2024-03-13 6:16:52 4 [Note] InnoDB: Cannot close file ./plan/uap_event_queue.ibd because of 1 pending operations 2024-03-13 6:29:06 4 [Note] InnoDB: Cannot close file ./plan/uap_event_queue.ibd because of 1 pending operations

            People

              Unassigned Unassigned
              MurthyRamachandrula R S N Murthy
              Votes:
              0 Vote for this issue
              Watchers:
              3 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.