Mongod Freezing for 20 to 90 Seconds

[Dan Riegel]

We are running a mongo replicaset on EC2 m2.xl hardware (two ubuntu
10.04 mongod 2.0.2 machines in replication config and an aribter
running on a micro instance). Each mongod uses four EBS volumes in a
raid 10 configuration, with an XFS filesystem. The hardware seems
reasonably comfortably sized - the db is about 100 GB, and io
saturation averages at around 20%, with occasional spikes up to 35%.
During the incident I am writing about though, it went to 100% for a
single 1 minute period.

Periodically (sometimes a few times a day, sometime it skips a day
entirely) our db freezes up for a few tens of seconds. The times are
not predictable. The sirens only start firing if it lasts more than
10 seconds, and that is happening something like 3-6 times a week.
The most recent incident, which was the worst, lasted at least 90
seconds, and I'm worried that this is getting worse as the database
grows. The outage was so bad that the primary db swapped roles with
the secondary, then switched back a minute or so after it recovered.

Here's the most disconcerting thing in the log:
...
Thu Jan 26 14:57:19 [conn442741] end connection 10.203.49.200:50900
Thu Jan 26 14:57:21 [conn442742] end connection 10.28.1.67:39262
Thu Jan 26 14:57:31 [conn442745] end connection 10.13.63.171:60348
Thu Jan 26 14:59:00 [conn441104] update ctp.logWifiLive query: { uuid:
"abcdefgh", year: 2012, month: 1 } update: { omitted : 1 } 121031ms
Thu Jan 26 14:59:00 [conn441229] end connection 10.214.7.207:41170
Thu Jan 26 14:59:00 [conn442295] end connection 10.202.195.96:53524
...

See, right in the middle, where there are NO LOGS for 89 seconds?!? I
don't think that should happen in a db that handles at least 60
updates per second. And that first entry at the end of the delay is
an update that took 121 seconds. (there is an index that perfectly
matches the query, and that query is normally so fast that it does not
get logged at all).

I dug up this thread about a similar problem, which attributes the
cause to NUMA
http://groups.google.com/group/mongodb-user/browse_thread/thread/7ef9e0e5e40d4e38

But as far as I can tell, EC2 machines don't have NUMA (right?),
though there is precious little information on the internet about it.
We are on mms - no obvious smoking gun there, though you can certainly
see the incident on the graphs. During the time of the outage, it was
not possible to establish connections. I have been running
currentOp() on the db every 5 seconds, so I have a fairly detailed
history of anything that ran for a long time, or that got stuck. I
can see the 121 second query start running before the db seized up,
and I can see it had the write lock. The next currentOp() that went
through was 86 seconds later at 14:58:57, and by then, that query was
gone (though the log doesn't show it finishing until 3 seconds
later). Page faults seem reasonable for the whole time - they go from
about .25 before the incident, and spike to 6 at the worst, which I
think is still ok.

Could anyone suggest what is going on here?

[Nat]

Which kernel are you using? Certain version of 2.6.32 kernel has a record of freezing.

[Dan Riegel]

2.6.32 indeed. I had no idea it had such a flaw. Is there something
I could do to see if that's the reason for our db spacing out? What
is the remedy? Just upgrade?

[Nat Luengnaruemitchai]

Can you get uname -a? 

--
You received this message because you are subscribed to the Google Groups "mongodb-user" group.

To post to this group, send email to mongod...@googlegroups.com.
To unsubscribe from this group, send email to mongodb-user...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.

[Antoine Girbal]

Note about the linux versions having issues:
http://www.mongodb.org/display/DOCS/Production+Notes

Could you get the result of explain() when doing a query on the same
match as your update?

[Dan Riegel]

> uname -a
Linux mongod-prod 2.6.32-341-ec2 #42-Ubuntu SMP Tue Dec 6 14:56:13 UTC
2011 x86_64 GNU/Linux

This is an ec2 build: https://launchpad.net/ubuntu/lucid/+package/linux-image-2.6.32-341-ec2


This is the explain on the query (seems fine to me):

db.logWifiLive.find({ uuid: "abcdefgh", year: 2012, month:
1 } ).explain()
{
"cursor" : "BtreeCursor uuid_1_year_-1_month_-1",
"nscanned" : 0,
"nscannedObjects" : 0,
"n" : 0,
"millis" : 26,
"nYields" : 0,
"nChunkSkips" : 0,
"isMultiKey" : false,
"indexOnly" : false,
"indexBounds" : {
"uuid" : [
[
"abcdefgh",
"abcdefgh"
]
],
"year" : [
[
2012,
2012
]
],
"month" : [
[
1,
1
]
]

[Antoine Girbal]

yes this explain is fine, should be real quick.
Besides the OS upgrade, the thing to look at is what exactly is
happening during those 90s: high CPU or iostat?

[Antoine Girbal]

based on your MMS, I would say to watch for the resident memory of
mongod.
It seems under 6GB of resident (it's been trending down), and there is
about 1.5GB of non-data memory so only 4.5GB of documents in RAM.
Based on the size of your working set / indexes, it may be too low.
You should watch for any other process on the box eating memory (do
not run anything else than mongod), number of connections, stack size,
javascript overhead, etc.

[Dan Riegel]

I suspect that the reason for the declining resident memory is that
today, we started running a long-overdue data cleanup. So, what I
suspect is happening is that it dredges up some old data from the disk
that we haven't looked up in a long time, which knocks out something
more recent, then we delete it, leaving a space in the cache. Rinse,
and repeat. I think we will perform a compact after the cleanup is
complete.

Anyway, we will upgrade. Do you have a version that you would
recommend? Could we jump straight to 3.0.0-14 (ubuntu 11.10)?

[Dan Riegel]

Preliminary results of upgrading the server to Ubuntu 11.10 have been
positive. After running for about 4 days, we have not seen any pauses
that impacted the performance statistics. That isn't quite enough to
proclaim victory yet, but after a week, I might break down and
celebrate.

[Antoine Girbal]

ok great to hear keep us posted

[Dan Riegel]

Sooo, I knew it was too soon. It turned out to be a glitch in the
data collection. We are still seeing db pauses. In fact, the base io
saturation (from iostat) on the 11.10 primary server seems
consistently higher (24% vs 15%) than the saturation on the 10.04
secondary. It was the same when the primary was 10.04 and 11.10 was
just a secondary. I will at least say that I don't think the pauses
are worse than before though. Can't yet say if they are better.

[Antoine Girbal]

Dan,
what's the status on this issue? Are you still seeing long pauses?
Going back through the thread, it sounds like you're not sure if you
have NUMA.
It would say so at the beginning of the mongod logs, look for NUMA.