2

I get that docker has some overhead and I wouldn't expect it to be as fast as local bin, but 2 seconds overhead? It seems too much ... Once the container is running, the execution itself seems the same.

$ time docker-compose run --rm php-cli php -i > /dev/null
docker-compose run --rm php-cli php -i > /dev/null  0,43s user 0,07s system 23% cpu 2,107 total

$ time php -i > /dev/null
php -i > /dev/null  0,04s user 0,01s system 98% cpu 0,050 total

Even the simple docker hello-world takes more time than I would think is appropriate.

time docker run --rm hello-world > /dev/null
docker run --rm hello-world > /dev/null  0,07s user 0,02s system 9% cpu 0,869 total

I tried stracing the command and it hangs on wait4 most of the time (which I guess is waiting for the docker daemon response? I'm not a pro so please correct me), here is partial output if that helps https://pastebin.com/pdA63zBi.

Is this expected behavior or is something wrong with my setup?

EDIT: Here is a strace summary for clean php-cli image:

strace -tt -c -f -S time docker run --rm php:7.2-cli php -i > /dev/null
strace: Process 30557 attached
strace: Process 30558 attached
strace: Process 30559 attached
strace: Process 30560 attached
strace: Process 30561 attached
strace: Process 30562 attached
strace: Process 30563 attached
strace: Process 30565 attached
strace: Process 30566 attached
strace: Process 30567 attached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 71.53    0.039424          43       919       163 futex
 18.01    0.009927          47       211           pselect6
  6.56    0.003617          50        73           mmap
  1.27    0.000702           5       128           rt_sigaction
  0.41    0.000227           2       138           rt_sigprocmask
  0.34    0.000188           9        22           sigaltstack
  0.34    0.000188          17        11           gettid
  0.30    0.000165          14        12           munmap
  0.25    0.000138           4        38           mprotect
  0.22    0.000124          12        10           clone
  0.14    0.000076          76         1           readlinkat
  0.11    0.000062           1        87           sched_yield
  0.10    0.000053           3        17           openat
  0.09    0.000049           1        65           epoll_pwait
  0.09    0.000048           4        11           set_robust_list
  0.06    0.000032           3        10           epoll_ctl
  0.04    0.000024           1        34        10 read
  0.04    0.000020           3         6           fcntl
  0.03    0.000018           1        20           close
  0.02    0.000012          12         1           epoll_create1
  0.01    0.000006           3         2           lseek
  0.01    0.000004           0        13           fstat
  0.01    0.000004           0        48        47 newfstatat
  0.01    0.000003           0         7           write
  0.00    0.000002           0         5         2 connect
  0.00    0.000001           0         5           socket
  0.00    0.000001           0         3           getpeername
  0.00    0.000001           0         3           setsockopt
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         2         1 ioctl
  0.00    0.000000           0        10        10 access
  0.00    0.000000           0         2           getpid
  0.00    0.000000           0         1           shutdown
  0.00    0.000000           0         3           getsockname
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           getuid
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           sched_getaffinity
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           prlimit64
  0.00    0.000000           0         1           getrandom
------ ----------- ----------- --------- --------- ----------------
100.00    0.055116                  1928       233 total

If I run bash in it and then do the same inside the container, the futex syscall has almost no impact - it runs just fine.

||improve this question
  • you need to add -tt -f parameters to your strace to produce useful output (wait4 means it is waiting for some other process it spawned, but we don't know which one or what it is doing or how long is it taking without those options) – Matija Nalis Jun 7 '18 at 13:20
  • It is possible you have unneeded overhead within your docker image in addition to the overhead from docker process. Would need to see the Dockerfile for the image exhibiting issues to determine if that is the case. – GracefulRestart Jun 7 '18 at 21:27
  • @MatijaNalis: nice, I didn't know that option, nice :) As wgl discovered, it's mostly caused by futex. Any thoughts on that? – grongor Jun 9 '18 at 10:37
  • @GracefulRestart: I tried using using the clean php:7.2-cli image and although it is faster, it still exhibits the same behavior (startup takes a long time). I do have a lot of extensions and custom binaries, but nothing that should be significant. In the entrypoint there is a step-down from root via gosu, nothing else. – grongor Jun 9 '18 at 10:38
1

Executing a command from host to container will have it processed by the docker daemon.

If you exec -it [image ID] bash and then test the time:

$ docker exec -it php bash
root@0fddab587d30:/# time php -i > /dev/null

real    0m0.029s
user    0m0.011s
sys     0m0.018s

Running strace on the host, through dockerd to the container

$ strace -c -f -S name docker run -d --rm php:cli php -i > /dev/null
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.04    0.000073           7        10        10 access
  0.01    0.000025          25         1           arch_prctl
  0.04    0.000064          21         3           brk
  0.21    0.000359          45         8           clone
  0.09    0.000158           9        17           close
  0.02    0.000036           9         4         2 connect
  0.02    0.000027          27         1           epoll_create1
  0.04    0.000068          11         6           epoll_ctl
  3.97    0.006676          56       120           epoll_wait
  0.00    0.000000           0         1           execve
  0.03    0.000056          14         4           fcntl
  0.05    0.000082           6        13           fstat
 72.92    0.122754         128       959       161 futex
  0.00    0.000001           1         2           getpeername
  0.00    0.000000           0         1           getpid
  0.01    0.000022          22         1           getrandom
  0.00    0.000000           0         2           getsockname
  0.12    0.000199          22         9           gettid
  0.00    0.000004           4         1           getuid
  0.03    0.000044          22         2         1 ioctl
  0.01    0.000011           6         2           lseek
  0.78    0.001317          20        67           mmap
  0.49    0.000821          24        34           mprotect
  0.25    0.000427          39        11           munmap
  0.01    0.000013          13         1           open
  0.09    0.000154          11        14           openat
  0.02    0.000027          27         1           prlimit64
 17.57    0.029574          78       381           pselect6
  0.10    0.000166           7        23         6 read
  0.03    0.000046          46         1           readlinkat
  1.50    0.002522          20       128           rt_sigaction
  0.74    0.001241           9       132           rt_sigprocmask
  0.02    0.000032          32         1           sched_getaffinity
  0.30    0.000500          18        28           sched_yield
  0.10    0.000175          19         9           set_robust_list
  0.01    0.000025          25         1           set_tid_address
  0.00    0.000000           0         2           setsockopt
  0.19    0.000323          18        18           sigaltstack
  0.03    0.000044          11         4           socket
  0.13    0.000215           8        28        27 stat
  0.03    0.000049          10         5           write
------ ----------- ----------- --------- --------- ----------------
100.00    0.168330                  2056       207 total

And with running strace in the php:cli container the time is significantly less even with more syscalls, it seems the futex syscall is of concern here:

$ docker run -it --security-opt seccomp:unconfined php:cli bash
root@3bd1a83a2586:/# apt update && apt install strace

root@3bd1a83a2586:/# strace -c -f -S name php -i > /dev/null
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  4.38    0.000830          15        55        54 access
  0.03    0.000006           6         1           arch_prctl
  0.00    0.000000           0        15           brk
  2.73    0.000518           8        61           close
  0.00    0.000000           0         1           execve
  3.74    0.000708          12        61           fstat
  0.02    0.000003           0        18           futex
  0.00    0.000000           0         1           getcwd
  0.00    0.000000           0         2           getdents
  0.00    0.000000           0         3           getrandom
  0.00    0.000000           0         2           getrlimit
  0.00    0.000000           0         1         1 ioctl
  0.00    0.000000           0         2           lseek
  0.00    0.000000           0         5         1 lstat
  0.00    0.000000           0         1           madvise
 10.42    0.001974          14       145           mmap
  5.06    0.000959           9       108           mprotect
  0.24    0.000046           4        13           munmap
 10.34    0.001960          28        69         9 open
  3.45    0.000654          10        63           read
  0.00    0.000000           0        80           rt_sigaction
  0.00    0.000000           0         2           rt_sigprocmask
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           socket
  0.23    0.000043           7         6         4 stat
  0.00    0.000000           0         1           sysinfo
  0.00    0.000000           0         1           uname
 59.36    0.011250           4      3037           write
------ ----------- ----------- --------- --------- ----------------
100.00    0.018951                  3757        69 total
||improve this answer
  • Thanks for your time! Yeah, most of the time it hangs on the futex. The question now is why...and is it normal behavior? Can it be "fixed" somehow? It seems strange that 80% of time is spent on some lock, all the time. – grongor Jun 9 '18 at 10:33

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.