sk_lookup + test_bprm = huge delay

sk_lookup + test_bprm = huge delay

[Alexei Starovoitov]

Hi KP, Lorenz,

I need your help to debug a huge delay I'm seeing while running the test_progs.

To debug it I've added the following printf-s:

diff --git a/tools/testing/selftests/bpf/prog_tests/test_bprm_opts.c
b/tools/testing/selftests/bpf/prog_tests/test_bprm_opts.c
index 2559bb775762..cdd2182c83a2 100644
--- a/tools/testing/selftests/bpf/prog_tests/test_bprm_opts.c
+++ b/tools/testing/selftests/bpf/prog_tests/test_bprm_opts.c
@@ -66,8 +66,10 @@ static int run_set_secureexec(int map_fd, int secureexec)
                 * If the value of TMPDIR is set, the bash command returns 10
                 * and if the value is unset, it returns 20.
                 */
+               null_fd = open("/dev/console", O_WRONLY);
+               dprintf(null_fd, "before_bash\n");
                execle("/bin/bash", "bash", "-c",
-                      "[[ -z \"${TMPDIR}\" ]] || exit 10 && exit 20", NULL,
+                      "echo running_bash > /dev/console;[[ -z
\"${TMPDIR}\" ]] || exit 10 && exit 20", NULL,
                       bash_envp);
                exit(errno);
        } else if (child_pid > 0) {

Then I do:
./test_progs -n 127
before_bash
running_bash
before_bash
running_bash
#127 test_bprm_opts:OK
Summary: 1/0 PASSED, 0 SKIPPED, 0 FAILED

and it takes a split second to execute. There is no visible delay.

But when I run it as:
./test_progs -n 98,127
#98 sk_lookup:OK
before_bash
// huge delay here
running_bash
before_bash
running_bash
#127 test_bprm_opts:OK
Summary: 2/46 PASSED, 0 SKIPPED, 0 FAILED

real    0m51.414s
user    0m0.808s
sys    0m35.731s

All 50 seconds are spent waiting after "before_bash" line is printed.
Something is drastically delaying execle("/bin/bash").

But replacing arg0 of "bash" with "sh" makes it fast !
execle("/bin/bash", "sh"
                               ^^ instead of "bash".
I cannot explain all this at all.

sk_lookup test doing some netns and forking "ip",
but why would that slow down "bash" startup time?
And why would bash start quickly if it thinks that it's name is "sh" ?

For giggles I've tried:
execle("/bin/bash", "foobar"
and it's also slow.

Crazy ideas are welcome :)

Re: sk_lookup + test_bprm = huge delay

[Alexei Starovoitov]

On Fri, Feb 26, 2021 at 5:59 PM Alexei Starovoitov
<alexei.starovoitov@gmail.com> wrote:
>
> Crazy ideas are welcome :)

So it was my .bashrc.
Something in it was causing a delay.
I've added this line to choke it for non-interactive shell:
[ -z "$PS1" ] && return