Runc: too many mount/umount syscalls

Created on 29 Jul 2020 · 13Comments · Source: opencontainers/runc

I'm not sure this is the right place to discuss. We are observing high cpu usage by systemd init process[1]. After some digging, it is possible caused by many mount/umount syscalls. Is it because runc was be executed?[3] At same time there is no new pod be scheduled to this instance or be deleted. What is the purpose runc was executed in this case?

Thanks!

[1] high cpu usage init process.

[2]

/# mountsnoop
COMM             PID     TID     MNT_NS      CALL
exe              1774545 1774545 4026531840  mount("/proc/self/exe", "/var/run/docker/runtime-runc/moby/910fdb2d258cb4e4c504d1414c9c635074d64aa4554671123d4cc652c007dd2e/runc.GC2atV", "", MS_BIND, "") = 0
exe              1774545 1774545 4026531840  mount("", "/var/run/docker/runtime-runc/moby/910fdb2d258cb4e4c504d1414c9c635074d64aa4554671123d4cc652c007dd2e/runc.GC2atV", "", MS_RDONLY|MS_REMOUNT|MS_BIND, "") = 0
exe              1774545 1774545 4026531840  umount("/var/run/docker/runtime-runc/moby/910fdb2d258cb4e4c504d1414c9c635074d64aa4554671123d4cc652c007dd2e/runc.GC2atV", MNT_DETACH) = 0
exe              1774598 1774598 4026531840  mount("/proc/self/exe", "/var/run/docker/runtime-runc/moby/41d0d870275682fd5c20ada27dec21ac2302cc2d2c3064e719094870934e30fb/runc.4yGzla", "", MS_BIND, "") = 0
exe              1774598 1774598 4026531840  mount("", "/var/run/docker/runtime-runc/moby/41d0d870275682fd5c20ada27dec21ac2302cc2d2c3064e719094870934e30fb/runc.4yGzla", "", MS_RDONLY|MS_REMOUNT|MS_BIND, "") = 0
exe              1774598 1774598 4026531840  umount("/var/run/docker/runtime-runc/moby/41d0d870275682fd5c20ada27dec21ac2302cc2d2c3064e719094870934e30fb/runc.4yGzla", MNT_DETACH) = 0

[3]
nsenter was import from https://github.com/opencontainers/runc/blob/master/init.go#L10
mount syscall executed from https://github.com/opencontainers/runc/blob/master/libcontainer/nsenter/cloned_binary.c#L402

Additional information:
OS: ubuntu 18.04
GKE 1.14

Source

axot

All 13 comments

Is it possible caused by exec probe?

axot on 29 Jul 2020

Yes, if you run runc exec very frequently you will see mount and umount syscalls. These are necessary to protect against CVE-2019-5736 (see 0a8e4117e7f715d5fbeef398405813ce8e88558b and #1984 which added this logic). The solution is to create a sealed memfd and bind-mount it on top of /usr/bin/runc (runc detects this and will avoid copying if that is the case) -- but to do this you need to have some C code running at system startup.

cyphar on 30 Jul 2020

We could have mitigated the situation by remove exec probe currently. Any improve could do in runc side? In systemd, there are trying to add rate limit for sd_event.

axot on 30 Jul 2020

Hello, I also have high CPU usage by /lib/systemd/systemd --user and /sbin/init processes. I tried different perf command, but haven't seen such clear view CPU usage. Can you tell me how to record and view such CPU usage screen? Thank you.

cloud-66 on 3 Aug 2020

Hello @cloud-66, I think you need debug symbol for this, please following the instruction from https://wiki.ubuntu.com/Debug%20Symbol%20Packages

Once you have done, perform these commands,

# add debug symbol for systemd
$ apt install systemd-dbgsym

# record with call graph and sample rate here is 99Hz
$ perf record --call-graph=dwarf -F99 -p 1

# wait few seconds, check the report
$ perf report --stdio -G

axot on 4 Aug 2020

👍1

Yes, if you run runc exec very frequently you will see mount and umount syscalls.

Here's my finding repasted from https://github.com/kubernetes/kubernetes/issues/82440

Liveness probe period of 30 seconds, and readiness probe period of 5 seconds. However, I can see in pstree that a runc process is constantly spawned in any container that has probes defined.

It's reasonable to expect some syscall activity every exec probe period. It's also reasonable to expect a reduction in the number of syscalls per minute when exec probe period is longer (e.g. 30 seconds instead of 5 seconds). However, this is not a case. A mere presence of an exec probe causes a lot of syscalls and overall increased load on CPU, regardless of the exec probe period.

I suggest reading through https://github.com/kubernetes/kubernetes/issues/82440 where I provided a lot of data on the problem. I don't know if it's a Kubernetes or a Runc bug.

EDIT: Thanks for @cyphar for explaining it's not a Runc issue below! :heart:

Nowaker on 30 Sep 2020

👍1

(Copying this comment from the Kubernetes issue.)

Taking a quick look, https://github.com/kubernetes/kubernetes/issues/82440#issuecomment-534332237 is describing Kubernetes effectively spamming runc status (the output of which is the JSON blob described). I don't think it's directly related to opencontainers/runc#2532 (we don't do any mounts in runc status), but I'm also not sure why Kubernetes (or I guess containerd) is requesting the status so many times.

On the runc side of things, in theory runc events could be used instead of runc status to switch away from a polling model for getting container states, though I don't think runc events has all of the information you might need to replace runc status.

cyphar on 30 Sep 2020

👍1

@axot

Any improve could do in runc side? In systemd, there are trying to add rate limit for sd_event.

Not really. The mount setup was actually added to avoid other issues (we used to copy the binary rather than ro-mount it, which caused container and system memory usage to increase by 10MB each time you attached or configured a container). I am working on some kernel patches to remove the need for these protections (by blocking chained opens through a read-only fd), but they'd need to be merged first and then you'd need to upgrade as well.

cyphar on 30 Sep 2020

🎉1

@cyphar Good to hear that!

axot on 30 Sep 2020

I was about to post a program to create a bind-mount of a memfd (which would allow you to avoid this overhead) but I just figured out that you can't bind-mount memfds. Oops. :thinking:

cyphar on 30 Sep 2020

So, this is mostly not a problem in runc per se, but a problem in systemd which re-reads the proverbial mountinfo on every mount/umount.

The ultimate fix to that belongs in the kernel, and some work is being done in that direction (see https://lkml.org/lkml/2020/3/18/569) but we're not quite there yet.

In the meantime, systemd workarounds are being worked on -- if someone is interested to look into that, start from here: https://github.com/systemd/systemd/issues/15464