0

I am running the Percona version of MySQL Server v5.6 and every few days the MySQL seems to crash and then automatically restart itself. How can I work out what the reason is for the crash? I've seen other people with MySQL stopping unexpectedly and it seems to be down to memory problems but in their cases the error log mentions this. In my case I don't have anything appearing in the log file until it's actually restarting.

I'm including the relevant log file below with the last "expected" error and then what it is logging when MySQL is restarting. It consists of various "Unsafe statement written to the binary log" warnings prior to the crash but I don't think they are the reason for the crash. (I will shortly update the statements to not use the ON DUPLICATE KEY construct to stop them to stop the log from filling up. I should also mention that I don't do replication which is why I don't think they are too important at the moment.)

The server is a 64 bit Centos 6.6 running on a virtual machine (Virtuozzo).

Hopefully someone can point me in the right direction to determine what's causing the crash. Thanks!

Log file below:

2018-03-19 08:39:51 21476 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. INSERT... ON DUPLICATE KEY UPDATE  on a table with more than one UNIQUE KEY is unsafe Statement: INSERT INTO xxxx ON DUPLICATE KEY UPDATE xxxx
180319 08:39:52 mysqld_safe Number of processes running now: 0
180319 08:39:52 mysqld_safe mysqld restarted
2018-03-19 08:39:53 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-03-19 08:39:53 20217 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
2018-03-19 08:39:53 20217 [Note] Plugin 'FEDERATED' is disabled.
2018-03-19 08:39:53 20217 [Note] InnoDB: Using atomics to ref count buffer pool pages
2018-03-19 08:39:53 20217 [Note] InnoDB: The InnoDB memory heap is disabled
2018-03-19 08:39:53 20217 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-03-19 08:39:53 20217 [Note] InnoDB: Memory barrier is not used
2018-03-19 08:39:53 20217 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-03-19 08:39:53 20217 [Note] InnoDB: Using Linux native AIO
2018-03-19 08:39:53 20217 [Note] InnoDB: Using CPU crc32 instructions
2018-03-19 08:39:53 20217 [Note] InnoDB: Initializing buffer pool, size = 3.0G
2018-03-19 08:39:54 20217 [Note] InnoDB: Completed initialization of buffer pool
2018-03-19 08:39:54 20217 [Note] InnoDB: Highest supported file format is Barracuda.
2018-03-19 08:39:54 20217 [Note] InnoDB: Log scan progressed past the checkpoint lsn 123717382274
2018-03-19 08:39:54 20217 [Note] InnoDB: Database was not shutdown normally!
2018-03-19 08:39:54 20217 [Note] InnoDB: Starting crash recovery.
2018-03-19 08:39:54 20217 [Note] InnoDB: Reading tablespace information from the .ibd files...
2018-03-19 08:39:54 20217 [Note] InnoDB: Restoring possible half-written data pages
2018-03-19 08:39:54 20217 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 123717811056
InnoDB: Transaction 790235434 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 790235904
2018-03-19 08:39:55 20217 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 7
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 697177863, file name mysql-bin.000227
InnoDB: Starting in background the rollback of uncommitted transactions
2018-03-19 08:39:56 20217 [Note] InnoDB: 128 rollback segment(s) are active.
2018-03-19 08:39:56 7f481bd03700  InnoDB: Rollback of non-prepared transactions completed
2018-03-19 08:39:56 20217 [Note] InnoDB: Waiting for purge to start
2018-03-19 08:39:56 20217 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.22-71.0 started; log sequence number 123717811056
2018-03-19 08:39:56 20217 [Note] Recovering after a crash using /var/lib/mysql/mysql-bin
2018-03-19 08:46:36 20217 [Note] Starting crash recovery...
2018-03-19 08:46:36 7f491ce677e0  InnoDB: Starting recovery for XA transactions...
2018-03-19 08:46:36 7f491ce677e0  InnoDB: Transaction 790235434 in prepared state after recovery
2018-03-19 08:46:36 7f491ce677e0  InnoDB: Transaction contains changes to 1 rows
2018-03-19 08:46:36 7f491ce677e0  InnoDB: 1 transactions in prepared state after recovery
2018-03-19 08:46:36 20217 [Note] Found 1 prepared transaction(s) in InnoDB
2018-03-19 08:46:36 20217 [Note] Crash recovery finished.
2018-03-19 08:46:36 20217 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2018-03-19 08:46:36 20217 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
2018-03-19 08:46:36 20217 [Note] Server hostname (bind-address): '*'; port: 3306
2018-03-19 08:46:36 20217 [Note] IPv6 is available.
2018-03-19 08:46:36 20217 [Note]   - '::' resolves to '::';
2018-03-19 08:46:36 20217 [Note] Server socket created on IP: '::'.
2018-03-19 08:46:37 20217 [Note] Event Scheduler: Loaded 0 events
2018-03-19 08:46:37 20217 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.22-71.0-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Percona Server (GPL), Release 71.0, Revision 726
2018-03-19 08:46:38 20217 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. INSERT... ON DUPLICATE KEY UPDATE  on a table with more than one UNIQUE KEY is unsafe Statement: INSERT INTO xxxx ON DUPLICATE KEY UPDATE xxxx

Edit: As per @impimp's question in the comments, here is the content of /var/log/messages

Mar 18 04:02:22 HOSTNAME rsyslogd: [origin software="rsyslogd" swVersion="5.8.10" x-pid="474" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Mar 19 08:39:52 HOSTNAME kernel: [103311785.405884] Out of memory in UB 650543: OOM killed process 21476 (mysqld) score 0 vm:6363484kB, rss:4024500kB, swap:45536kB
Mar 20 09:17:35 HOSTNAME kernel: [103400050.711461] Out of memory in UB 650543: OOM killed process 20217 (mysqld) score 0 vm:6382720kB, rss:4066652kB, swap:0kB
Andy Castles
  • 98
  • 1
  • 9
  • 1
    could you please check in dmesg if your MySQL instance wasn't killed by kernel's OOM Killer? How many memory you have available on your server? – impimp Mar 19 '18 at 16:39
  • There are a couple of posts here that go through getting the information needed to diagnose. The version you have there is pretty old too: you'd need to upgrade it to see if the problem still occurs in the latest 5.6 version - current is 5.6.39-83.1 - before logging a bug report. https://www.percona.com/blog/2015/08/11/mysql-qa-episode-12-server-crashing-now-customers-users-experiencing-crash/ https://www.percona.com/blog/2015/08/17/mysql-is-crashing-a-support-engineers-point-of-view/ – greenweeds Mar 19 '18 at 18:09
  • Thanks @impimp, I've editted the question to add in information about dmesg, it looks like OOM is the problem. The server has 6GB of memory with mysqld using 3.9GB. According to `free`the server has 1GB free, but I'm assuming that the memory use increases during higher load and then the process gets killed. Is this just a case of changing the memory allowances in my.cnf then? – Andy Castles Mar 21 '18 at 09:46
  • Thanks @percona-lorraine, those two links look useful. I'll see if I can update to the latest version, however in this case it looks like the kernel is killing it due to lack of memory. – Andy Castles Mar 21 '18 at 09:49
  • @impimp If you could write a short answer simply saying to check if the instance was called by the OOM killer then I'll mark it as the accepted answer. I'd prefer to leave this question with an answer rather than seeminly unanswered when you actually came up with the answer immediately. Thanks! – Andy Castles Apr 26 '18 at 08:32

0 Answers0