Juju 2.1.1: Mongo Out Of Memory on bootstrap machine 0

Juju status failed OpenStack HA deployment.

All juju logs from each unit in the deployment. base-machine/0 will have the Out of Memory errors related the the bootstrap node killing mongod.

We might want to watch: https://bugs.launchpad.net/juju/+bug/1653558 as well

All juju 2.1beta3 logs from OpenStack HA region deployment. base-machine/0 == bootstrap node
https://private-fileshare.canonical.com/~csmith/my.tgz

Chad, Juju team think they fixed this in beta4, can you retry with that?

Additional data points:

 1. tried an HA OpenStack 6 node deployment (juju2.1beta4) which was making use of a new model in using an external 2.1beta3 controller. On the bootstrap node of the 2.1beta3 controller mongod climbed from 1.3GB -> 1.7Gb over two hours of idle update-status hooks. This leads me to believe that mongod will continue to grow if left over a 24 hour period.

 2. Deployment #2: Allowed landscape to bootstrap a 2.1beta4 controller and use the bootstrap node and the controller model for the 6 node HA deployment. At the end of the HA deployment, mongod claims 1.4Gb of Memory. Will update with mongodb memory footprint for these two deployments after the get a few hours of idle "bake time".

Followup on my 6 node HA OpenStack clusters:

  1. external juju 2.1beta3 controller separate model for the cloud deployment: mongodb has continued to grow in memory for my idle 6 node cloud:
  - bootstrap node is not involved in the deployment
  - 9 hours since cloud deployment: mongod memory footprint 1.3Gb -> 2.1 Gb

  2. internal (bootstrapped by landscape) juju 2.1beta4 controller, using the :controller model (and bootstrap node as one of the 6 machines) for the deployment:
   - bootstrap node is one of the 6 machines in the cloud (has 7 lxc with openstack services on it)
   - 7 hours since cloud deployment: mongodb memory footprint 1.3Gb -> 2.7Gb
   - juju status or juju ssh 0 no longer responsive, swap space fully allocated at 100%

Must mention I have not yet seen an OOM event on either deployment yet. Will update tomorrow.

Update on existing 6 node deployments:
 1. External 2.1beta3 controller (beta4 deployment in a separate model)
    mongod has grown to 2.6GiB from 2.1GiB in the last 19 hours

 2. Internal 2.1beta4 controller services places on the bootstrap machine 0 in :controller model:
    - mongod has grown to 4.6GiB from 2.7GiB in the last 19 hour
    - no OOM events killing mongo yet, and memory is nearly at capacity
              total used free shared buff/cache available
Mem: 15G 14G 234M 431M 1.0G 359M
Swap: 4.0G 4.0G 0B

We wrote a script to sort mongo collections * databases based on storage size. The most significant mongo collections are juju log related.

juju.statuseshistory: 25.03 MiB (0%)
blobstore.blobstore.chunks: 33.65 MiB (1%)
local.oplog.rs: 1.00 GiB (35%)
logs.logs: 1.76 GiB (61%)

--- database size
admin 951.00 B
presence 737.90 kiB
blobstore 33.65 MiB
juju 45.33 MiB
local 1.00 GiB
logs 1.76 GiB

The simple script: http://paste.ubuntu.com/23783766/

I'm wondering if Landscape using the :controller bootstrap machine 0 is what leads to the eventual OOM because of wiredTiger cache grabbing 50% of the machine's total memory.

Since juju doesn't specify --wiredTigerCacheSizeGB option to mongod, mongo assumes machine 0 owns all physical memory and wiredTiger will grow quickly to 50% of the physical memory on the system [1].

Since landscape deploys lxcs to machine 0 in the controller model, memory is impacted by the number of applications running in the lxcs so mongo claiming 50% of the physical memory will quickly lead to saturating swap space as mongo gets too big.

References:
[1] From https://docs.mongodb.com/manual/faq/storage/
"""
Starting in 3.4, the WiredTiger internal cache, by default, will use the larger of either:

50% of RAM minus 1 GB, or
256 MB.

NOTE
The storage.wiredTiger.engineConfig.cacheSizeGB limits the size of the WiredTiger internal cache. The operating system will use the available free memory for filesystem cache, which allows the compressed MongoDB data files to stay in memory. In addition, the operating system will use any free RAM to buffer file system blocks and file system cache.

To accommodate the additional consumers of RAM, you may have to decrease WiredTiger internal cache size.
"""

Marking back as new for comment from the juju team. I have a deployment up that I believe I can give access to if more debugging is needed. We have a cron running every 30 mins to grab mongo and ps_mem related information.

Just got my first OOM on this juju2.1beta4 system:
Jan 11 23:27:24 bierstadt kernel: [102792.536095] Out of memory: Kill process 5423 (mongod) score 256 or sacrifice child

I'm not certain if juju has the ability to cap mongo's (or wiredTiger's) memory growth, or whether juju can govern smaller set sizes in memory so mongo doesn't keep around as much data.
It seems this problem is exacerbated by two conditions:
  1. having multiple active lxcs on the bootstrap machine
  2. having an HA OpenStack deployment (with high-frequency leader election logging)

Background on landscape using the bootstrap machine for deployment is to avoid burning a full machine for just juju's controller when the controller's only role is to support a single region.

If landscape had a config setting knob in juju to tune down the mongo memory caps, then landscape could knowingly set a cap during bootstrap and/or lxc placement events. Landscape would know that the additional lxcs will impact available memory on the bootstrap node so it could limit mongo(wireTiger) growth appropriately.

Validated wiredTiger default cache settings are in fact ~8Gb from mongo's db.serverStatus() command linked in comment #10.

looked at wiredTiger: : { "cache" : { "maximum bytes configured" : 8589934592 }} which is ~8Gig on the bootstrap node. This will be too high a value if the bootstrap has any memory hungry lxcs on it.

There was a bug we found earlier in the week that may well have contributed to this. The guys in the OIL CI lab are testing.

marking as Incomplete until we hear back from OIL. It's possible that this bug has been fixed as per comment # 14.

Can someone please link to this "other bug" and to the PR that fixed it? And can someone from OIL please make a comment here as to what they saw, what they are testing, and the results when they come? So that we have a point of contact.

This is quite expensive and time consuming to test and we don't want to just "could you please test this new version and see if it still happens" based on vague statements.

juju 2.1beta4 controller on an idle cloud.

mongod %MEM taken from ps output.

juju 2.1beta4 controller on an idle cloud.

mongod RSS taken from ps output.

juju 2.1beta4 controller on an idle cloud.

mongod VSZ taken from ps output.

juju 2.1beta4 controller on an idle cloud.

overall controller RAM and swap usage as measured by Landscape.

The above graphs are from a controller created a few days ago. The cloud deployed using that controller is idle.

This controller does not have the TRACE logging issue, i.e., it's logging is set to "<root>=WARNING;unit=DEBUG".

Chad's script for mongo stats outputs this at the end:
(...)
juju.txns: 5.57 MiB (0%)
juju.txns.log: 9.54 MiB (0%)
blobstore.blobstore.chunks: 34.16 MiB (2%)
juju.statuseshistory: 79.36 MiB (5%)
logs.logs: 262.03 MiB (18%)
local.oplog.rs: 1.01 GiB (72%)

--- database size
admin 951.00 B
presence 1.48 MiB
blobstore 34.16 MiB
juju 97.65 MiB
logs 262.03 MiB
local 1.01 GiB

The memory usage growth is much more tame, but looks like it's still happening.

BTW, uptime:

ubuntu@born:~$ uptime
 13:41:30 up 2 days, 18:10, 1 user, load average: 1.24, 1.46, 1.55

@Andreas,

The PR with the fix is against 2.1: https://github.com/juju/juju/pull/6789

The bug that we've referred to is: https://bugs.launchpad.net/juju/+bug/1649719

Thanks Anastasia for the updates here, we'll grab the RC1 when it comes out to continue memory growth investigation.
I've attached juju status for landscape's 6 node HA deployment for reference

Hi there,

There was a very bad memory leak that was identified in the beta3 and beta4 releases of 2.1. This was causing rampant memory usage. This particular leak was identified and fixed in early January, but I am still investigating other leaks in the 2.1 branch.

Some of the continued chatter about leaks is on bug 1649719.

Thanks for the update, Tim!

On Jan 26, 2017 6:41 PM, "Tim Penhey" <email address hidden> wrote:

> Hi there,
>
> There was a very bad memory leak that was identified in the beta3 and
> beta4 releases of 2.1. This was causing rampant memory usage. This
> particular leak was identified and fixed in early January, but I am
> still investigating other leaks in the 2.1 branch.
>
> Some of the continued chatter about leaks is on bug 1649719.
>
> --
> You received this bug notification because you are subscribed to
> Landscape Project.
> Matching subscriptions: default, everything
> https://bugs.launchpad.net/bugs/1655169
>
> Title:
> Juju 2.1beta4: Mongo Out Of Memory on bootstrap machine 0
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/juju/+bug/1655169/+subscriptions
>

Sinzui pointed me to these bugs after we observed issues on 2.0.2 in our HA controller for deploying models into Prodstack.

https://grafana.admin.canonical.com/dashboard/snapshot/EiekDtFVtH6VJzO1ANUKFehtROypKdIq?from=1485370617479&to=1485525311195

We have seen occasional need to restart a single instance due to an OOM but unfortunately today had 2 of 3 near simultaneously which took us a while to recover from and clean up lost agents in the models once juju status etc started returning again.

Per sinzui we shouldn't expect a fix in 2.0.3 but rather this fix to land in 2.1

Adding an update after setting up a long running cloud with 2.1.1:

   - This cloud is a 6 Node High-availability configuration kvm, openvswitch ceph object ceph block
   - Additional memory pressure on the controller machine with 7 lxds on machine 0 with various openstack services
   - Additional mongodb log pressure due to a debug juju log setting in landscape
            logging-config model <root>=DEBUG;juju.apiserver=TRACE;unit=DEBUG

   - The deployment has OOM killed mongod on the controller machine twice in 7 days at a rate of about once every 2.5 days
   - Controller machine has 16 Gb of memory, so wiredtiger will grab up to 8 Gb for cache.
   - mongod is grabbing 6.6Gb memory currently (see attached ps_mem.log)
   - mongo logs database is around 3.3 Gb of that memory consumption (see attached mongodb.log)

While we don't expect customers to set landscape debug-juju feature flag, this represents that customers will be unable to tune juju logging configs and expect to keep their autopilot deployed cloud running.

@Chad Smith (chad.smith),

We are aware of the residual and minor memory leaks in 2.1. The workaround for these is to restart jujud occasionally via cron job. Majority of improvements did go into 2.1.x, hence, the Fix Released status on this report.

These are being fixed in Juju 2.2. The fix requires a dependent websocket library update and will not be backported to previous Juju versions. We are tracking the progress of this work through bug # 1649719.

If you are experiencing further memory leaks with 2.2x, please file a separate bug rather than morph this one.