My server seems to crash/restart under a load that would not have previously made it crash.
How can I troubleshoot this?
VPS is running Centos 6.x, 8GB ram
- Mysql is crashing/restarting itself under loads that would not have previously done it in.
- This error:
InnoDB: Unable to lock ./ibdata1, error: 11
pops up in the log after the crash. Could this simply be from mysql recovering from a crash and trying to restart while it hasn't fully died?
I'm not sure if any of this is related to the crashing, as it shows during the database trying to restart itself. Quite a few lines of:
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
The log then proceeds with:
141207 18:58:06 [ERROR] Plugin 'InnoDB' init function returned error.
141207 18:58:06 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
141207 18:58:06 [ERROR] Failed to initialize plugins.
141207 18:58:06 [ERROR] Aborting
141207 18:58:06 [Note] /usr/libexec/mysqld: Shutdown complete
141207 18:58:06 mysqld_safe Number of processes running now: 1
141207 18:58:06 mysqld_safe mysqld process hanging, pid 15456 - killed
141207 18:58:06 mysqld_safe mysqld restarted
141207 18:58:06 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
141207 18:58:06 InnoDB: Initializing buffer pool, size = 6.0G
141207 18:58:06 InnoDB: Completed initialization of buffer pool
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
141207 18:58:06 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Last MySQL binlog file position 0 14626, file name /var/lib/mysql/mysql-bin.000892
141207 18:58:06 InnoDB: Started; log sequence number 3 2358701171
141207 18:58:06 [Note] Recovering after a crash using /var/lib/mysql/mysql-bin
141207 18:58:06 [Note] Starting crash recovery...
141207 18:58:06 [Note] Crash recovery finished.
141207 18:58:06 [Note] Event Scheduler: Loaded 0 events
141207 18:58:06 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.1.73-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 Source distribution
There doesn't seem to be much information leading to a cause of why mysql is now so weak. Considering no my.cnf changes or otherwise have been made, I don't think it's a configuration issue.
Where should I be looking to get better data on this issue? Or is there a more 'hard' reset of sorts I can do to get things back to normal?
EDIT - Latest from the logs
Cleaned up my log files and restarted the server before running a load that it is currently crashing for (that it could previously handle just fine.)
Here is the latest output from the log file, everything from after the restart I performed before running the task. As far as I can tell, nothing that clues into the reason for the crash, correct?
141207 20:50:34 mysqld_safe Number of processes running now: 0
141207 20:50:34 mysqld_safe mysqld restarted
141207 20:50:35 InnoDB: Initializing buffer pool, size = 5.0G
141207 20:50:35 InnoDB: Error: cannot allocate 5368725504 bytes of
InnoDB: memory with malloc! Total allocated memory
InnoDB: by InnoDB 36878736 bytes. Operating system errno: 12
InnoDB: Check if you should increase the swap file or
InnoDB: ulimits of your operating system.
InnoDB: On FreeBSD check you have compiled the OS with
InnoDB: a big enough maximum process size.
InnoDB: Note that in most 32-bit computers the process
InnoDB: memory space is limited to 2 GB or 4 GB.
InnoDB: We keep retrying the allocation for 60 seconds...
141207 20:50:49 InnoDB: Completed initialization of buffer pool
InnoDB: Log scan progressed past the checkpoint lsn 3 2681111025
141207 20:50:49 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 3 2686353408
InnoDB: Doing recovery: scanned up to log sequence number 3 2691596288
InnoDB: Doing recovery: scanned up to log sequence number 3 2696839168
InnoDB: Doing recovery: scanned up to log sequence number 3 2702082048
InnoDB: Doing recovery: scanned up to log sequence number 3 2707324928
InnoDB: Doing recovery: scanned up to log sequence number 3 2712567808
InnoDB: Doing recovery: scanned up to log sequence number 3 2717810688
InnoDB: Doing recovery: scanned up to log sequence number 3 2723053568
InnoDB: Doing recovery: scanned up to log sequence number 3 2728296448
InnoDB: Doing recovery: scanned up to log sequence number 3 2733539328
InnoDB: Doing recovery: scanned up to log sequence number 3 2738782208
InnoDB: Doing recovery: scanned up to log sequence number 3 2739356250
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 237115 row operations to undo
InnoDB: Trx id counter is 0 15792384
141207 20:50:50 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 157660, file name /var/lib/mysql/mysql-bin.000902
InnoDB: Starting in background the rollback of uncommitted transactions
141207 20:51:07 InnoDB: Rolling back trx with id 0 15789484, 237115 rows to undo
InnoDB: Progress in percents: 1141207 20:51:07 InnoDB: Started; log sequence number 3 2739356250
141207 20:51:07 [Note] Recovering after a crash using /var/lib/mysql/mysql-bin
141207 20:51:07 [Note] Starting crash recovery...
141207 20:51:07 [Note] Crash recovery finished.
2 3 4141207 20:51:07 [Note] Event Scheduler: Loaded 0 events
141207 20:51:07 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.1.73-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 Source distribution
5 6 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 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
InnoDB: Rolling back of trx id 0 15789484 completed
141207 20:51:11 InnoDB: Rollback of non-prepared transactions completed
141207 20:51:20 [ERROR] /usr/libexec/mysqld: Table './bck_wpdb/bck_statpress' is marked as crashed and should be repaired
141207 20:51:20 [Warning] Checking table: './bck_wpdb/bck_statpress'
141207 20:52:19 [ERROR] /usr/libexec/mysqld: Table './mdi_db1/mdi_statpress' is marked as crashed and should be repaired
141207 20:52:19 [Warning] Checking table: './mdi_db1/mdi_statpress'