OOM killer causing the CI EOFError on linux recently

[yuyichao]

Real reason is the OOM killer (see the updated title and comment below)

Original post:

With the patch below (the /dev/tty part might not be necessary) I've got the following backtrace on a machine that can reproduce the EOFError issue (or what looks like it)

signal (8): Floating point exception
__gmp_exception at /usr/lib/libgmp.so (unknown line)
unknown function (ip: 1705129166)
__gmpz_powm at /usr/lib/libgmp.so (unknown line)
powermod at ./gmp.jl:424
powermod at ./gmp.jl:430
unknown function (ip: 1399079124)
jl_apply_generic at /home/yuyichao/project/julia/src/gf.c:1663
anonymous at ./test.jl:105
do_test_throws at ./test.jl:59
jl_apply_generic at /home/yuyichao/project/julia/src/gf.c:1663
do_call at /home/yuyichao/project/julia/src/interpreter.c:66
eval at /home/yuyichao/project/julia/src/interpreter.c:212
jl_toplevel_eval_flex at /home/yuyichao/project/julia/src/toplevel.c:539
jl_toplevel_eval_flex at /home/yuyichao/project/julia/src/toplevel.c:568
jl_load at /home/yuyichao/project/julia/src/toplevel.c:615
include at ./boot.jl:253
jl_apply_generic at /home/yuyichao/project/julia/src/gf.c:1663
runtests at /home/yuyichao/project/julia/test/testdefs.jl:198
unknown function (ip: 1711445219)
jl_apply_generic at /home/yuyichao/project/julia/src/gf.c:1663
jl_f_apply at /home/yuyichao/project/julia/src/builtins.c:473
anonymous at ./multi.jl:854
run_work_thunk at ./multi.jl:605
jl_apply_generic at /home/yuyichao/project/julia/src/gf.c:1663
anonymous at ./multi.jl:854
start_task at /home/yuyichao/project/julia/src/task.c:234
unknown function (ip: 0)

diff --git a/src/init.c b/src/init.c
index 06a58c7..a394b31 100644
--- a/src/init.c
+++ b/src/init.c
@@ -249,6 +249,12 @@ static int is_addr_on_stack(void *addr)

 void sigdie_handler(int sig, siginfo_t *info, void *context)
 {
+    int fd = open("/dev/tty", O_RDWR);
+    int oldfd1 = dup(1);
+    int oldfd2 = dup(2);
+    dup2(fd, 1);
+    dup2(fd, 2);
+    close(fd);
     if (sig != SIGINFO) {
         sigset_t sset;
         uv_tty_reset_mode();
@@ -269,6 +275,10 @@ void sigdie_handler(int sig, siginfo_t *info, void *context)
         sig != SIGINFO) {
         raise(sig);
     }
+    dup2(oldfd1, 1);
+    dup2(oldfd2, 2);
+    close(oldfd1);
+    close(oldfd2);
 }
 #endif

@@ -1201,6 +1211,9 @@ void jl_install_default_signal_handlers(void)
     sigemptyset(&act_die.sa_mask);
     act_die.sa_sigaction = sigdie_handler;
     act_die.sa_flags = SA_SIGINFO;
+    for (int i = 0;i < 32;i++) {
+        sigaction(i, &act_die, NULL);
+    }
     if (sigaction(SIGINFO, &act_die, NULL) < 0) {
         jl_errorf("fatal error: sigaction: %s\n", strerror(errno));
     }

[yuyichao]

Although I write it in the title, I could not grantee that this is the issue behind those failures.

Also, is there a reason SIGFPE is only handled for windows?

[tkelman]

Interesting. I've seen in gdb there is a sigfpe thrown during normal operation in the numbers test, but it's supposed to get caught and handled as a Julia exception I think.

[quinnj]

Possibly related to #11351?? (normally caught write error to read-only memory, except when run from include)

[tkelman]

If it's repeatable with a patch, can you try bisecting, applying the patch as needed at all steps?

[yuyichao]

Sorry I didn't notice that the signal handler was installed before my loop. Moving the loop to the front suppress the printing of SIGFPE. So I'm closing this for now.

The reason it is failing on my VPS is actually the OOM killer, which also sounds like a possible candidate for the CI failure. What's the configuration of the Linux CI and is there a memory log / dmesg for it?

[yuyichao]

This is what I see in the output of dmesg.

[7464878.811504] Out of memory: Kill process 18793 (julia) score 156 or sacrifice child
[7464878.811509] Killed process 18793 (julia) total-vm:9373516kB, anon-rss:656052kB, file-rss:2452kB

It happens on a machine with 4G of memory (although ~1G is used by other processes)

[tkelman]

We have had situations where the cause of the CI failure was probably hitting the OOM killer, but we were never absolutely positive about it. The resolution of some common-seeming failures at the time was to find some particular tests that allocated a large amount of memory and comment them out (we should find and move those to test/perf instead, or make a new test/torture directory).

Any suggestions for how to find out if travis is hitting an OOM killer, and/or make Julia give a better backtrace when it does? I suspect the VM's don't have much memory there, but don't know enough details to determine how to debug it. We could open an issue at travis-ci/travis-ci and ask for help.

[yuyichao]

Well, the OOM killer should leave a log in the kernel and dmesg at the end of the build should print it.

IIRC, the return code of the process also indicate whether the process is killed.

[tkelman]

Well it looks like instead of propagating the return code of child processes we're ending up with EOFError so something isn't working right. I've never used dmesg before but I'll make a test branch tk/dmesg where I output that at the end of Travis, see what happens.

[yuyichao]

Or if the full output of dmesg is too much. dmesg | grep -i kill should be enough.

It should print sth like

[7465405.462999] dhcpcd-run-hook invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
[7465405.463109]  [<ffffffff81172cc6>] ? oom_kill_process+0xbe/0x380
[7465405.463839] Out of memory: Kill process 19094 (julia) score 155 or sacrifice child
[7465405.463845] Killed process 19094 (julia) total-vm:9401780kB, anon-rss:654728kB, file-rss:1636kB

[tkelman]

OOM ahoy https://travis-ci.org/JuliaLang/julia/jobs/65200677

Time to bust out --track-allocation ?