Skip to content

Easy Fix: Mysql InnoDB: Database was not shut down normally

by Paul Kenjora on February 1st, 2008

Sometime last week I noticed that my Django powered sites were returning “Internal Server Errors” about 3 times a day at random intervals. A bit of investigation and I noticed that MySQL was down and hence Django was barfing. I looked at the logs and there were no errors except that MySQL/InnoDB was restarting periodically with warnings. I did what any Django developer would do, I restarted the server 3 times a day. That got old…

What I saw in the MySQL logs…

I saw a InnoDB malloc error early on in the logs and I corrected the problem by limiting my queries. Yes I’m crunching that much data. We can have a whole separate discussion on this later…


Number of processes running now: 0
080128 08:51:17 mysqld restarted
080128 8:51:20 InnoDB: Error: cannot allocate 8404992 bytes of
InnoDB: memory with malloc! Total allocated memory
InnoDB: by InnoDB 6359288 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...
080128 8:52:34 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...
080128 8:52:35 InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 43675.
InnoDB: Doing recovery: scanned up to log sequence number 0 43675
080128 8:52:36 InnoDB: Started; log sequence number 0 43675
080128 8:52:39 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.0.27' socket: '/var/lib/mysql/mysql.sock' port: 3306 Source distribution


Unfortunately I still received the "InnoDB: Database was not shut down normally" error quite consistently. By the way, turning off InnoDB in "my.cnf" had no effect. I do not recommend messing with that file anyway, unless you know what you are doing. So InnoDB was the issue but I did not know how to fix it…


Number of processes running now: 0
080128 08:53:47 mysqld restarted
080128 8:53:51 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...
080128 8:53:52 InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 43675.
InnoDB: Doing recovery: scanned up to log sequence number 0 43675
080128 8:53:52 InnoDB: Started; log sequence number 0 43675
080128 8:53:54 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.0.27' socket: '/var/lib/mysql/mysql.sock' port: 3306 Source distribution


Fixing InnoDB

After sitting down and burning all night on InnoDB error searches across Google I decided to call around. I was lucky enough to talk with one of the founders of Help Me Sue, also a Django application. After describing the problem he suggested I reset the InnoDB read/write logs by dumping the DB to text and importing it back in. I gave it a try:


mysqldump db_name > backup-file.sql

mysql
drop database db_name;
create database db_name;

mysql db_name < backup-file.sql


That did the trick. Since then I have not had any InnoDB problems. I guess the malloc error messed up the read/write logs and MySQL could never get them quite right again. So for all the Django developers out there, don't waste time learning MySQL configuration details, just dump your database and import it back. Hope this saves someone somewhere some time. A special thanks to the founders at Help Me Sue.

More from Aware Labs

Aware Labs Recommends

AwareLabs has content marketing with Arkayne Socialize.

From → Environment Setup, Tutorial

  • karan123
    Hi

    My application is using a MySqL InnoDB engine via mysqlclient lib. i want to know could in any scenerio mySQL allow me to connect but my queries fail because of any reason. Could it be that the tables are bening rebuilded while my appl queries and can they fail

    TIA
    Karan
  • As it turns out I had to re-do my entire DB. THe problem came back a few days later. I think this was being caused by some mis-matched keys. I did a manual delete of a few records a few days prior to this appearing. That as it turns out may have been the culprit.

    I ended up destroying the DB, having Django admin regenerate it, and then re-populating the entire DB using a few batch jobs. I was lucky enough that all my data was batch generated. I lost 3 or 4 user accounts but no one will notice, sigh. So far so good.
  • Not sure about read/write logs or lowering your queries for the malloc error. I think mysql should actually be able to gracefully handle malloc...although the fact that you got that is weird. is swap turned on, on your server? Crank the queries back up, it should be happy running queries all day long - if thats what you gotta do. The innodb can have left over junk that mysql doesn't bother cleaning up when running normally(deleted rows was all i was aware of...but this suggest there is some sort of state information as well...dunno). the dump to file doesn't contain the left over cruft. so when you pull it bank it is a bit cleaned up.
blog comments powered by Disqus