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

MariaDB 10.6.12 hang 2 days after upgrade

    XMLWordPrintable

Details

    Description

      Today our production server was suddenly hanging. The only thing that changed was an upgrade from 10.6.11 to 10.6.12 2 days ago. So I assume it has something to do with the new release because we never experienced this before.

      How did we find: Script complained that it was already running. So previous run of script did not terminate for long time.

      Database shows:

      SQL> SHOW PROCESSLIST;
      +--------+-------------+--------------------------+--------+-------------+--------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+
      | Id     | User        | Host                     | db     | Command     | Time   | State                                                         | Info                                                                                                 | Progress |
      +--------+-------------+--------------------------+--------+-------------+--------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+
      |      5 | system user |                          | NULL   | Slave_IO    | 222766 | Waiting for master to send event                              | NULL                                                                                                 |    0.000 |
      |      6 | system user |                          | NULL   | Slave_SQL   |      3 | Slave has read all relay log; waiting for more updates        | NULL                                                                                                 |    0.000 |
      |      7 | zabbix      | localhost:58656          | zabbix | Sleep       |      1 |                                                               | NULL                                                                                                 |    0.000 |
      |      8 | zabbix      | localhost:58666          | zabbix | Sleep       |      2 |                                                               | NULL                                                                                                 |    0.000 |
      |      9 | zabbix      | localhost:58674          | zabbix | Sleep       |      1 |                                                               | NULL                                                                                                 |    0.000 |
      |     10 | zabbix      | localhost:58686          | zabbix | Sleep       |      3 |                                                               | NULL                                                                                                 |    0.000 |
      |     13 | zabbix      | localhost:58708          | zabbix | Sleep       |     51 |                                                               | NULL                                                                                                 |    0.000 |
      |     16 | zabbix      | localhost:58718          | zabbix | Sleep       |      0 |                                                               | NULL                                                                                                 |    0.000 |
      |     32 | zabbix      | localhost:39622          | zabbix | Sleep       |     35 |                                                               | NULL                                                                                                 |    0.000 |
      |    146 | replication | maas1.fromdual.com:35856 | NULL   | Binlog Dump | 222729 | Master has sent all binlog to slave; waiting for more updates | NULL                                                                                                 |    0.000 |
      |    150 | zabbix      | localhost:46088          | zabbix | Sleep       |   7903 |                                                               | NULL                                                                                                 |    0.000 |
      |    367 | zabbix      | localhost:60340          | zabbix | Sleep       |   8268 |                                                               | NULL                                                                                                 |    0.000 |
      |    588 | zabbix      | localhost:54340          | zabbix | Sleep       |   7958 |                                                               | NULL                                                                                                 |    0.000 |
      |   1269 | zabbix      | localhost:45482          | zabbix | Sleep       |   8028 |                                                               | NULL                                                                                                 |    0.000 |
      |   1484 | zabbix      | localhost:40008          | zabbix | Sleep       |   8101 |                                                               | NULL                                                                                                 |    0.000 |
      |  67247 | zabbix      | localhost:47262          | zabbix | Query      |  10473 | Update                                                        | insert into history_uint (itemid,clock,ns,value) values (66915,1676576402,1,3145344),(66916,16765764 |    0.000 |
      | 413224 | zabbix      | localhost:44396          | zabbix | Query       |  10473 | Update                                                        | insert into history_uint (itemid,clock,ns,value) values (26687,1676576404,32,7631),(26836,1676576403 |    0.000 |
      | 413226 | zabbix      | localhost:44426          | zabbix | Query       |  10473 | Update                                                        | insert into history_uint (itemid,clock,ns,value) values (23187,1676576401,66,0),(23188,1676576401,67 |    0.000 |
      | 590933 | zabbix      | localhost:51912          | zabbix | Query       |  10473 | Update                                                        | insert into history_uint (itemid,clock,ns,value) values (23177,1676576401,153,0),(23178,1676576401,1 |    0.000 |
      | 652992 | zabbix      | localhost:42022          | zabbix | Query       |  10473 | Statistics                                                    | SELECT itemid,COUNT(*) AS count,AVG(value) AS avg,MIN(value) AS min,MAX(value) AS max,round(500* MOD |    0.000 |
      | 652997 | zabbix      | localhost:42034          | zabbix | Query       |  10473 | Statistics                                                    | SELECT itemid,COUNT(*) AS count,AVG(value) AS avg,MIN(value) AS min,MAX(value) AS max,round(500* MOD |    0.000 |
      | 652999 | zabbix      | localhost:42046          | zabbix | Query       |  10473 | Statistics                                                    | SELECT itemid,COUNT(*) AS count,AVG(value) AS avg,MIN(value) AS min,MAX(value) AS max,round(500* MOD |    0.000 |
      | 674125 | zabbix      | localhost:52324          | zabbix | Query       |     54 | Opening tables                                                | insert into history_uint (itemid,clock,ns,value) values (66915,1676576402,1,3145344),(66916,16765764 |    0.000 |
      | 674245 | root        | localhost                | NULL   | Query       |      0 | starting                                                      | show processlist                                                                                     |    0.000 |
      +--------+-------------+--------------------------+--------+-------------+--------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+
       
      SQL> status;
      --------------
      mysql  Ver 15.1 Distrib 10.6.12-MariaDB, for linux-systemd (x86_64) using readline 5.1
       
      Connection id:          674245
      Current database:
      Current user:           root@localhost
      SSL:                    Not in use
      Current pager:          stdout
      Using outfile:          ''
      Using delimiter:        ;
      Server:                 MariaDB
      Server version:         10.6.12-MariaDB-log MariaDB Server
      Protocol version:       10
      Connection:             Localhost via UNIX socket
      Server characterset:    latin1
      Db     characterset:    latin1
      Client characterset:    utf8mb4
      Conn.  characterset:    utf8mb4
      UNIX socket:            /var/run/mysqld/mysql-33006.sock
      Uptime:                 2 days 13 hours 53 min 38 sec
       
      Threads: 32  Questions: 15509507  Slow queries: 3764  Opens: 973  Open tables: 789  Queries per second avg: 69.606
      

      Killing did not help:

      SQL> SHOW PROCESSLIST;
      +--------+-------------+--------------------------+--------+-------------+--------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+
      | Id     | User        | Host                     | db     | Command     | Time   | State                                                         | Info                                                                                                 | Progress |
      +--------+-------------+--------------------------+--------+-------------+--------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+
      |      5 | system user |                          | NULL   | Slave_IO    | 222809 | Waiting for master to send event                              | NULL                                                                                                 |    0.000 |
      |      6 | system user |                          | NULL   | Slave_SQL   |     15 | Slave has read all relay log; waiting for more updates        | NULL                                                                                                 |    0.000 |
      |      7 | zabbix      | localhost:58656          | zabbix | Sleep       |      1 |                                                               | NULL                                                                                                 |    0.000 |
      |      8 | zabbix      | localhost:58666          | zabbix | Sleep       |     45 |                                                               | NULL                                                                                                 |    0.000 |
      |      9 | zabbix      | localhost:58674          | zabbix | Sleep       |      3 |                                                               | NULL                                                                                                 |    0.000 |
      |     10 | zabbix      | localhost:58686          | zabbix | Sleep       |      1 |                                                               | NULL                                                                                                 |    0.000 |
      |     13 | zabbix      | localhost:58708          | zabbix | Sleep       |     33 |                                                               | NULL                                                                                                 |    0.000 |
      |     16 | zabbix      | localhost:58718          | zabbix | Sleep       |      0 |                                                               | NULL                                                                                                 |    0.000 |
      |     32 | zabbix      | localhost:39622          | zabbix | Sleep       |     18 |                                                               | NULL                                                                                                 |    0.000 |
      |    146 | replication | maas1.fromdual.com:35856 | NULL   | Binlog Dump | 222771 | Master has sent all binlog to slave; waiting for more updates | NULL                                                                                                 |    0.000 |
      |    150 | zabbix      | localhost:46088          | zabbix | Sleep       |   7945 |                                                               | NULL                                                                                                 |    0.000 |
      |    367 | zabbix      | localhost:60340          | zabbix | Sleep       |   8311 |                                                               | NULL                                                                                                 |    0.000 |
      |    588 | zabbix      | localhost:54340          | zabbix | Sleep       |   8001 |                                                               | NULL                                                                                                 |    0.000 |
      |   1269 | zabbix      | localhost:45482          | zabbix | Sleep       |   8071 |                                                               | NULL                                                                                                 |    0.000 |
      |   1484 | zabbix      | localhost:40008          | zabbix | Sleep       |   8144 |                                                               | NULL                                                                                                 |    0.000 |
      |  67247 | zabbix      | localhost:47262          | zabbix | Killed      |  10516 | Update                                                        | insert into history_uint (itemid,clock,ns,value) values (66915,1676576402,1,3145344),(66916,16765764 |    0.000 |
      | 413224 | zabbix      | localhost:44396          | zabbix | Killed      |  10516 | Update                                                        | insert into history_uint (itemid,clock,ns,value) values (26687,1676576404,32,7631),(26836,1676576403 |    0.000 |
      | 413226 | zabbix      | localhost:44426          | zabbix | Killed      |  10516 | Update                                                        | insert into history_uint (itemid,clock,ns,value) values (23187,1676576401,66,0),(23188,1676576401,67 |    0.000 |
      | 590933 | zabbix      | localhost:51912          | zabbix | Killed      |  10516 | Update                                                        | insert into history_uint (itemid,clock,ns,value) values (23177,1676576401,153,0),(23178,1676576401,1 |    0.000 |
      | 652992 | zabbix      | localhost:42022          | zabbix | Query       |  10516 | Statistics                                                    | SELECT itemid,COUNT(*) AS count,AVG(value) AS avg,MIN(value) AS min,MAX(value) AS max,round(500* MOD |    0.000 |
      | 652997 | zabbix      | localhost:42034          | zabbix | Query       |  10516 | Statistics                                                    | SELECT itemid,COUNT(*) AS count,AVG(value) AS avg,MIN(value) AS min,MAX(value) AS max,round(500* MOD |    0.000 |
      | 652999 | zabbix      | localhost:42046          | zabbix | Query       |  10516 | Statistics                                                    | SELECT itemid,COUNT(*) AS count,AVG(value) AS avg,MIN(value) AS min,MAX(value) AS max,round(500* MOD |    0.000 |
      | 674125 | zabbix      | localhost:52324          | zabbix | Query       |     96 | Opening tables                                                | insert into history_uint (itemid,clock,ns,value) values (66915,1676576402,1,3145344),(66916,16765764 |    0.000 |
      | 674245 | root        | localhost                | NULL   | Query       |      0 | starting                                                      | show processlist                                                                                     |    0.000 |
      | 674255 | zabbix      | localhost:53326          | zabbix | Query       |     28 | Opening tables                                                | insert into history_uint (itemid,clock,ns,value) values (26687,1676576404,32,7631),(26836,1676576403 |    0.000 |
      | 674370 | zabbix      | localhost:60396          | zabbix | Query       |     12 | Opening tables                                                | insert into history_uint (itemid,clock,ns,value) values (23177,1676576401,153,0),(23178,1676576401,1 |    0.000 |
      | 674372 | zabbix      | localhost:37496          | zabbix | Query       |      6 | Opening tables                                                | insert into history_uint (itemid,clock,ns,value) values (23187,1676576401,66,0),(23188,1676576401,67 |    0.000 |
      | 674373 | zabbix      | localhost:37508          | zabbix | Sleep       |      1 |                                                               | NULL                                                                                                 |    0.000 |
      +--------+-------------+--------------------------+--------+-------------+--------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+
      

      We did not see any message in the error log.

      A proper shutdown (-15) was NOT successful. The database did just not terminate in a decent amount of time:

      Status information:

      Current dir: /home/mysql/database/prod2/data/
      Running threads: 26  Cached threads: 7  Stack size: 299008
       
      Key caches:
      default
      Buffer_size:       2097152
      Block_size:           1024
      Division_limit:        100
      Age_threshold:         300
      Partitions:              0
      blocks used:             0
      not flushed:             0
      w_requests:              0
      writes:                  0
      r_requests:              0
      reads:                   0
       
      handler status:
      read_key:   1148401981
      read_next:  1015362765
      read_rnd     346076179
      read_first:     572208
      write:        33409058
      delete          556427
      update:         485556
       
      Table status:
      Opened tables:        973
      Open tables:          789
      Open files:            65
      Open streams:           4
       
      Alarm status:
      Active alarms:   0
      Max used alarms: 0
      Next alarm time: 0
       
      Memory status:
      Non-mmapped space allocated from system: 276168704
      Number of free chunks:                   2878
      Number of fastbin blocks:                136
      Number of mmapped regions:               58
      Space in mmapped regions:                538791936
      Maximum total allocated space:           0
      Space available in freed fastbin blocks: 9552
      Total allocated space:                   99193792
      Total free space:                        176974912
      Top-most, releasable space:              58768
      Estimated memory (with thread stack):    824827904
      Global memory allocated by server:       59489400
      Memory allocated by threads:             4525024
       
      Events status:
      LLA = Last Locked At  LUA = Last Unlocked At
      WOC = Waiting On Condition  DL = Data Locked
       
      Event scheduler status:
      State      : INITIALIZED
      Thread id  : 0
      LLA        : stop:638
      LUA        : stop:688
      WOC        : NO
      Workers    : 0
      Executed   : 0
      Data locked: NO
       
      Event queue status:
      Element count   : 0
      Data locked     : NO
      Attempting lock : NO
      LLA             : drop_schema_events:393
      LUA             : drop_schema_events:395
      WOC             : NO
      Next activation : never
      2023-02-16 23:38:16 0 [Note] bin/mysqld (initiated by: unknown): Normal shutdown
      2023-02-16 23:38:16 6 [Note] Error reading relay log event: slave SQL thread was killed
      2023-02-16 23:38:16 6 [Note] Slave SQL thread exiting, replication stopped in log 'prod1_binlog.002843' at position 32730719, master: 116.203.122.76:33006
      2023-02-16 23:38:16 5 [Note] Slave I/O thread exiting, read up to log 'prod1_binlog.002843', position 32730719, master 116.203.122.76:33006
      2023-02-16 23:38:36 0 [Warning] bin/mysqld: Thread 674372 (user : 'zabbix') did not exit
      2023-02-16 23:38:36 0 [Warning] bin/mysqld: Thread 674370 (user : 'zabbix') did not exit
      2023-02-16 23:38:36 0 [Warning] bin/mysqld: Thread 674255 (user : 'zabbix') did not exit
      2023-02-16 23:38:36 0 [Warning] bin/mysqld: Thread 674125 (user : 'zabbix') did not exit
      2023-02-16 23:38:36 0 [Warning] bin/mysqld: Thread 652999 (user : 'zabbix') did not exit
      2023-02-16 23:38:36 0 [Warning] bin/mysqld: Thread 652997 (user : 'zabbix') did not exit
      2023-02-16 23:38:36 0 [Warning] bin/mysqld: Thread 652992 (user : 'zabbix') did not exit
      2023-02-16 23:38:36 0 [Warning] bin/mysqld: Thread 590933 (user : 'zabbix') did not exit
      2023-02-16 23:38:36 0 [Warning] bin/mysqld: Thread 413226 (user : 'zabbix') did not exit
      2023-02-16 23:38:36 0 [Warning] bin/mysqld: Thread 413224 (user : 'zabbix') did not exit
      2023-02-16 23:38:36 0 [Warning] bin/mysqld: Thread 67247 (user : 'zabbix') did not exit
      

      Kill -9 helped.
      Start of the DB shows 7 transactions rolled back:

      2023-02-16 23:42:15 0 [Note] Starting MariaDB 10.6.12-MariaDB-log source revision 4c79e15cc3716f69c044d4287ad2160da8101cdc as process 2319572
      2023-02-16 23:42:15 0 [Note] mysqld: Aria engine: starting recovery
      tables to flush: 3 2 1 0
       (0.0 seconds); 
      2023-02-16 23:42:15 0 [Note] mysqld: Aria engine: recovery done
      2023-02-16 23:42:15 0 [Note] InnoDB: Compressed tables use zlib 1.2.12
      2023-02-16 23:42:15 0 [Note] InnoDB: Number of pools: 1
      2023-02-16 23:42:15 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
      2023-02-16 23:42:15 0 [Note] InnoDB: Using Linux native AIO
      2023-02-16 23:42:15 0 [Note] InnoDB: Initializing buffer pool, total size = 25769803776, chunk size = 134217728
      2023-02-16 23:42:15 0 [Note] InnoDB: Completed initialization of buffer pool
      2023-02-16 23:42:15 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=37225590795933,37225598153720
      2023-02-16 23:42:20 0 [Note] InnoDB: 8 transaction(s) which must be rolled back or cleaned up in total 2381 row operations to undo
      2023-02-16 23:42:20 0 [Note] InnoDB: Trx id counter is 6897314056
      2023-02-16 23:42:20 0 [Note] InnoDB: Starting final batch to recover 22118 pages from redo log.
      2023-02-16 23:42:21 0 [Note] InnoDB: Last binlog file '/home/mysql/database/prod2/binlog/prod2_binlog.002865', position 127260559
      2023-02-16 23:42:21 0 [Note] InnoDB: 128 rollback segments are active.
      2023-02-16 23:42:21 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
      2023-02-16 23:42:21 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
      2023-02-16 23:42:21 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      2023-02-16 23:42:21 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      2023-02-16 23:42:21 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
      2023-02-16 23:42:21 0 [Note] InnoDB: 10.6.12 started; log sequence number 37225787347580; transaction id 6897314057
      2023-02-16 23:42:21 0 [Note] InnoDB: Loading buffer pool(s) from /home/mysql/database/prod2/data/ib_buffer_pool
      2023-02-16 23:42:21 0 [Note] Plugin 'FEEDBACK' is disabled.
      2023-02-16 23:42:21 0 [Note] InnoDB: Rolled back recovered transaction 6897313229
      2023-02-16 23:42:21 0 [Note] Loaded 'metadata_lock_info.so' with offset 0x7f21d41fd000
      2023-02-16 23:42:21 0 [Note] Recovering after a crash using /home/mysql/database/prod2/binlog/prod2_binlog
      2023-02-16 23:42:21 0 [Note] Starting table crash recovery...
      2023-02-16 23:42:21 0 [Note] Crash table recovery finished.
      2023-02-16 23:42:21 0 [Note] Server socket created on IP: '0.0.0.0'.
      2023-02-16 23:42:21 0 [Note] Server socket created on IP: '::'.
      2023-02-16 23:42:21 0 [Note] Reading of all Master_info entries succeeded
      2023-02-16 23:42:21 0 [Note] Added new Master_info '' to hash table
      2023-02-16 23:42:21 5 [Note] Slave I/O thread: Start asynchronous replication to master 'replication@116.203.122.76:33006' in log 'prod1_binlog.002843' at position 32730719
      2023-02-16 23:42:21 0 [Note] bin/mysqld: ready for connections.
      Version: '10.6.12-MariaDB-log'  socket: '/var/run/mysqld/mysql-33006.sock'  port: 33006  MariaDB Server
      2023-02-16 23:42:21 6 [Note] Slave SQL thread initialized, starting replication in log 'prod1_binlog.002843' at position 32730719, relay log './prod2-relay-log.006987' position: 508
      2023-02-16 23:42:21 5 [Note] Slave I/O thread: connected to master 'replication@116.203.122.76:33006',replication started in log 'prod1_binlog.002843' at position 32730719
      2023-02-16 23:42:21 0 [Note] InnoDB: Rolled back recovered transaction 6897313491
      2023-02-16 23:42:21 0 [Note] InnoDB: Rolled back recovered transaction 6897312943
      2023-02-16 23:42:21 8 [Warning] Aborted connection 8 to db: 'unconnected' user: 'unauthenticated' host: 'localhost' (This connection closed normally without authentication)
      2023-02-16 23:42:21 0 [Note] InnoDB: Rolled back recovered transaction 6897265003
      2023-02-16 23:42:22 0 [Note] InnoDB: Rolled back recovered transaction 6897313487
      2023-02-16 23:42:22 0 [Note] InnoDB: Rolled back recovered transaction 6897265005
      2023-02-16 23:42:22 0 [Note] InnoDB: Rolled back recovered transaction 6897265007
      2023-02-16 23:42:22 0 [Note] InnoDB: Rolled back recovered transaction 6897265039
      2023-02-16 23:42:22 0 [Note] InnoDB: Rollback of non-prepared transactions completed
      2023-02-16 23:42:28 0 [Note] InnoDB: Buffer pool(s) load completed at 230216 23:42:28
      

      Please let me know what I should gather as information if it happens the next time...

      Attachments

        1. mdev_30665_1.tar.gz
          51 kB
          Oli Sennhauser
        2. test_backtrace.trc
          23 kB
          Oli Sennhauser

        Issue Links

          Activity

            People

              marko Marko Mäkelä
              oli Oli Sennhauser
              Votes:
              0 Vote for this issue
              Watchers:
              9 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.