[SERVER-11219] mongod crash during index build leaves orphaned index Created: 16/Oct/13 Updated: 10/Dec/14 Resolved: 28/Oct/13 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Index Maintenance |
| Affects Version/s: | 2.4.5 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Arkadiy Kukarkin | Assignee: | J Rassi |
| Resolution: | Duplicate | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Issue Links: |
|
||||||||||||
| Operating System: | ALL | ||||||||||||
| Steps To Reproduce: | Index was built in the background and presumably worked before? |
||||||||||||
| Participants: | |||||||||||||
| Description |
|
[ed: original title was "Index shown in getIndexes() does not actually exist"] I've been trying to track down a mysterious performance issue on one of our shards for a little while, and it turns out the culprit is an index that doesn't actually exist:
Queries that should use this index do a full scan instead. |
| Comments |
| Comment by J Rassi [ 28/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks. Copying earlier resolve message: "Issue fixed by refactor in | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Arkadiy Kukarkin [ 28/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Cool, wanted to make sure you didn't need any more data from me. I didn't look at getIndexes output after dropIndex, so it's possible it was partially successful. Building normally now. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by J Rassi [ 28/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hmm. I can confirm that repairDatabase on 2.2.3 fetches the index list for the rebuild in the same way that db.collection.getIndexes() does (that is, a query on db.system.indexes), so I'm currently convinced that you got rid of the system.indexes entry somehow (the dropIndex attempt?), sometime between posting the ticket and running repairDatabase. Anyway, you have a fresh database on this member now, so I'd just create the index on it as usual if you haven't already. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Arkadiy Kukarkin [ 28/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Finished without errors, however index was not rebuilt:
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by J Rassi [ 26/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
repairDatabase finish without errors? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by J Rassi [ 25/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Yeah that's a bug – filed | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Arkadiy Kukarkin [ 25/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
On a side note, an error similar to other "not master" errors would probably be more helpful. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Arkadiy Kukarkin [ 25/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Restarting as standalone fixed the issue, never mind! | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by J Rassi [ 25/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Also (perhaps relatedly), I just noticed the SECONDARY prompt from your shell excerpt. You'll need to restart the secondary in standalone mode (without the --replSet flag) to perform write operations on it. You may have already – sometimes the shell doesn't update the prompt properly. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by J Rassi [ 25/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Can you post the log excerpt for the repairDatabase, with at least a few minutes of context? And the member is still running 2.2.2, yes? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Arkadiy Kukarkin [ 25/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Ok, attempting to repairDatabase yields this:
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by J Rassi [ 17/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Issue fixed by refactor in | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by J Rassi [ 17/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I'll go back on my earlier advice: run repairDatabase instead of a reIndex. reIndex only drops the index collections that are registered with namespace details, so after the reIndex finishes the list.i_1 index collection will still have the old index data around on disk (though the old data will be inaccessible to queries). repairDatabase does a rebuild-everything-from-scratch, which is the more robust fix (also, a reIndex on a collection with half-built indexes doesn't work in 2.4). I also decided not to file a request for the user mechanism to remove half-built indexes: it wouldn't be backported since it's a feature, and the I'll resolve this ticket then, assuming you'll run repairDatabase when you can next take a maintenance window for that host; feel free to re-open the ticket if you run into any problems. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Arkadiy Kukarkin [ 16/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Taking this member down is harder than it sounds, because there is an unrelated issue with the secondary (which does have the index correctly committed, sigh) where it absolutely refuses to catch up at above realtime speed and has been staying in STARTUP2 all day. Disk and network are at under 200k/s max but CPU is pegged and serverStatus takes 2000ms+ to run :\ Will post this one to the mailing list, I'm guessing it's a locking issue. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Arkadiy Kukarkin [ 16/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Okay, that makes sense. The index collection does indeed have some objects, but fewer than expected: }, No idea why that machine would run of memory – it has plenty of RAM and doesn't really run anything else. I seem vaguely remember unusually high resource usage at around this time, but no details. I'll dig around a bit to see if I can find anything. mongod version is 2.2.2 at this time | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by J Rassi [ 16/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Reproduced on 2.2.3, verified that reIndex fixes the issue. [edit: run repairDatabase instead of reIndex; see comment below] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by J Rassi [ 16/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Nope, not an OOM kill, an assertion failure (13524). 13524 is an assertion in the journaling subsystem during allocation of a journal commit – it's raised when posix_memalign() returns an error (presumably ENOMEM). At the time of the assertion failure, the external sort had finished and the index build was being committed to disk. Fatal assertion failures generate an abort() call, which is why you see signal 6. I'm guessing that the amount of memory requested was less than 256MB, since warnings are printed whenever the journal commit size exceeds that, but I can't tell without seeing if there are any in the full log. And it's not clear why the system was out of memory at that time either; system memory usage stats from that time would probably help diagnose that. Committing a index build to disk that uses external sort isn't memory-intensive by itself. I see that the index has an entry in db.system.indexes (from your collection.getIndexes() output), and I presume that a collection was allocated for the index (site_events.listen.$list.i_1), but I see no entry for the index in the database's namespace details (from your collection.stats() output). The namespace details is the "definitive" listing – since it's not there, it's not being updated or used for queries. So, the process aborted during the index build, you have a half-built index of sorts. Unfortunately, in 2.2 (which I presume you were running, since the log says February) mongod doesn't continue aborted index builds on restart (fixed in 2.5.0 as part of You can't remove it with dropIndex; you probably want to take the member down for maintenance and run reIndex. I'll file a feature request for a user mechanism to remove half-built indexes and link it here. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Arkadiy Kukarkin [ 16/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Can't drop it, I guess: events2:PRIMARY> db.listen.dropIndex("list.i_1"); { "ok" : 0, "errmsg" : "index not found" } | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Arkadiy Kukarkin [ 16/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
This appears to be the most relevant piece:
So it looks like the process may have gotten OOM killed (though that should be 9, not 6?) while attempting to commit the index, restarted, tried again (and got killed again) then gave up. I don't remember how this machine was spun up, but I am guessing initial dataset copy from EC2 snapshot. Should I drop and rebuild the index now? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by J Rassi [ 16/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
It'd look something like
And, do you know if this member was brought up from an initial sync? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Arkadiy Kukarkin [ 16/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hey Rassi! This was indexed a while ago, but maybe the logs are still around. What string should I grep for? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by J Rassi [ 16/Oct/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Do you have the mongod log excerpt for the list.i_1 index build? |