Significant slow down when executed in quick succession

[johnchen902]

When isolate --run is executed in quick succession, the later commands take sigificantly longer than the first.

To reproduce, save this as a shell script, run it, and check the real time (as output by time).

isolate --init
time isolate --run -- /usr/bin/echo 1
isolate --cleanup
isolate --init
time isolate --run -- /usr/bin/echo 2
isolate --cleanup

It is expected that all executions take roughly the same. However, the first execution takes around 0.05s and the second takes around 0.1s on my machine. On another machine the first execution also takes around 0.05s but the second takes at least 0.8s!

Both machine are x86_64 and running latest Arch Linux and isolate built from commit 7f55e36. The first machine (the less severe one) is using usual Arch Linux kernel 4.10.5. The second machine is inside lxc with linux-userns kernel 4.10.1.

[seirl]

I tried both of those on two different machines (archlinux and ubuntu 16.10 x86_64) multiple times and I can't reproduce your result at all. Do you get similar differences in user time? Can you compute the average wall time of 1000 runs, for instance?

[johnchen902]

User time is always 0.00. Wall time average is computed with this script, isolate.sh:

sumt1=0
sumt2=0
for ((i=1; i<=$ITERATIONS; i++)); do
    isolate --init >/dev/null
    /usr/bin/time -f %e -o /tmp/time1 isolate --run -- /usr/bin/echo 1 >/dev/null 2>/dev/null
    isolate --cleanup >/dev/null
    isolate --init >/dev/null
    /usr/bin/time -f %e -o /tmp/time2 isolate --run -- /usr/bin/echo 2 >/dev/null 2>/dev/null
    isolate --cleanup >/dev/null
    sumt1=$(echo $sumt1 + $(cat /tmp/time1) | bc)
    sumt2=$(echo $sumt2 + $(cat /tmp/time2) | bc)
    sleep $SLEEPTIME
done
echo sumt1 = $sumt1, sumt2 = $sumt2

On the first machine:

$ sudo env ITERATIONS=1000 SLEEPTIME=0.1 bash isolate.sh
sumt1 = 43.54, sumt2 = 99.61

On the second machine:

johnchen902@johnchen902 ~> sudo env ITERATIONS=100 SLEEPTIME=1 bash isolate.sh 
sumt1 = 4.34, sumt2 = 84.86

[johnchen902]

Seems like kernel just spent that much time tearing down namespaces before the child can be reaped, as demostrated by timing the following code and toggling the comments.

#define _GNU_SOURCE
#include <fcntl.h>
#include <sched.h>
#include <signal.h>
#include <sys/wait.h>
#include <unistd.h>
#define CHILD_STACK_SIZE (1 << 23)
static int fd[2];
static int child_main(void *param) { (void) param;
    // close(fd[1]);
    // execl("/usr/bin/true", "/usr/bin/true", NULL);
    return 0;
}
int main() {
    static int child_stack[CHILD_STACK_SIZE];
    int flags = SIGCHLD | CLONE_NEWCGROUP | CLONE_NEWIPC | CLONE_NEWNET
            | CLONE_NEWNS | CLONE_NEWPID | CLONE_NEWUTS ;
    pipe2(fd, O_CLOEXEC);
    clone(child_main, child_stack + CHILD_STACK_SIZE, flags, NULL);
    close(fd[1]);
    // char buf[1]; read(fd[0], buf, 1);
    // wait(NULL);
}

A special "init" program in the namespace may serve as a workaround, because we need not to wait for the init to die.

[gollux]

This is definitely a kernel issue. I do not think it matters much as average execution times in most contests are significantly higher than this delay, but if anybody feels it does matter, please reopen this issue and we shall investigate further.

[johnchen902]

When I opened this issue, it did matter because I want to run 20 tasks concurrently on the 0.8s machine (with >20 cores), and it is observed that such overhead cannot be parallelized.

Later I decided to roll my solution, which avoids destroying and recreating namespaces. As I no longer use isolate at all, it doesn't matter to me now.

[bblackham]

See further discussion and proposed workaround in issue #34.