Closed Bug 1291940 Opened 8 years ago Closed 6 years ago

TaskCluster slows down considerably when using AUFS

Categories

(Taskcluster :: Workers, defect, P1)

Product:
Taskcluster
Component:
Workers
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: gps, Assigned: wcosta)

References

(Blocks 2 open bugs)

Details

In bug 1290282, I was investigating some oddities where c4.8xlarge instances barely had any performance wins over c3.4xlarge instances on TC Firefox build tasks despite having 2x the number of CPU cores.

I knew something was wrong after garndt posted dstat output while `mach build` was doing some heavy compilation:

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
 10   5  83   3   0   0| 705k   16M|   0     0 |   0     0 |  18k   43k
 39  15  42   4   0   0|   0    25M|  42k   44k|   0     0 |  52k  106k
 36   8  29  28   0   0|4096B   21M|  35k   34k|   0     0 |  38k   68k
 47   9  43   1   0   0|   0  4728k|  54k   56k|   0     0 |  48k   96k
 45  14  41   0   0   0|   0    28k|  25k   25k|   0     0 |  46k   93k
 42  14  44   0   0   0|   0    20k|  74k   74k|   0     0 |  53k  104k
 34  20  46   0   0   0|   0    36k|  77k   76k|   0     0 |  57k  111k
 35  19  45   0   0   0|   0  1376k|  53k   52k|   0     0 |  53k  104k
 37  20  43   0   0   0|   0  9456k|  79k   82k|   0     0 |  54k  104k
 28  27  46   0   0   0|   0    36k|  82k   81k|   0     0 |  54k  105k
 31  24  45   0   0   0|   0  8192B|  41k   41k|   0     0 |  51k   99k
 40  18  42   0   0   0|   0    28k|  44k   43k|   0     0 |  50k   97k
 36  21  42   0   0   0|   0  1444k| 135k  139k|   0     0 |  45k   88k
 33  21  46   1   0   0|   0    21M| 105k  100k|   0     0 |  47k   92k
 27  26  47   0   0   0|   0  2020k| 129k  132k|   0     0 |  52k  103k
 38  19  43   0   0   0|   0    32k|  90k   92k|   0     0 |  50k   96k

Note the very high sys (kernel) CPU usage and number of context switches. For comparison, here's what I got on a non-TC c4.8xlarge instance doing the same operation:

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
 93   6   1   0   0   0|   0    41M| 660B  832B|   0     0 |9801  4182
 92   7   1   0   0   0|   0  7320k|2016B   13k|   0     0 |9596  7047
 93   7   1   0   0   0|   0  8888k|2310B   10k|   0     0 |9567  4825
 91   8   1   0   0   0|   0  9248k|2574B   11k|   0     0 |9798  6004
 93   7   1   0   0   0|   0  7464k| 924B 3044B|   0     0 |9530  4706
 94   6   0   0   0   0|   0   102M| 198B  730B|   0     0 |  10k 4105
 94   5   1   0   0   0|   0   105M|1386B 8132B|   0     0 |  12k 7619
 92   7   1   0   0   0|   0    16M|1716B 6180B|   0     0 |9710  8397
 93   6   0   0   0   0|   0  4096k| 396B 1220B|   0     0 |9570  5332

The sys numbers are still a bit high for my liking. But context switches are *way* down, dare I say reasonable.

The TC team stood up a docker worker and gave me SSH access to investigate.

I initially thought OS and kernel differences might be to blame. My instance was running Ubuntu 16.04 (Linux 4.4). TC was running Ubuntu 14.04 (Linux 3.13) and had a number of outdated system packages. Upgrading system packages (including the kernel) and rebooting appeared to make things a bit faster. Although I would have to measure again to confirm.

I built Firefox from source outside of Docker and both my instance and TC instance had remarkably similar times:

  5:04 wall vs   5:03 wall
143:28 user vs 143:08 user
  9:18 sys  vs   9:29 sys

Inside Docker was a different story.

Building from a host-mounted ext4 volume was slightly slower:

  5:42 wall
136:49 user
 13:54 sys

But building from a Docker aufs volume was much slower:

  8:38 wall
132:19 user
 75:03 sys

dstat output during parts of the build was horrendous:

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
  9  82   9   0   0   0|   0    72k|3300B   15k|   0     0 |  20k   27k
  7  83  11   0   0   0|   0    64k|3366B   12k|   0     0 |  19k   29k
  3  88   9   0   0   0|   0    68k|1188B 5074B|   0     0 |  20k   29k
  5  86   9   0   0   0|   0    64k|  66B  358B|   0     0 |  25k   25k
 12  78  10   0   0   0|   0   576k|2574B   10k|   0     0 |  18k   27k
  6  80  14   0   0   0|   0    30M| 990B 3684B|   0     0 |  19k   28k
  4  91   4   0   0   0|   0    64k| 198B  722B|   0     0 |  21k   22k
  5  93   1   0   0   0|   0    64k| 132B  874B|   0     0 |  22k   21k
  9  85   6   0   0   0|   0    92k|2310B 8290B|   0     0 |  19k   26k
  4  87   9   0   0   0|   0  1316k| 198B  866B|   0     0 |  18k   25k
  3  95   3   0   0   0|   0    18M| 198B  714B|   0     0 |  21k   21k
  7  90   3   0   0   0|   0    64k| 990B 4310B|   0     0 |  17k   22k

95% CPU time in the kernel!!!

So it appears aufs under high load is a steaming pile. This shouldn't come as a surprise - aufs is an abandoned project and overlayfs is the equivalent technology that's part of the Linux kernel.

So where does this leave us? Well, TaskCluster is using aufs heavily in production. My understanding is that unless a cache is declared (caches use volumes mounted from the host and are backed by ext4), your I/O inside a TC task will be using aufs. And if aufs has performance problems, well, TC tasks will be slow.

The good news is a *lot* of Firefox automation uses caches (read: no aufs), so the negative impact of aufs is mitigated a bit. However, caches are stripped on most Try tasks because of concerns over cache poisoning. So e.g. a TC Firefox build will use ext4 on mozilla-central but aufs on Try. That means Try tasks will be slower than non-Try tasks. In theory, this applies to non-build tasks as well.

A potential silver lining is that the aufs performance degradation might only be for large CPU counts driving high concurrent I/O loads. In bug 1290282, c3.4xlarge instances were faster than c3.2xlarge instances (not linear as expected but still pretty good) whereas c3.8xlarge hardly had any advantage over c3.4xlarge despite double the cores. I'll have to run some tests on less beefy instances to see if aufs overhead is measurable on e.g. 1, 2, and 4 core instances, which make up most of the instances in TC. If it is, then this performance problem could result in thousands of hours of wasted machine time every day.

Per discussion in #taskcluster, jonasfj and garndt have ideas for addressing this at the worker level. I'll let them chime in.
We currently build on c3.2xlarge instances on an Ubuntu 14.04 host. I decided to compare the performance of a build in a c4.2xlarge (8 vCPUs) instance from at the host level and inside a Docker aufs volume to quantify the impact aufs has on TC tasks today.

Host build (ext3):

 19:30 wall
138:54 user
  7:23 sys

Docker build (aufs):

 20:15 wall
138:50 user
  9:33 sys

There appears to be slight overhead to aufs on a c4.2xlarge (8 vCPUs). Although this was a sampling size of 1, so results could be within variance. FWIW, I did witness rather high sys CPU time during the "export" tier and during parts of the "compile" tier. But it wasn't as high as it is in the c4.8xlarge. (I suspect "export" tier is bad because that tier creates thousands of files and symlinks and is effectively a stress test for I/O writing.)

On a c4.4xlarge (16 vCPUs):

Host build (ext3):

 10:59 wall
141:54 user
  7:28 sys

Docker build (aufs):

 11:47 wall
140:32 user
 15:00 sys

sys time is higher with aufs. dstat output also shows sys CPU time was higher throughout this build compared to the c4.2xlarge. Still not as bad as c4.8xlarge. But noticeably worse than c4.2xlarge.

The good news is aufs impact on c4.2xlarge instances appears minimal (the 45s gap between native and aufs remained intact - although not sure how that happened with ~5 minutes more kernel time). But the impact isn't horrendous like with c4.8xlarge instances. Since we don't run many instances with more than 8 cores in TC (do we run any at all?), this hopefully means we don't have major, widespread performance issues on TC due to aufs.

The bad news is that until we address this underlying problem with aufs, running high vCPU instances in TC will have diminishing returns for many workloads. We'll get *some* wins. But they won't be as large as expected because aufs will eat the extra CPU. Put another way, running high vCPU instances is, to some extent, throwing money away. c4.4xlarge has an arguably tolerable amount of aufs overhead. But we should definitely avoid c4.8xlarge instances for the time being, as aufs could eat a lot of their extra CPU.
In #taskcluster yesterday, I stated that the excessive kernel time appears to have gone away in Ubuntu 16.04. I was wrong. Kernel overhead on a c4.8xlarge on Ubuntu 16.04 is *worse* than 14.04!

Ubuntu 14.04 aufs (from comment #0):

  8:38 wall
132:19 user
 75:03 sys

Ubuntu 16.04 aufs:

 20:53 wall
103:03 user
461:28 sys  !!!

Ubuntu 16.04 overlayfs:

  5:49 wall
135:32 user
  9:39 sys

Building outside of Docker yielded the same time as within Docker on overlayfs. That's an encouraging sign for overlayfs.
Did you use the overlay or overlay2 docker storage driver?
overlay with docker 1.10 (the Docker that ships with Ubuntu 16.04).
There has been some talk of mitigating the impact of aufs by using aggressively using Docker volumes (which are essentially bind mounted from the host filesystem). This is a good idea in theory. So let's put that to the test.

On the same c4.8xlarge Ubuntu 16.04 instance used in comment #2, building Firefox with a source directory and object directory volume bind mounted from the host but still using aufs for the Docker container:

Ubuntu 16.04 host volume + aufs container:

 10:09 wall
111:27 user
117:41 sys

As you can see, we're somewhere between native/overlayfs and full aufs despite avoiding aufs for the Firefox source and output.

What gives? My theory is that the *reads* to the aufs container filesystem by processes like python and gcc loading standard library modules and headers is triggering aufs overhead. So even though we do hardly any write I/O to aufs, aufs is still slowing us down by interfering with the read path. FWIW, dstat reported little to no disk reads during the build. This is presumably because everything was in the page cache. But apparently the page cache isn't good enough for aufs: it still interferes with reading.

It's looking more and more like avoiding aufs entirely is the only path forward.
I built with overlay2 and it has nearly identical performance as overlay.
Depends on: 1293395
Blocks: thunder-try
We have what looks like to be an intermittent failure related to aufs in bug 1295474.

garndt: given the performance and stability implications of running aufs, what is the timeline for not using aufs?
Blocks: 1295474
Flags: needinfo?(garndt)
Also note that bug 1256004 was also likely due to aufs, although we were able to work around it.
I don't have a timeline really, but i can say I can start looking into this soon with others.  I think making the changes is easy enough, it's then validating that everything continues running as expected that might take a little time.
Flags: needinfo?(garndt)
Assignee: nobody → garndt
FWIW, I tried switching my local dev environment to overlay2 and I'm running into what looks like bugs due to the filesystem not behaving like a filesystem should. So it looks like that storage driver is still buggy :/

I've used devicemapper with some success. However, it is *really* slow at creating new image layers compared to aufs and overlayfs, which is a big deal for my local development environment which reminds tons of Docker images frequently. However, I don't think this is a major issue for TC because it treats Docker images as tarballs and doesn't do any of the fancy layering foo.

The matrix at https://docs.docker.com/engine/userguide/storagedriver/selectadriver/ also seems to indicate devicemapper might be the least crappy storage driver.
that's really good to know.  Is it worth it to try overlay2 on the TC instances or is it just way too far gone to be of use?
Everything coming out of Docker seems to indicate overlayfs/overlay2 is the future. But if there are bugs in the filesystem, I'm inclined to write it off.

I should clarify my comment about layer creation being slow. It's like 1-3s instead of say 100ms. This likely won't matter unless you are building or pulling images with many layers.
Another option is btrfs.
I upgraded to Docker 1.12 and haven't yet reproduced the overlayfs bug I was seeing before. It's possible I wasn't actually running overlay2 on the machine encountering the issues referenced in comment #10.

Regarding btrfs, I'll have to give it another try. I think its layer generation is also a bit slow. But, again, we shouldn't care about this so much.
Ahh - the issue I was having with overlay was related to hard links (some processes were confused by the presence of hard links where hard links should not have been present). The docs at https://docs.docker.com/engine/userguide/storagedriver/overlayfs-driver/ indicate that "overlay" relied heavily on hard links and "overlay2" does not.

FWIW, the bottom of that page contains some nuggets about overlayfs, notably that open(2) doesn't conform to POSIX standards and rename(2) isn't supported either. Good times. A "real" filesystem like btrfs keeps sounding better and better.
UNIX domain sockets don't work with the overlay filesystem: https://github.com/docker/docker/issues/12080
garndt: I keep seeing people bit by AUFS bugs or performance issues. The problems aren't obvious because AUFS "just works" most of the time. I suspect the use of AUFS is a "silent killer" of overall performance on TaskCluster, especially on large-core instances (read: we're wasting money due to sub-optimal performance).

What's the story on transitioning off AUFS? Depending on the timeline, it may justify someone doing work to have tasks alert when they are doing obviously sub-optimal things on AUFS like not having the workspace be a cache. But that won't save us: frequently accessed files baked into the Docker image will still kill perf because they are hosted on AUFS. And Try tasks can't use caches easily, meaning they always get AUFS and are therefore slower.
Flags: needinfo?(garndt)
Sorry for the delayed response, I just returned from PTO and will be looking at this once I get caught up.  I will have to see where we are with other priority projects on our plate.  Last time I looked at this, I think I hit a rabbit hole of issues when trying to switch the fs drivers, but we can investigate with a new set of eyes.

I'm going to leave the ni? at least for a couple of days to keep it on my radar.
Switching ni? to wander, he will start looking into this.
Flags: needinfo?(garndt) → needinfo?(wcosta)
Component: Worker → Docker-Worker
Blocks: 1399895
Assignee: garndt → wcosta
Status: NEW → ASSIGNED
Flags: needinfo?(wcosta)
While I was hacking on bug 1415725, I cranked out a patch to switch docker-worker to overlay2. PR at https://github.com/taskcluster/docker-worker/pull/337.
Commit pushed to master at https://github.com/taskcluster/docker-worker

https://github.com/taskcluster/docker-worker/commit/feb14875f6dbee6cdbca619a280f4b56deeb398b
Upgrade to kernel 4.4 and use overlay2 storage driver

AUFS is the source of numerous performance problems and
filesystem consistency issues. Bug 1291940 has plenty of
details. The tl;dr is AUFS takes out a global kernel lock
for pretty much all I/O operations and concurrent I/O
grinds to a halt as you add more concurrency. Firefox builds
actually get slower as you use more cores. In addition, there
are consistency issues with AUFS that result in files randomly
not being evailable after write.

In this commit, I bump the kernel version from 3.13 to 4.4
(so overlayfs is usable), add support for the overlay2 storage
driver (added in Docker 1.12 - which we conveniently use),
and switch the default storage driver to overlay2.

The version of v4l2loopback was also bumped to the latest
in order to pull in fixes so it compiles with Linux 4.4.
wcosta just pushed this out ~2 hours ago. So all new worker instances should be using the new AMIs with Linux 4.4 and overlay2 storage driver.

I'm optimistic we'll see perfherder alerts as a result of this change. Could take a while for existing workers running AUFS to self-terminate, however.
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
https://treeherder.mozilla.org/perf.html#/graphs?series=mozilla-inbound,1445527,1,2&series=mozilla-inbound,1582370,1,2&series=mozilla-inbound,1446792,1,2 is showing a ~4 minute Linux64 opt build time drop for c4.4xlarge today. This will almost certainly generate a Perfherder alert once enough data comes in.
I rolled back AMIs today after a report of docker daemon failing to start in some instances. Connecting to a machine docker.log showed a failure to create logical volumes:

ls: cannot access /dev/nvme*n*: No such file or directory
umount: /dev/xvdb: not mounted
  No physical volume label read from /dev/xvdb
  Can't open /dev/xvdb exclusively.  Mounted filesystem?
  Unable to add physical volume '/dev/xvdb' to volume group 'instance_storage'.
  No physical volume label read from /dev/xvdb
  Can't open /dev/xvdb exclusively.  Mounted filesystem?
  Unable to add physical volume '/dev/xvdb' to volume group 'instance_storage'.
  No volume groups found
Creating logical volume 'instance_storage'
ls: cannot access /dev/nvme*n*: No such file or directory
umount: /dev/xvdb: not mounted

Tracking down the issue, the root cause was vgcreate trying to open /dev/xvdb exclusively and failing:
open /dev/xvdb exclusively open("/dev/xvdb", O_RDWR|O_EXCL|O_DIRECT|O_NOATIME) = -1 EBUSY (Device or resource busy)
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Today a made a new rolled out the images after some tests yesterday. The gecko-t-linux-xlarge it is only work type that showed the problem so far.
* Today I rolled out
Per IRC discussion, it looks like failures in gecko-t-linux-xlarge were due to using an older, buggy AMI. The new AMIs appear to "just work."

wcosta: can we resolve this bug now?
Flags: needinfo?(wcosta)
(In reply to Gregory Szorc [:gps] from comment #27)
> Per IRC discussion, it looks like failures in gecko-t-linux-xlarge were due
> to using an older, buggy AMI. The new AMIs appear to "just work."
> 
> wcosta: can we resolve this bug now?

I found one case with newest AMI where the error happened. I connected to the machine, and after I rebooted it, the error was gone. It feels like there is a very subtle race condition on docker daemon initialization that produces the wrong behavior once in a while. Not sure if we should close this bug and investigate in a follow-up one, as it seems not to affect production. The only downside is Papertrail backlog.
Flags: needinfo?(wcosta)
If the incidence rate is low, let's get a new bug on file.

FWIW, I think the way we create the volume (as part of docker's initialization routine) is kinda wonky. IMO this should be a one-time operation performed as part of launching the EC2 instance. But we can discuss this in another bug.
Status: REOPENED → RESOLVED
Closed: 7 years ago → 7 years ago
Resolution: --- → FIXED
The problem seems to get a lot more frequent once I added c5 instances.
Rolled back AMIs, as we won't take advantage of c5 instances and there still occasional bustage with other instances. Didn't reverted the patches, however.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
New AMIs got rolled out today. Workers are still recycling. But it looks like things will stick this time.
Status: REOPENED → RESOLVED
Closed: 7 years ago → 6 years ago
Resolution: --- → FIXED
Blocks: 1424461
Blocks: 1425493
Component: Docker-Worker → Workers
You need to log in before you can comment on or make changes to this bug.