mongod stops all operations for 20 seconds or so for no apparent reason

[Tejaswi]

Here's a screenshot of mongostat (http://i.imgur.com/61S7j.png)
Here's the relevant mongodb-log (http://pastebin.com/6hDgKf3s)

This happens once every 24 hours or so. Does this have anything to do
with allocating the next 2G file? That's supposed to happen in a
background thread without blocking other operations, right?

Or am I doing something in code/shell that could be blocking?

Is there a comprehensive list of operations that block that I can
check against?

-T

[Eliot Horowitz]

I don't think its related to the file allocation?

What hardware is this running on?

It looks like similar to numa issues we've seen.

> --
> 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.
>
>

[Eliot Horowitz]

I don't think its related to the file allocation?

What hardware is this running on?

It looks like similar to numa issues we've seen.

On Tue, Aug 9, 2011 at 3:59 PM, Tejaswi <nada...@gmail.com> wrote:

[Eliot Horowitz]

Can you look at http://www.mongodb.org/display/DOCS/NUMA and try the 2
things there?

[Tejaswi]

This is a plain vanilla EC2 m2.4xlarge (68G) instance.

File system is RAID0 on XFS on 4 EBS volumes each of size 1TB.

This machine and an equivalent machine with a light weight arbiter in
a replica-set.

-T

ps: apologies for not giving the machine specs in the first post.

On Aug 10, 8:49 am, Eliot Horowitz <el...@10gen.com> wrote:
> Can you look athttp://www.mongodb.org/display/DOCS/NUMAand try the 2

> things there?
>
>
>
>
>
>
>
> On Wed, Aug 10, 2011 at 8:44 AM, Eliot Horowitz <el...@10gen.com> wrote:
> > I don't think its related to the file allocation?
>
> > What hardware is this running on?
>
> > It looks like similar to numa issues we've seen.
>

> > On Tue, Aug 9, 2011 at 3:59 PM, Tejaswi <nadaha...@gmail.com> wrote:
> >> Here's a screenshot of mongostat (http://i.imgur.com/61S7j.png)
> >> Here's the relevant mongodb-log (http://pastebin.com/6hDgKf3s)
>
> >> This happens once every 24 hours or so. Does this have anything to do
> >> with allocating the next 2G file? That's supposed to happen in a
> >> background thread without blocking other operations, right?
>
> >> Or am I doing something in code/shell that could be blocking?
>
> >> Is there a comprehensive list of operations that block that I can
> >> check against?
>
> >> -T
>
> >> --
> >> 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 athttp://groups.google.com/group/mongodb-user?hl=en.

[Eliot Horowitz]

Can you run iostat -x 2?
Usually slow serveStatus is a result of a lot of swapping or odd
kernel performance.

[Erez Zarum]

I am having the same problems.
But i am running 3 shards (with a replicaset per each) on physical machines (64GB ram per node) (total of 6 nodes)
i know the current version of mongod (stable 1.8.2) fails to set numactl on my kernel (centos 5.5), i have not tried starting up mongod using interleave=all, could that solve this problem?

I would also like to know if there's any benefit from upgrading to CentOS 6, there are some large improvements in the kernel regarding mmap and filesystems.

On each node i use 14x146GB 10k disks (RAID10, Adaptec 52445 with Battery) on XFS.

for some reason only this server output 2 nodes in numactl
[root@xx-xxx4:~]# numactl --hardware
available: 2 nodes (0-1)
node 0 size: 32291 MB
node 0 free: 201 MB
node 1 size: 32320 MB
node 1 free: 25 MB
node distances:
node   0   1
  0:  10  21
  1:  21  10

[root@xx-xxx3:~]# numactl --hardware
available: 1 nodes (0)
node 0 size: 64623 MB
node 0 free: 291 MB
node distances:
node   0
  0:  10

Thanks!

[Eliot Horowitz]

I would definitely do both things mentioned here first:
http://www.mongodb.org/display/DOCS/NUMA

[Tejaswi]

iostat output when the write-freeze was happening: http://pastebin.com/raw.php?i=7EZp4sM8

I see writes freezing completely, which is reflected in the mongod
logs as well.

Does that help?

-T

> >> On Wed, Aug 10, 2011 at 10:55 AM, Tejaswi <nadaha...@gmail.com> wrote:
> >> > This is a plain vanilla EC2 m2.4xlarge (68G) instance.
>
> >> > File system is RAID0 on XFS on 4 EBS volumes each of size 1TB.
>
> >> > This machine and an equivalent machine with a light weight arbiter in
> >> > a replica-set.
>
> >> > -T
>
> >> > ps: apologies for not giving the machine specs in the first post.
>
> >> > On Aug 10, 8:49 am, Eliot Horowitz <el...@10gen.com> wrote:

> >> >> Can you look athttp://www.mongodb.org/display/DOCS/NUMAandtry the 2

[Richard Kreuter]

Just to be clear, have you tried tweaking the NUMA settings?

> > >> >> Can you look athttp://www.mongodb.org/display/DOCS/NUMAandtrythe 2

[Tejaswi]

I am not on NUMA architecture. Apologies for not having made that
clear.

ubuntu@ip-x-x-x-x:~$ numastat
sysfs not mounted or system not NUMA aware

-T

[Tejaswi]

I had a "Too Many Open Files" error on the same DB a few hours back. I
had to increase my ulimit -n.

Could the block problem be due to that?

-T

[Eliot Horowitz]

That could definitely be the problem.
Let us know if it happens after that.

[Erez Zarum]

Bumping this thread up because i assume what i am having is a NUMA problem.
Investigating more on my cluster, i have started to profile some thing up and found a strange behavior.
i got 6 nodes, only 1 of those nodes got a different CPU, looking at stats i have collected when the cluster hangs, i can see kswapd goes up (i guess it tries to free pages up) and locks the machine.
Looking at the node(nodes #4) with the different CPU i can see that he utilize NUMA as needed and never cause kswapd to go up, i have tried setting up interleave=all on 2 nodes and this does not help at all.
Also, this node has a different motherboard which could also be it.
The CPU on node #4 is: Intel Xeon E5506 (Supermicro X8DTU)
The CPU on the other nodes is: Intel Xeon L5410 (Supermicro X7DW3)
All of them have 64GB RAM
If i look over the last 6 months+ (from the monitoring system) i can see that node #4 never had any problems while all the others involved, getting hangs, all the time.

I think first thing i will try is to disable NUMA at base, running the kernel with numa=off, what do you think?

[Eliot Horowitz]

See this: http://www.mongodb.org/display/DOCS/NUMA

[Erez Zarum]

I did follow it, but it's seems as kswapd is still causing high cpu lock.
I assume something else effect it so i want to try and disable NUMA on the kernel side.

[Erez Zarum]

I have disabled numactl at the kernel (booting the kernel with numa=off).
So far i can see i am able to get higher fault/s (with higher queries/s) with very very low lock%, before hand, high fault/s caused a huge lock%, it should not be related i assume, but i can not explain this.

I will know in the next day or two if it helped or not, the problem happens when mongod uses most of the RAM cache and then kswapd come to free dirty pages, at this moment it hangs the whole node.

I will keep this thread updated

[Richard Kreuter]

Hello,

Have you seen the problem recur after disabling NUMA?

Regards,
Richard

On Aug 18, 5:29 am, Erez Zarum <e...@icinga.org.il> wrote:
> I have disabled numactl at the kernel (booting the kernel with numa=off).
> So far i can see i am able to get higher fault/s (with higher queries/s)
> with very very low lock%, before hand, high fault/s caused a huge lock%, it
> should not be related i assume, but i can not explain this.
>
> I will know in the next day or two if it helped or not, the problem happens
> when mongod uses most of the RAM cache and then kswapd come to free dirty
> pages, at this moment it hangs the whole node.
>
> I will keep this thread updated
>

> On Wed, Aug 17, 2011 at 6:25 PM, Erez Zarum <e...@icinga.org.il> wrote:
> > I did follow it, but it's seems as kswapd is still causing high cpu lock.
> > I assume something else effect it so i want to try and disable NUMA on the
> > kernel side.
>
> > On Wed, Aug 17, 2011 at 2:48 PM, Eliot Horowitz <el...@10gen.com> wrote:
>
> >> See this:http://www.mongodb.org/display/DOCS/NUMA
>

> ...
>
> read more »

[Infin1ty]

I am writing from my second profile,
Yes, problems happen even when i set numa=off to the kernel line.
As you can see in this file: http://oi53.tinypic.com/9jqfte.jpg,
mongod (this process is a secondary node in a sharded cluster +
replicaset configuration) goes up to 700% , system idle, no disk i/o
as well, and kswapd0 goes up to 100% making the whole server hang.
As i can understand it happens when dirty pages are being freed (this
call goes from the mongod i assume).
If i will restart mongod and will let it start from scratch (about
64GB RAM available and not cached) it will work faster than it is now
(without any hangs until it reach around 60GB resident), this should
be the opposite, and the more i have cached in RAM the faster it will
be (mongod is more stable/faster when it's cold than it is warm at
this situation).
After a restart i can see high rate of fault/s (for obvious reason)
but yet, the cluster is so much faster and i never get mongod to hang
until i reach the 60GB resident memory.

Take a note that when this happens, the whole cluster as is (mongod -
master/secondary, mongos , etc..) is mostly not usable!

[Infin1ty]

Sorry for the double post, but i do receive those messages on the
linux buffer (dmesg)

INFO: task mongod:26155 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
mongod D 0000000000000001 0 26155 1 26156
26154 (NOTLB)
ffff811014d1fee8 0000000000000082 ffffffff800ce6ba ffff81102fca74c0
0000000000000286 0000000000000001 ffff810e7aed4860 ffff8109fe789820
000074e3388dce3d 0000000000000f76 ffff810e7aed4a48 0000000700000001
Call Trace:
[<ffffffff800ce6ba>] zone_statistics+0x3e/0x6d
[<ffffffff8000f5cd>] __alloc_pages+0x227/0x308
[<ffffffff8006466c>] __down_read+0x7a/0x92
[<ffffffff800d06ca>] sys_mincore+0xd6/0x21a
[<ffffffff8005d116>] system_call+0x7e/0x83

> ...
>
> read more »

[Infin1ty]

More input on the issue:
What happens is when the mongod get over to 60G (resident) kswapd
kicks in and start to free pages, making mongod having only 50G
resident memory up until it gets into around 60G again.
This goes over and over, when kswapd free pages the whole system
simply hangs, i guess the cluster is not aware of it and this thinking
everything is ok with all the shards/replicasets, and that is what
making the whole cluster hangs.

I am wondering if it's because mongod reaching to almost all available
memory (and then kswapd kicks in) or is it some kind of a function
coming out of mongod.
Then possibly setting somehow a limit on mongod to 55G (resident) ram
will fix it.

The only weird problem is that all the servers but one (node4) are
having this issue. (total 6 nodes)
It happens also on node4, but node4 never hangs. (node4 has numa
enabled with 2 nodes, meaning two kswapd (0 and 1) , i did not try to
disable numa there as it was working well)

The difference between them as i can see it is the CPU, Motherboard
and RAM, what more came to my eyes was the CPU (new generation of
Intel using the QPI technology).

Xeon E5506 on node4, the rest have the Xeon L5410

What bothers me the most is that kswapd kicks in, should i worry about
it?

> ...
>
> read more »

[Erez Zarum]

I have disabled NUMA at the BIOS but kswapd was still doing his job, making mongod taking resources from all the cores on the CPU.
I was setting vm.swappiness to 0 when i first initialized those servers, treating mongodb as any other database i have worked it.
This might be wrong, as last night i have traced this may be the problem, setting it back to 60 seems to make the job.
I will report more on it after a week.

> ...
>
> read more »

[Steffen]

Just to make sure, you have disabled NUMA at boot and set swapiness
back to default, which solves your issues?

what about /proc/sys/vm/zone_reclaim_mode?

We have also issue with this, and we increased the IO subsystem (6x
15k SAS as Raid10), swapiness 20, zone_reclaim_mode 0, numactl
interleave-all.
At the Moment this is our best setup. But if we push a lot writes to
Mongo the system begins to hang.
CPU: 2x Intel(R) Xeon(R) CPU E5620
Mongo 1.8.2: 3 node ReplicaSet

[Erez Zarum]

zone_reclaim_mode is set to 0
and i have set deadline as the scheduler.
vm.swappiness=60
so far it looks like it's helping and system is not swapping at all.

[Erez Zarum]

read this on swapping:
http://www.westnet.com/~gsmith/content/linux-pdflush.htm
that explains why kswapd hangs.
mongodb is expecting the OS to write dirty pages back to disk.
setting it to 0 was aggresive, when mongodb reached around 60GB (out of the 62GB the OS see) the whole system simply hanged because it was "too late" for kswapd to kicks in and when it did it had much more work, at this situation the mongod process was left with almost no place to cache data (as kswapd kicked in later), this made my whole server hang.

so far it proves i was right, perhaps someone else could explain it in a more easy way.

[Erez Zarum]

there's also good information in here: http://kerneltrap.org/node/3000
So far my cluster runs well, nothing hangs/stall, this is a thing that never happened before.

[Steffen]

Thanks for the link. Very interesting.

Did you change your dirty_background_ratio ?
My Ubuntu default is 10.

[Erez Zarum]

no, i have left it default.
I run CentOS 5.6 currently.
I do know upgraindg to 6.0 will improve a lot as well.

[Tejaswi]

I had had this issue with 1.8 because of not having set enough number
of open files.

I am now on 2.0.0 and the "bug" is back. The DB blocks for an
extensive period of time (around 4 minutes), and accepts:

- No inserts
- single digit queries

And most importantly, my resident process memory size goes down
dramatically during this time. Typically, from 45G to 37G. The qr|qw
and ar|aw numbers also keep increasing - till they hit around 100. The
db then "returns" and things get back to normal. The res_memory size
takes around an hour to climb back up to 45G.

Also, my entire DB is taking only 60% of the available memory on the
machine. I don't see any other process consuming any other memory. But
Top tells me that all my memory is used. Is this problem related to
the "blocking problem"?

I am on a m2.4xl - 68G RAM machine on EC2. 2 replicas 1 arbiter setup.

-T

On Sep 4, 11:14 am, Erez Zarum <e...@icinga.org.il> wrote:
> read this on swapping:http://www.westnet.com/~gsmith/content/linux-pdflush.htm
> that explains why kswapd hangs.
> mongodb is expecting the OS to write dirty pages back to disk.
> setting it to 0 was aggresive, when mongodb reached around 60GB (out of the
> 62GB the OS see) the whole system simply hanged because it was "too late"
> for kswapd to kicks in and when it did it had much more work, at this
> situation the mongod process was left with almost no place to cache data (as
> kswapd kicked in later), this made my whole server hang.
>
> so far it proves i was right, perhaps someone else could explain it in a
> more easy way.
>
>
>
>
>
>
>
> On Sun, Sep 4, 2011 at 3:31 PM, Erez Zarum <e...@icinga.org.il> wrote:
> > zone_reclaim_mode is set to 0
> > and i have set deadline as the scheduler.
> > vm.swappiness=60
> > so far it looks like it's helping and system is not swapping at all.
>

[Eliot Horowitz]

Can you send the logs from that period?

[Tejaswi]

The logs were not very helpful. A bunch of connections were reset
though.

If it's really important, I can wait for it to happen again, and copy
the logs.

-T

[Eliot Horowitz]

Need something to work off of.
Another option is setting up mms (http://mms.10gen.com/)
Then can see much more detailed info if/when it happens again.

[Tejaswi Nadahalli]

I am on MMS.

And the problem happened 10 minutes ago, and I have a log as well. Attached.

-T