can opal_progress() call opal_progress()? (test hanging in MPI_COMM_DUP)

[jsquyres]

An intel test is hanging in MPI_COMM_DUP (MPI_Keyval1_c and MPI_Keyval1_f), and the backtrace from one of the hung processes is a bit strange:

$ mpirun -np 4 --mca btl vader,self ./MPI_Keyval1_c
[...hangs...]

A snapshot backtrace from a hung process is:

(gdb) bt
#0  0x00002aaaaaafecb2 in opal_list_remove_first (list=0x773508) at ../opal/class/opal_list.h:670
#1  0x00002aaaaaaff885 in ompi_comm_request_progress () at communicator/comm_request.c:114
#2  0x00002aaaab1ad39e in opal_progress () at runtime/opal_progress.c:221
#3  0x00002aaaaab215a1 in ompi_request_default_test_all (count=1, requests=0x779d10, completed=0x7fffffffc00c, statuses=0x0) at request/req_test.c:214
#4  0x00002aaabbfa5095 in NBC_Progress (handle=0x7741d8) at nbc.c:326
#5  0x00002aaabbfa30ec in ompi_coll_libnbc_progress () at coll_libnbc_component.c:242
#6  0x00002aaaab1ad39e in opal_progress () at runtime/opal_progress.c:221
#7  0x00002aaaaab21d64 in ompi_request_wait_completion (req=0x773580) at ../ompi/request/request.h:397
#8  0x00002aaaaab21da2 in ompi_request_default_wait (req_ptr=0x7fffffffc180, status=0x0) at request/req_wait.c:40
#9  0x00002aaaaaaf636a in ompi_comm_set (ncomm=0x7fffffffc1f8, oldcomm=0x78ef60, local_size=0, local_ranks=0x0, remote_size=0, remote_ranks=0x0, attr=0x76d6f0, errh=0x619040 <ompi_mpi_errors_return>, copy_topocomponent=true, local_group=0x76cd10, remote_group=0x778820) at communicator/comm.c:122
#10 0x00002aaaaaaf84b2 in ompi_comm_dup_with_info (comm=0x78ef60, info=0x0, newcomm=0x7fffffffc3c8) at communicator/comm.c:988
#11 0x00002aaaaaaf83f6 in ompi_comm_dup (comm=0x78ef60, newcomm=0x7fffffffc3c8) at communicator/comm.c:969
#12 0x00002aaaaab4d2cf in PMPI_Comm_dup (comm=0x78ef60, newcomm=0x7fffffffc3c8) at pcomm_dup.c:63
#13 0x0000000000402ba0 in main (argc=1, argv=0x7fffffffc528) at MPI_Keyval1_c.c:454

Notes:

• ompi_comm_dup_with_info() is essentially waiting on a request that never completes. This seems to be the real issue. The only communication this test does is duping communicators.
• A secondary issue (only happened to be noticed by this snapshot backtrace): is opal_progress() allowed to call opal_progress()?

These 2 tests (the C and Fortran versions) are not hanging on the v2.x branch.

@bosilca @hjelmn

[bosilca]

It is difficult to see the problem only from this stack trace. Moreover, recursively calling opal_progress is not forbidden (especially in this particular context where we need to progress non-blocking non-PML requests).
@hjelmn I look at the ompi_comm_request_progress function, and I do not think there is a reason for it to exists. We have added completion callback to the requests to avoid having to register/unregister specialized progress functions.

[hjelmn]

yeah. was written before i knew about the callback. will update this soon

[jsquyres]

@hjelmn You made mention that you were going to update the request callback function. Have you had a chance to do so?

[sam6258]

I am seeing an issue in v3.0.x, v3.1.x, and master that resembles a similar stack trace as this issue, however the issue is with multi threaded support. When performing MPI_Comm_dup in a loop with threads, the problem is almost instantly reproducible.

The stack trace looks as follows:

Rank 0:

Thread 1 (Thread 0x100000047050 (LWP 151366)):
#0  0x00001000001de854 in pthread_spin_lock () from /lib64/libpthread.so.0
#1  0x0000100001f5d368 in mlx5_poll_cq_1 () from /lib64/libmlx5-rdmav2.so
#2  0x0000100002276ab8 in poll_device () from /u/smiller/ompi-v3.0.x/lib/openmpi/mca_btl_openib.so
#3  0x0000100002277a8c in btl_openib_component_progress () from /u/smiller/ompi-v3.0.x/lib/openmpi/mca_btl_openib.so
#4  0x0000100000528640 in opal_progress () from /u/smiller/ompi-v3.0.x/lib/libopen-pal.so.40
#5  0x00001000005317e4 in sync_wait_mt () from /u/smiller/ompi-v3.0.x/lib/libopen-pal.so.40
#6  0x00001000000e0a14 in ompi_request_default_wait () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#7  0x000010000015081c in ompi_coll_base_barrier_intra_two_procs () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#8  0x00001000038e5124 in ompi_coll_tuned_barrier_intra_dec_fixed () from /u/smiller/ompi-v3.0.x/lib/openmpi/mca_coll_tuned.so
#9  0x00001000000fb85c in PMPI_Barrier () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#10 0x0000000010000dc0 in main (argc=1, argv=0x3fffe401eeb8) at mt_comm_dup_hang.c:81

Rank 1:

Thread 3 (Thread 0x10001046f1d0 (LWP 151445)):
#0  0x00001000000c1df0 in ompi_comm_request_progress () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#1  0x0000100000528640 in opal_progress () from /u/smiller/ompi-v3.0.x/lib/libopen-pal.so.40
#2  0x00001000000e028c in ompi_request_default_test_all () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#3  0x00001000039d7f90 in NBC_Progress () from /u/smiller/ompi-v3.0.x/lib/openmpi/mca_coll_libnbc.so
#4  0x00001000039d673c in ompi_coll_libnbc_progress () from /u/smiller/ompi-v3.0.x/lib/openmpi/mca_coll_libnbc.so
#5  0x0000100000528640 in opal_progress () from /u/smiller/ompi-v3.0.x/lib/libopen-pal.so.40
#6  0x00001000005317e4 in sync_wait_mt () from /u/smiller/ompi-v3.0.x/lib/libopen-pal.so.40
#7  0x00001000000c12a0 in ompi_comm_nextcid () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#8  0x00001000000bb380 in ompi_comm_dup_with_info () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#9  0x00001000000bb420 in ompi_comm_dup () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#10 0x0000100000100ec4 in PMPI_Comm_dup () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#11 0x0000000010000e48 in runfunc (targ=0x100201c0 <thread_args>) at mt_comm_dup_hang.c:96
#12 0x00001000001d8728 in start_thread () from /lib64/libpthread.so.0
#13 0x000010000032d210 in clone () from /lib64/libc.so.6

Thread 2 (Thread 0x10001006f1d0 (LWP 151446)):
#0  0x00001000001ddd60 in pthread_cond_wait@@GLIBC_2.17 () from /lib64/libpthread.so.0
#1  0x00001000005317a4 in sync_wait_mt () from /u/smiller/ompi-v3.0.x/lib/libopen-pal.so.40
#2  0x00001000000c12a0 in ompi_comm_nextcid () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#3  0x00001000000bb380 in ompi_comm_dup_with_info () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#4  0x00001000000bb420 in ompi_comm_dup () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#5  0x0000100000100ec4 in PMPI_Comm_dup () from /u/smiller/ompi-v3.0.x/lib/libmpi.so.40
#6  0x0000000010000e48 in runfunc (targ=0x100201d0 <thread_args+16>) at mt_comm_dup_hang.c:96
#7  0x00001000001d8728 in start_thread () from /lib64/libpthread.so.0
#8  0x000010000032d210 in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x100000047050 (LWP 151367)):
#0  0x00001000001d9b34 in pthread_join () from /lib64/libpthread.so.0
#1  0x0000000010000d98 in main (argc=1, argv=0x3fffcd706188) at mt_comm_dup_hang.c:79

In opal/threads/wait_sync.c, it looks like we are stuck in the loop waiting on while(sync->count > 0) or opal_progress to exit. Rerunning a gdb capture of the stack traces will show opal_progress looping through the registered progress functions, so we know it is not a particular progress function that is hung.

A gist of the testcase can be found at: https://gist.github.com/sam6258/8233342cee7c0acc93d2c9ffbf18ba35

[jsquyres]

Recap:

• Back at the beginning of time, we have 2 CID allocation algorithms:
  • Single threaded: simple and fast, which is now what is used everywhere
  • Multi threaded: thread safe, iterative, and slow.

It looks like we're using the single threaded/fast one everywhere now. That may be a mistake.

We may need to go back to:

• Have both CID algorithms available at runtime
• Always choose the safe/correct algorithm (e.g., in THREAD_MULTIPLE runs, choose the slow/correct one)
• Allow the user to override to choose the fast one if they want (i.e., they can guarantee that they will never overlap multiple CID allocations) -- e.g., via info key, MCA var, MPIT, ...etc.

[ggouaillardet]

@jsquyres as far as I understand, we now only use the thread safe, iterative and slow algorithm.
At first glance, and with respect to CID allocation, I think this is now a requirement because of MPI_Comm_idup(), that adds similar restrictions than MPI_THREAD_MULTIPLE.
Some time ago, I prepared a PR to add a new framework, and MPI_THREAD_MULTIPLE value was passed to the components when they are open.

[bosilca]

There is an opportunity for these two issues not to be related. The original issue has not been updated for months (years), I will therefore assume it has been fixed.

Let me scale back this example to try to explain what I think is the problem. Duplicating a communicator involves 2 allreduce, one with MPI_MAX (to find a suitable cid) and one with MPI_MIN (to agree on it). These reductions are done sequentially on the same communicator. In single threaded everything goes smooth, the global order of these 2 allreduce is ALWAYS respected.

In multi-threaded cases, starting multiple duplications in same time will basically see a tuple of (max, mix) allreduce posted sequentially per dup, on the same communicator on each process. MPI requires that collectives are posted in the same order globally, but in a distributed system we have no way to enforce a global order between the tuple of allreduce from the dup operation. The current algorithm work just fine if the global order is respected, but fails when this is not the case, which is exactly the reported behavior: random deadlocks.

For a toy example that tries to mimic the behavior of multiple duplications, replace the runfunc from the previous gist with the following:

void *runfunc(void * args) {
    MPI_Request req;
    MPI_Status status;
    int myrank, mysize;

    MPI_Comm_rank(MPI_COMM_WORLD, &myrank);
    MPI_Comm_size(MPI_COMM_WORLD, &mysize);

    int old_value = myrank, new_value;
    int *sbuf = &old_value, *rbuf = &new_value;

    MPI_Iallreduce( sbuf, rbuf, 1, MPI_INT, MPI_MAX, MPI_COMM_WORLD, &req );
    MPI_Wait(&req, &status);
    assert( new_value == (mysize - 1) );

    MPI_Iallreduce( sbuf, rbuf, 1, MPI_INT, MPI_MIN, MPI_COMM_WORLD, &req );
    MPI_Wait(&req, &status);
    assert( new_value == 0 );

    pthread_exit(NULL);
}

So the problem of our cid selection in multithreaded cases is that we mix the reduces in a totally nondeterministic way.

I can see few solutions, but none trivial.

• have a tag range in the libnbc that for reductions accounts for the MPI_Op (for reductions the handle->tag should not be simply monotonically increasing per operation but instead monotonically increasing per collective and MPI_Op).
• add multiple internal communicators for collectives (2 in this case), first to avoid the current collision between the internal reduction and user posted iallreduce) and second to give a different communication context to the 2 allreduces (the max and the min will then be posted on 2 different internal communicators).

[ggouaillardet]

@bosilca @sam6258 I think this is an invalid example with respect to the standard.

MPI_Comm_dup() is a collective operation, and it is hence incorrect to invoke it on the same communicator (MPI_COMM_WORLD in this case) simultaneously on multiple threads.

makes sense ?

[sam6258]

I think @ggouaillardet is correct. I will have to re-evaluate the test case from which we wrote this small test case to see that it is not violating the standard. I added the necessary synchronization in runfunc to ensure two threads were not calling the same collective on COMM_WORLD at the same time, and the test case does not hang. Thanks Gilles! And everyone for looking into this.

[jsquyres]

Sounds like we can close this issue, then...?

[sam6258]

I will verify with our tester tomorrow and close if I see a violation of the standard in our original testcase. Thanks!

[bosilca]

This particular example is indeed incorrect, but replace the blocking dup with a non-blocking dup and we are back with a valid non-functional example.

[ggouaillardet]

@bosilca in order to avoid any confusion/misunderstanding, would you mind updating such a valid non-functional example ?

[bosilca]

What we need to emphasize is the non-determinism between internal steps of the operation itself. We can achieve this by changing the runfunc in the gist example by

/*   Thread function */
void *runfunc(void * args) {
    MPI_Comm comms[2];
    MPI_Request reqs[1] = {MPI_REQUEST_NULL};

    MPI_Comm_idup( MPI_COMM_WORLD, &comms[0], &reqs[0] );

    MPI_Waitall(1, reqs, MPI_STATUSES_IGNORE);

    MPI_Comm_free(&comms[0]);
    pthread_exit(NULL);
}

The question I couldn't find an answer to in the MPI Standard is if we are allowed to post 2 idup on the same communicator at the same time.