Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Duplicate
-
10.6.12
-
Ubuntu 20.04, n.a.
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
Issue Links
- duplicates
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-