Univention Bugzilla – Bug 48976
Slow performance of (e.g.) ucr commits in UCS based docker containers.
Last modified: 2020-08-05 00:29:33 CEST
Why are our docker containers so slow? root@master10:~# time ucr commit /etc/pam.d/common-auth Multifile: /etc/pam.d/common-auth real 0m0,635s user 0m0,128s sys 0m0,028s root@master10:~# time univention-app shell etherpad-lite ucr commit /etc/pam.d/common-auth Multifile: /etc/pam.d/common-auth real 0m3,271s user 0m0,768s sys 0m0,184s root@master10:~# time bash -c 'ucr commit /etc/pam.d/common-auth; ucr commit /etc/pam.d/common-auth; ucr commit /etc/pam.d/common-auth' Multifile: /etc/pam.d/common-auth Multifile: /etc/pam.d/common-auth Multifile: /etc/pam.d/common-auth real 0m0,371s user 0m0,284s sys 0m0,072s root@master10:~# time univention-app shell etherpad-lite bash -c 'ucr commit /etc/pam.d/common-auth; ucr commit /etc/pam.d/common-auth; ucr commit /etc/pam.d/common-auth' Multifile: /etc/pam.d/common-auth Multifile: /etc/pam.d/common-auth Multifile: /etc/pam.d/common-auth real 0m6,818s user 0m0,772s sys 0m0,172s root@master10:~# time univention-app shell etherpad-lite ls -ld /etc/pam.d/common-auth -rw-r--r-- 1 root root 1522 Mar 1 07:16 /etc/pam.d/common-auth real 0m1,350s user 0m0,780s sys 0m0,188s
The timing always include the time required to enter the container and spawn a shell there. Try: univention-app shell etherpad-lite time ucr commit /etc/pam.d/common-auth
Yeah, that's why I ran the command trice, so you may compare the scaling. But it's a good idea to start the time in the container: root@master10:~# univention-app shell etherpad-lite bash -c 'time ucr commit /etc/pam.d/common-auth' Multifile: /etc/pam.d/common-auth real 0m1.203s ## best value of 5 attempts. user 0m0.316s sys 0m0.880s root@master10:~# time ucr commit /etc/pam.d/common-auth Multifile: /etc/pam.d/common-auth real 0m0,118s user 0m0,088s sys 0m0,024s
The 1st measurement of comment 2 ist very strange: more time is spend in the kernel than in user space. Ist this a c-p-error? In the other measurements the proportion is around 4:1. I wonder if cgroups mess up those measurements. Could you run: # time univention-app shell etherpad-lite bash -c 'time ucr commit /etc/pam.d/common-auth' Regarding the general question of this bug: "why are the containers slow?" I wonder if that's the case, and if true: for which workloads they are. I think they are bad at writing on layered storage. I remember OX telling me in a call that we should put directories that are often written to on an external volume. That suggests, that all that time is spent inside the docker process (and its syscalls), trying to figure out which device to write to and. Try this: # univention-app shell etherpad-lite bash -c 'time echo "foo" > /etc/foo' # univention-app shell etherpad-lite bash -c 'time echo "foo" > /$volume/foo'
> I wonder if cgroups mess up those measurements. > Could you run: > # time univention-app shell etherpad-lite bash -c 'time ucr commit /etc/pam.d /common-auth' Here you go: root@master10:~# time univention-app shell etherpad-lite bash -c 'time ucr commit /etc/pam.d/common-auth' Multifile: /etc/pam.d/common-auth real 0m2.088s user 0m0.264s sys 0m0.776s real 0m3,660s user 0m0,624s sys 0m0,100s > Regarding the general question of this bug: "why are the containers slow?" > I wonder if that's the case, and if true: for which workloads they are. Yeah, same here. Workload: Package installations. UCR commits. That's why I care. > I think they are bad at writing on layered storage Probably, that's why I opend this but.
> Try this: > > # univention-app shell etherpad-lite bash -c 'time echo "foo" > /etc/foo' Zero, because echo is quite fast ;-) root@master10:~# univention-app shell etherpad-lite bash -c 'time bash -c "echo foo > /etc/hosts"' real 0m0.003s user 0m0.000s sys 0m0.000s vs: root@master10:~# univention-app shell etherpad-lite bash -c 'time bash -c "ucr commit /etc/hosts"' Multifile: /etc/hosts real 0m1.199s user 0m0.328s sys 0m0.852s
I just used a python profiler and found the subprocess.Popen call in /usr/lib/python2.7/dist-packages/univention/config_registry/handler.py function "run_filter" slow. Looks like the close_fds=True option slows things down considerably (for each @%@ block): root@container:/# time python -c 'import subprocess; subprocess.call(["true"],stdin=subprocess.PIPE, stdout=subprocess.PIPE)' real 0m0.033s user 0m0.012s sys 0m0.004s root@container:/# time python -c 'import subprocess; subprocess.call(["true"],stdin=subprocess.PIPE, stdout=subprocess.PIPE, close_fds=True)' real 0m0.998s user 0m0.332s sys 0m0.648s Fixed in python3: root@member:/# time python3 -c 'import subprocess; subprocess.call(["true"],stdin=subprocess.PIPE, stdout=subprocess.PIPE, close_fds=True)' real 0m0.073s user 0m0.044s sys 0m0.000s It's about python2.7 inefficiently closing the full range of FDs: root@member:/# ulimit -n 1048576 root@member:/# ulimit -n 10 ## reduce it to test the effect root@member:/# time python -c 'import subprocess; subprocess.call(["true"],stdin=subprocess.PIPE, stdout=subprocess.PIPE, close_fds=True)' real 0m0.076s user 0m0.012s sys 0m0.012s