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.
-tt -f
parameters to yourstrace
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