Recovering from InnoDB Page Corruption: A Post Mortem
Recovering from InnoDB Page Corruption: A Post-Mortem
I recently wrote about how to Repair a database following InnoDB Page corruption.
This post is a post-mortem of the circumstances that led to the corruption prompting that post. Some of it comes from log observation, other elements are from re-creating the circumstances in a VM.
Improper Database Distribution
This was my most obvious mistake, and one that I should definitely have known better than to make - I had a production database on a development server (I'm still not sure why...)
The circumstances
I was running tests on a badly performing Joomla database. In particular, I was attempting to get Joomla's com_finder indexer to complete an indexing run on a database with > 70,000 sizable com_content articles.
I found that the script was hitting the PHP memory_limit on each run - increasing the limit simply prolonged the inevitable.
Rather than looking at the indexing plugin, I put the command into a for loop to force it to restart whenever it bummed out
for i in {1..100}; do php finder_indexer.php; done
This was (avoidable) mistake number 2. It compounded the issues that arose later - in trying to brute force past one issue, I ensured that when the next arose the script would keep running, causing further issues.
Heavy Load
From the server's point of view, the processing load wasn't that high, but MySQL was getting absolutely hammered by the indexing script.
Every now and then, the script would error out with a lost MySQL connection, restart and then go on again for a while. The cause of this was that MySQL had died and then restarted
This leads us onto the next, much more subtle mistake
FSync Lies
I didn't have Write Barriers enabled, so when fsync reported a write as complete, it only actually mean that the data had made it into the storage write caches.
So MySQL thought various bits of data had been written to disk, before they'd actually reached the platters.
In normal circumstances, this isn't great (in that it's a risk) but doesn't generally do any harm. Unfortunately, when things go wrong it leads to some pretty major headaches.
Jira was active
My JIRA install checks various mail accounts regularly, and creates Issues/comments whenever it finds something matching a rule.
Similarly, the GIT integration plugin I use, scans various GIT repos for new commits and links them up to the relevant Issue.
All this, of course, means that the DB is being used even when I'm not personally using JIRA.
JIRA makes good use of InnoDB tables, which in this case was it's own undoing. As a result of the ridiculous pressure that I was putting MySQL (and the disks) under, a number of the writes that fsync had reported complete, never actually made it onto the disk platters
MySQL, of course, believed that they had and so carried on about it's business
MySQL got unstable
Now that the initial corruption had occurred, whenever JIRA tried to access certain tables within it's database, MySQL would encounter a corrupted InnoDB page and restart. Logging something like
140129 23:53:50 InnoDB: Page checksum 3244463932, prior-to-4.0.14-form checksum 3365547667
InnoDB: stored checksum 1349822260, prior-to-4.0.14-form stored checksum 3365547667
InnoDB: Page lsn 0 95653297, low 4 bytes of lsn at page end 95653297
InnoDB: Page number (if stored to page already) 568,
InnoDB: space id (if created with >= MySQL-4.1.1 and stored already) 0
InnoDB: Page may be an update undo log page
InnoDB: Page may be an index page where index id is 0 369
InnoDB: (index "cl_username" of table "JiraDB"."columnlayout")
InnoDB: Database page corruption on disk or a failed
InnoDB: file read of page 568.
This of course led to the com_finder indexer failing to execute it's query, and restarting.
Fixing the Issue took more than one attempt
I became properly aware of the issue the first time I tried to log into JIRA (to log the progress of the indexer... appropriate).
Nothing more useful than a Java stack trace was shown, but it didn't take too long to trace back to the database.
Looking at MySQL immediately yielded some interesting stats
$ mysqladmin version
mysqladmin Ver 8.42 Distrib 5.1.69, for redhat-linux-gnu on i386
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners.
Server version 5.1.69
Protocol version 10
Connection Localhost via UNIX socket
UNIX socket /var/lib/mysql/mysql.sock
Uptime: 4 seconds
Threads: 1 Questions: 15 Slow queries: 13 Opens: 8
Flush tables: 1 Open tables: 8 Queries per second avg: 3.1
An uptime of 4 seconds? More than a little odd. Attempting to log into JIRA again led to the same stack trace, and MySQL helpfully reported an uptime of 2 seconds.
The MySQL logs were full of page dumps, and it was quite clear why the uptime was so low.
So to recover the database I followed most of the steps I laid out in Recovering from corrupted InnoDB Pages.
I didn't check other Databases
Although I knew other databases would need to be checked, I had other things I needed to do (like record the progress of the com_finder indexer) to planned to check the other databases later (they weren't in use anyway right?).
That mistake is the reason that my earlier post includes a section on checking other databases. My original rationale makes sense, but it didn't consider all possibilities - after all how could corruption in one database lead to corruption in another?. It's not like corruption is infectious, and even if it was - the databases aren't interacting.
The next day, I tried to log into JIRA so that I could start checking the other databases and record which (if any) had been corrupted
The now all-too familiar stack trace was visible again.
The Databases only have to be in use at the same time
I said earlier that the other databases weren't in use. This in fact is only half true, every night my backup takes a dump of every database on the server. So whilst I wasn't actively using them, they were accessed - once.
One of the development database contained InnoDB tables that had also suffered from page corruption - although I've not been able to find how this occurred. It's not clear why anything was trying to write to that database at any point, so is appears to have been simple bad luck.
The problem is, the backup script only locks each table/database as it backs it up. So JIRA was (once again) quite happily trying to write to it's DB whilst the other (corrupted DB) was being read. The corruption led to MySQL restarting, and I now had two corrupted databases (again).
Log recovery starts to hurt
Now, following it's unscheduled restart, MySQL tried to replay the InnoDB log files, meaning it came across the corrupted pages, and.... restarted.
So MySQL had now put itself into a nice little loop of starting, finding corruption, restarting, finding corruption etc.
Final Recovery
Once I'd identified the cause of the secondary issue, recovery was quite easy.
- Put MySQL into force_recovery mode
- Dump all the databases with InnoDB table
- Drop those databases
- Take MySQL out of force_recovery
- Recreate the databases (and assign the appropriate users permissions
- Re-import from the dumps
The final step, of course was to remove the nobarrier mount options from the relevant filesystems.
Mistakes I made
I made a number of mistakes, though some are simply because it's a dev system so regularly tweaked to suit testing needs.
- Running a production database on a dev server - I'm sure there was originally a reason why the database was on this server (most likely, I installed on dev to play with JIRA and forgot to move the DB once I decided to stick with it), but the ramifications of the corruption would have been much smaller had I maintained a proper degree of seperation
- Disabling write-barriers - I disabled these a while ago whilst testing a few things. It can improve performance quite considerably, but isn't a good thing to have on a system hosting a transactional database.
- Not thoroughly troubleshooting Joomla - Rather than taking a lazy brute-force attempt at getting the indexer to complete a full run, I called the indexer in a loop so that it'd eventually get there. What I should have done (and still plan to do) is look at the plugin to see why it's eventually hitting memory limit (I did, at least, check the usual suspects)
- Not Checking All Databases - It was getting late at night and having recovered JIRA I decided to come back and check the other databases the next day. The rationale was that (as it was a dev system), the other databases weren't in use so should be fine overnight. What I should have done is at least check the others for corruption before jumping to that conclusion
Things I did Right
It's not all doom and gloom, there were a number of things I did that helped me resolve it quickly
- Regular Backups - Although the automated backup triggered the second instance of corruption, it saved my bacon on the first. Having daily backups meant that I lost little to no data through having to restore to an older snapshot
- Taking a paranoid backup - Just before I sloped off to bed, I took a backup of the JIRA database just to be safe. It was a good move, as the next nightly was blank (the database had corrupted again by this point)
- Not Rotating Logs too regularly - My logs rotate daily, but older copies of the log are maintained for quite some time. Had I been rotating logs out daily, it would have been harder to go back and follow the issue from start to finish
Process Changes
The first, mode obvious change I've made to avoid a repeat is to get the JIRA DB across onto the production database server.
I've been meaning to set Xen up on the dev server for quite a while so that testing can be compartmentalised a bit more effectively. That's now jumped much further up the list.
I've also added some of the change control mechanisms I use in Production, in particular turning /etc into a git repo. The next step is to write a script that watches for changes in certain files (fstab being one of them) and then nags me until I either confirm the commit (by using a certain commit message) or the change is reverted.
The production server can also no longer talk to the Dev server (with some small exceptions), so that the likelihood of me forgetting to migrate a database is reduced.
But What Happened to the Joomla DB?
This was all triggered by the attempt to run the com_finder indexer against a very large dataset, so it seems fitting to finish this post with the end result of that work.
Given the issues experienced, I moved the indexing efforts to a far more capable system (with nothing important running on it!) and continued to try and complete the indexing run.
It took 96 hours to complete, with multiple restarts due to hitting memory_limit (though the previously processed batches will complete very, very quickly at each restart).
Unfortunately, the resulting database was larger than I feel confident that the server hosting the site can reliably handle (at least until some other issues are resolved).
So the end result is that the initial work was (at least for now) in vain, but provided a good opportunity to look further into how InnoDB works and the impact that hardware/filesystem configuration can have on the security of your data.
