STAT/LaunchMON occasionally hangs

[dongahn]

As noted #43, @lee218llnl: reported.

Occasionally I get hangs with STAT, particularly after running it multiple times. It appears to be in lmon__fe.cxx on line 4601 in a pthread_cond_timedwait. I don’t know if this is an actual affect or just a correlation, but it seems like if I subsequently attach TV to the job and detach TV, then I am able to attach again with STAT.

I have also seen hang-like behavior (looping) in cobo on cobo_connect_hostname. This also appears to happen if I aggressively attach/detach/attach STAT multiple times.

I suspect 1 is due to FIFO handling within jsrun but I need a simple reproducer to prove or disprove myself.

I suspect 2 is due to a problem with colocation service within jsrun, but I need a simple reproducer to prove or disprove myself.

[dongahn]

FYI -- had a success on Sierra (flux-framework/flux-core#1612). I didn't see this occasional hang so this might be as frequently as I thought.

[lee218llnl]

I just did an strace on a LMON hang and compared it to a working version. Here’s some relevant output in the hang case:

[pid 87230] ptrace(PTRACE_CONT, 86987, NULL, SIG_0) = 0
[pid 87230] open("", O_WRONLY) = -1 ENOENT (No such file or directory)
[pid 87230] open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 11
[pid 87230] fstat(11, {st_mode=S_IFREG|0644, st_size=2294, ...}) = 0
[pid 87230] fstat(11, {st_mode=S_IFREG|0644, st_size=2294, ...}) = 0
[pid 87230] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2000000a0000
[pid 87230] read(11, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 2294
[pid 87230] lseek(11, -1457, SEEK_CUR) = 837
[pid 87230] read(11, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 1457
[pid 87230] close(11) = 0
[pid 87230] munmap(0x2000000a0000, 4096) = 0
[pid 87230] fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
[pid 87230] mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2000000a0000
[pid 87230] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2294, ...}) = 0
[pid 87230] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)
[pid 87230] waitpid(-1, 0x7fffffffbb28, WNOHANG|WSTOPPED|__WCLONE) = 0

And in the case where it does not hang:

[pid 89922] ptrace(PTRACE_CONT, 89080, NULL, SIG_0) = 0
[pid 89922] open("/var/tmp/jsm.rzansel62.52649/1954/MPIR_PIPE_118.6.30.15.9.32.17398", O_WRONLY) = 11
[pid 89922] open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 12
[pid 89922] fstat(12, {st_mode=S_IFREG|0644, st_size=2294, ...}) = 0
[pid 89922] fstat(12, {st_mode=S_IFREG|0644, st_size=2294, ...}) = 0
[pid 89922] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2000000a0000
[pid 89922] read(12, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 2294
[pid 89922] lseek(12, -1457, SEEK_CUR) = 837
[pid 89922] read(12, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 1457
[pid 89922] close(12) = 0
[pid 89922] munmap(0x2000000a0000, 4096) = 0
[pid 89922] fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
[pid 89922] mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2000000a0000
[pid 89922] write(11, "1", 1) = 1
[pid 89922] close(11) = 0
[pid 89922] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2294, ...}) = 0
[pid 89922] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)
[pid 89922] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_TRAPPED, si_pid=89080, si_uid=52649, si_status=SIGTRAP, si_utime=2248, si_stime=5646} ---
[pid 89922] waitpid(-1, [{WIFSTOPPED(s) && WSTOPSIG(s) == SIGTRAP}], WNOHANG|WSTOPPED|__WCLONE) = 89080
[pid 89922] ptrace(PTRACE_PEEKUSER, 89080, r0, [0x1001e584]) = 0

For some reason in the hang case, it is trying to open an empty string filename “”. Is there perhaps a race condition between LMON expecting to get the appropriate /var/tmp/jsm.rzansel… file name and jsm actually generating it? Also, this appears to no longer be deterministic for me on rzansel. Gotta love non-determinism!

[dongahn]

Wow. Great info!

The MPIR_attach_fifo should have the path of the attach FIFO by the time LaunchMON attaches to jsrun. I highly suspect that jsrun does not generate correct FIFO path randomly.

Or you test case might try to attach to the hung job too early?

[lee218llnl]

With the testing I'm doing, MPI_Init() has already completed and it's usually 10 seconds into the application.

[dongahn]

OK. Good info. I will try to reproduce it.