-1

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'
  • You have provided no further information for us in this post than your last. Can you rule out that you aren't still trying to start mysql when it is already running? FYI you aren't even killing it properly. If the process is not responding to a sigterm, your syntax for trying to send a sigkill is incorrect. If you must use killall, it would be "killall -s SIGKILL mysqld". – Peter Dec 7 '14 at 3:52
  • "You have provided no further information for us in this post than your last." I don't follow, my last post was an assertion error, that led to me dumping and restoring the DB. Different, and fixed, issue. This has been marked duplicate by a handful of people but the post referenced is not the same as this at all, I'm unsure as to what I'm missing. The last line is very helpful, although, as of this morning I don't seem to be having the issue. – Tim Dec 7 '14 at 17:10
  • You really should do a full dump and reload. – Michael Hampton Dec 7 '14 at 21:01
  • @MichaelHampton Surprisingly, this is actually just after doing a full dump and reload yesterday to resolve an assertion error. With that said, the dump had to be done from recovery mode. Should I do a dump and reload now that I can access it without recovery mode? Would that make a difference? – Tim Dec 7 '14 at 21:30
1

This log entry is the key to the most likely issue:

141207 20:50:34 mysqld_safe Number of processes running now: 0

If there is not an extremely verbose block of log messages, including a stack trace, immediately before this line, then MySQL's not actually crashing... the kernel is killing it because another process (such as the web server) is making aggressive demands on the system for memory. In a desperate attempt to relieve the pressure and avoid what is an impending system-wide crash or lock-up, the kernel goes scouting for a process to kill.

$ cat /var/log/messages | egrep -i 'mysql|oom|kernel'

Follow the trail from syslog. You will most likely need to reign in your web server.

Everything after the log entry above is just MySQL trying to restart itself and recover from being killed. In a case of severe memory shortage, it will fail to restart right away, because there's simply not enough system memory available:

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

In Linux, Error 12 is indeed "out of memory." And, again, that's not MySQL saying it's out of memory, that's the kernel.


Also noteworthy, 5,368,725,504 bytes seems like a very large buffer pool for an 8GB server, unless the server is doing nothing other than running MySQL. A subjective rule of thumb for shared workloads is to allocate not more than 50% of system memory for the buffer pool.

The amount of memory you allocate, here, is claimed and held by MySQL and unavailable for other processes. Generally, with this particular parameter, bigger is better... but only within reason based on available resources.

  • Ah, I figured that the last part was just mysql trying to restart itself. It turns out that for a bit it was maxing memory causing the system to kill it (turned up in messages). Although, even after that was fixed it still would die without leaving a log anywhere. I really appreciated that added info in troubleshooting - that's what I'm really trying to learn more about, so I come to the good people of ServerFault with better intel. I did wind up knocking the buffer pool donw to 4Gb, just for good measure. – Tim Dec 8 '14 at 21:12

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.