MySQL Crashes frequently

Peter Laws

Verified User
Joined
Sep 13, 2008
Messages
1,755
Location
London UK
I'm not sure what is going on here... This is an OpenVZ 6 CT that has been running flawlessly for years, however, two days ago MySQL started to crash/restart at random intervals. A client mucked up their wordpress database, so I reimported a .sql backup via phpmyadmin.... This is when this weird situation started to happen....

I thought it was a memory/vswap issue, however, a reboot of the CT didn't help, MySQL crashed three hours later...

Here's some of the log
Code:
2019-08-24 06:37:07 2076 [Note] IPv6 is available.2019-08-24 06:37:07 2076 [Note]   - '::' resolves to '::';
2019-08-24 06:37:07 2076 [Note] Server socket created on IP: '::'.
2019-08-24 06:37:07 2076 [Warning] 'user' entry 'root@xxxxxxxxx' ignored in --skip-name-resolve mode.
2019-08-24 06:37:07 2076 [Warning] 'user' entry '@xxxxxxxxxxx' ignored in --skip-name-resolve mode.
2019-08-24 06:37:07 2076 [Warning] 'proxies_priv' entry '@ root@xxxxxxx' ignored in --skip-name-resolve mode.
2019-08-24 06:37:07 2076 [Note] Event Scheduler: Loaded 0 events
2019-08-24 06:37:07 2076 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.6.12'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
190824 08:55:03 mysqld_safe Number of processes running now: 0
190824 08:55:03 mysqld_safe mysqld restarted
2019-08-24 08:55:04 15986 [Warning] You need to use --log-bin to make --binlog-format work.
2019-08-24 08:55:05 15986 [Note] Plugin 'FEDERATED' is disabled.
2019-08-24 08:55:05 15986 [Note] InnoDB: The InnoDB memory heap is disabled
2019-08-24 08:55:05 15986 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-08-24 08:55:05 15986 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-08-24 08:55:05 15986 [Note] InnoDB: Using Linux native AIO
2019-08-24 08:55:05 15986 [Note] InnoDB: Using CPU crc32 instructions
2019-08-24 08:55:05 15986 [Note] InnoDB: Initializing buffer pool, size = 6.0G
2019-08-24 08:55:10 15986 [Note] InnoDB: Completed initialization of buffer pool
2019-08-24 08:55:10 15986 [Note] InnoDB: Highest supported file format is Barracuda.
2019-08-24 08:55:11 15986 [Note] InnoDB: The log sequence numbers 1150586314715 and 1150586314715 in ibdata files do not match the log sequence number 1150587701549 in the ib_logfiles!
2019-08-24 08:55:11 15986 [Note] InnoDB: Database was not shutdown normally!
2019-08-24 08:55:11 15986 [Note] InnoDB: Starting crash recovery.
2019-08-24 08:55:11 15986 [Note] InnoDB: Reading tablespace information from the .ibd files...
2019-08-24 08:55:11 15986 [Note] InnoDB: Restoring possible half-written data pages
2019-08-24 08:55:11 15986 [Note] InnoDB: from the doublewrite buffer...
190824 08:55:12 mysqld_safe mysqld from pid file /usr/local/mysql/data/server5.pid ended
190824 08:56:05 mysqld_safe Starting mysqld daemon with databases from /usr/local/mysql/data
2019-08-24 08:56:05 16983 [Warning] You need to use --log-bin to make --binlog-format work.
2019-08-24 08:56:05 16983 [Note] Plugin 'FEDERATED' is disabled.
2019-08-24 08:56:05 16983 [Note] InnoDB: The InnoDB memory heap is disabled
2019-08-24 08:56:05 16983 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-08-24 08:56:05 16983 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-08-24 08:56:05 16983 [Note] InnoDB: Using Linux native AIO
2019-08-24 08:56:05 16983 [Note] InnoDB: Using CPU crc32 instructions
2019-08-24 08:56:05 16983 [Note] InnoDB: Initializing buffer pool, size = 6.0G
2019-08-24 08:56:07 16983 [Note] InnoDB: Completed initialization of buffer pool
2019-08-24 08:56:07 16983 [Note] InnoDB: Highest supported file format is Barracuda.
190824 08:56:07 mysqld_safe mysqld from pid file /usr/local/mysql/data/server5.pid ended
190824 08:57:02 mysqld_safe Starting mysqld daemon with databases from /usr/local/mysql/data
2019-08-24 08:57:02 18084 [Warning] You need to use --log-bin to make --binlog-format work.
2019-08-24 08:57:02 18084 [Note] Plugin 'FEDERATED' is disabled.
2019-08-24 08:57:02 18084 [Note] InnoDB: The InnoDB memory heap is disabled
2019-08-24 08:57:02 18084 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-08-24 08:57:02 18084 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-08-24 08:57:02 18084 [Note] InnoDB: Using Linux native AIO
2019-08-24 08:57:02 18084 [Note] InnoDB: Using CPU crc32 instructions
2019-08-24 08:57:02 18084 [Note] InnoDB: Initializing buffer pool, size = 6.0G
2019-08-24 08:57:04 18084 [Note] InnoDB: Completed initialization of buffer pool
2019-08-24 08:57:04 18084 [Note] InnoDB: Highest supported file format is Barracuda.
190824 08:57:05 mysqld_safe mysqld from pid file /usr/local/mysql/data/server5.pid ended
190824 08:57:17 mysqld_safe Starting mysqld daemon with databases from /usr/local/mysql/data
2019-08-24 08:57:18 18944 [Warning] You need to use --log-bin to make --binlog-format work.
2019-08-24 08:57:18 18944 [Note] Plugin 'FEDERATED' is disabled.
2019-08-24 08:57:18 18944 [Note] InnoDB: The InnoDB memory heap is disabled
2019-08-24 08:57:18 18944 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-08-24 08:57:18 18944 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-08-24 08:57:18 18944 [Note] InnoDB: Using Linux native AIO
2019-08-24 08:57:18 18944 [Note] InnoDB: Using CPU crc32 instructions
2019-08-24 08:57:18 18944 [Note] InnoDB: Initializing buffer pool, size = 6.0G
2019-08-24 08:57:19 18944 [Note] InnoDB: Completed initialization of buffer pool
2019-08-24 08:57:19 18944 [Note] InnoDB: Highest supported file format is Barracuda.
190824 08:57:19 mysqld_safe mysqld from pid file /usr/local/mysql/data/server5.pid ended
190824 08:58:05 mysqld_safe Starting mysqld daemon with databases from /usr/local/mysql/data
2019-08-24 08:58:06 19878 [Warning] You need to use --log-bin to make --binlog-format work.
2019-08-24 08:58:06 19878 [Note] Plugin 'FEDERATED' is disabled.
2019-08-24 08:58:06 19878 [Note] InnoDB: The InnoDB memory heap is disabled
2019-08-24 08:58:06 19878 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-08-24 08:58:06 19878 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-08-24 08:58:06 19878 [Note] InnoDB: Using Linux native AIO
2019-08-24 08:58:06 19878 [Note] InnoDB: Using CPU crc32 instructions
2019-08-24 08:58:06 19878 [Note] InnoDB: Initializing buffer pool, size = 6.0G
190824 08:58:08 mysqld_safe mysqld from pid file /usr/local/mysql/data/server5.pid ended
190824 08:59:05 mysqld_safe Starting mysqld daemon with databases from /usr/local/mysql/data
2019-08-24 08:59:05 20907 [Warning] You need to use --log-bin to make --binlog-format work.
2019-08-24 08:59:05 20907 [Note] Plugin 'FEDERATED' is disabled.
2019-08-24 08:59:05 20907 [Note] InnoDB: The InnoDB memory heap is disabled
2019-08-24 08:59:05 20907 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-08-24 08:59:05 20907 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-08-24 08:59:05 20907 [Note] InnoDB: Using Linux native AIO
2019-08-24 08:59:05 20907 [Note] InnoDB: Using CPU crc32 instructions
2019-08-24 08:59:05 20907 [Note] InnoDB: Initializing buffer pool, size = 6.0G
2019-08-24 08:59:06 20907 [Note] InnoDB: Completed initialization of buffer pool
2019-08-24 08:59:06 20907 [Note] InnoDB: Highest supported file format is Barracuda.
190824 08:59:07 mysqld_safe mysqld from pid file /usr/local/mysql/data/server5.pid ended
190824 09:00:03 mysqld_safe Starting mysqld daemon with databases from /usr/local/mysql/data
2019-08-24 09:00:03 22083 [Warning] You need to use --log-bin to make --binlog-format work.
2019-08-24 09:00:03 22083 [Note] Plugin 'FEDERATED' is disabled.
2019-08-24 09:00:03 22083 [Note] InnoDB: The InnoDB memory heap is disabled
2019-08-24 09:00:03 22083 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-08-24 09:00:03 22083 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-08-24 09:00:03 22083 [Note] InnoDB: Using Linux native AIO
2019-08-24 09:00:03 22083 [Note] InnoDB: Using CPU crc32 instructions
2019-08-24 09:00:03 22083 [Note] InnoDB: Initializing buffer pool, size = 6.0G
2019-08-24 09:00:04 22083 [Note] InnoDB: Completed initialization of buffer pool
2019-08-24 09:00:04 22083 [Note] InnoDB: Highest supported file format is Barracuda.
2019-08-24 09:00:04 22083 [Note] InnoDB: The log sequence numbers 1150586314715 and 1150586314715 in ibdata files do not match the log sequence number 1150587701549 in the ib_logfiles!
2019-08-24 09:00:04 22083 [Note] InnoDB: Database was not shutdown normally!
2019-08-24 09:00:04 22083 [Note] InnoDB: Starting crash recovery.
2019-08-24 09:00:04 22083 [Note] InnoDB: Reading tablespace information from the .ibd files...
2019-08-24 09:00:05 22083 [Note] InnoDB: Restoring possible half-written data pages
2019-08-24 09:00:05 22083 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Last MySQL binlog file position 0 641159340, file name mysql-bin.000364
2019-08-24 09:00:06 22083 [Note] InnoDB: 128 rollback segment(s) are active.
2019-08-24 09:00:06 22083 [Note] InnoDB: Waiting for purge to start
2019-08-24 09:00:06 22083 [Note] InnoDB: 5.6.12 started; log sequence number 1150587701549
2019-08-24 09:00:06 22083 [Note] Server hostname (bind-address): '*'; port: 3306
2019-08-24 09:00:06 22083 [Note] IPv6 is available.
2019-08-24 09:00:06 22083 [Note]   - '::' resolves to '::';
2019-08-24 09:00:06 22083 [Note] Server socket created on IP: '::'.
2019-08-24 09:00:06 22083 [Warning] 'user' entry 'root@xxxxxxxs' ignored in --skip-name-resolve mode.
2019-08-24 09:00:06 22083 [Warning] 'user' entry '@xxxxxxxx' ignored in --skip-name-resolve mode.
2019-08-24 09:00:06 22083 [Warning] 'proxies_priv' entry '@ root@xxxxxxxxx' ignored in --skip-name-resolve mode.
2019-08-24 09:00:06 22083 [Note] Event Scheduler: Loaded 0 events
2019-08-24 09:00:06 22083 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.6.12'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
Any ideas of what is going on? And to debug further?
 

Peter Laws

Verified User
Joined
Sep 13, 2008
Messages
1,755
Location
London UK
Most are InnoDB these days.......

Now, I really think it could be php-fpm, I know the size in DA's Services section isn't a reflect on real memory, but most of the time, the processes grow and grow..... Leading to show 14Gig, whereas the CT only has 12Gb memory, and 2Gb vSwap...... Yes, it's a busy CT, but it's been ok (well, load is high with 4 vCores) for years...... Maybe the client's sites visits are now too big for the CT now.

What is interesting, when MySQL crashes, sometimes it doesn't come back up. However, once I restart the php-fpm processes, MySQL instantly comes back up.

Like I say, I only noticed this behaviour a few hours after I imported back a backup database.
 
Last edited:
Top