rdmacm sometimes hangs in finalize in Mellanox Jenkins

[jsquyres]

http://bgate.mellanox.com/jenkins/job/gh-ompi-master-pr/2638/console -- which is a Jenkins run off #1821 -- shows a problem that we've been seeing in a few Jenkins runs: the rdmacm CPC in the openib BTL hangs during finalize.

Here's the command that is run:

/var/lib/jenkins/jobs/gh-ompi-master-pr/workspace/ompi_install1/bin/mpirun -np 8 -bind-to core --report-state-on-timeout --get-stack-traces --timeout 600 -mca btl_openib_receive_queues P,65536,256,192,128:S,128,256,192,128:S,2048,1024,1008,64:S,12288,1024,1008,64:S,65536,1024,1008,64 -mca btl_openib_cpc_include rdmacm -mca pml ob1 -mca btl self,openib -mca btl_if_include mlx4_0:2 /var/lib/jenkins/jobs/gh-ompi-master-pr/workspace/ompi_install1/examples/hello_c

This warning comes up; I don't know if it's significant:

11:17:09 --------------------------------------------------------------------------
11:17:09 No OpenFabrics connection schemes reported that they were able to be
11:17:09 used on a specific port.  As such, the openib BTL (OpenFabrics
11:17:09 support) will be disabled for this port.
11:17:09 
11:17:09   Local host:           jenkins01
11:17:09   Local device:         mlx5_0
11:17:09   Local port:           1
11:17:09   CPCs attempted:       rdmacm
11:17:09 --------------------------------------------------------------------------

But then all procs have a backtrace like this during finalize:

11:27:13    Thread 1 (Thread 0x7ffff73e3700 (LWP 10492)):
11:27:13    #0  0x0000003d6980b5bc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
11:27:13    #1  0x00007fffeeb81c6d in rdmacm_endpoint_finalize (endpoint=0x7fbdb0) at connect/btl_openib_connect_rdmacm.c:1229
11:27:13    #2  0x00007fffeeb6cdeb in mca_btl_openib_endpoint_destruct (endpoint=0x7fbdb0) at btl_openib_endpoint.c:368
11:27:13    #3  0x00007fffeeb559b7 in opal_obj_run_destructors (object=0x7fbdb0) at ../../../../opal/class/opal_object.h:460
11:27:13    #4  0x00007fffeeb5ae97 in mca_btl_openib_del_procs (btl=0x748ed0, nprocs=1, procs=0x7fffffffc768, peers=0x802fa0) at btl_openib.c:1328
11:27:13    #5  0x00007fffeefb2159 in mca_bml_r2_del_procs (nprocs=8, procs=0x78bf60) at bml_r2.c:623
11:27:13    #6  0x00007fffee2ba612 in mca_pml_ob1_del_procs (procs=0x78bf60, nprocs=8) at pml_ob1.c:455
11:27:13    #7  0x00007ffff7ca4b94 in ompi_mpi_finalize () at runtime/ompi_mpi_finalize.c:333
11:27:13    #8  0x00007ffff7cd6fe1 in PMPI_Finalize () at pfinalize.c:47
11:27:13    #9  0x0000000000400890 in main (argc=1, argv=0x7fffffffcb38) at hello_c.c:24

@jladd-mlnx @artpol84 Can you look into this?

@larrystevenwise @bharatpotnuri Is this happening on the v2.x branch for iWARP?

@hppritcha Is this a v2.0.0 or v2.0.1 item? IIRC, rdmacm is a non-default CPC for IB, and you have to add a per-peer QP -- I thought we had this conversation before about a previous rdmacm CPC error: that we would push it to v2.0.1 (but then we didn't because it also affected iWARP). Is my memory correct?

[hjelmn]

I think I see where it could be going bad. A change awhile ago updated how rdmacm disconnect was done and it looks like there is one path that is not correctly handled. Have PR open to check this case.

[jladd-mlnx]

@hjelmn Which change was this?

[hjelmn]

If my PR passes then the responsible commit is b8af310 . Looks like it is only triggered when there are multiple ports. Testing did not indicate a problem until recently.

[hjelmn]

I think in the case of Mellanox Jenkins some endpoints may not have a rdmacm client object. If that happens then we block indefinitely waiting for a callback that will never happen.

[hjelmn]

@jladd-mlnx Will re-assign back to you guys if I am wrong in my analysis. Though I am about 99% sure at this time. Also, if you want udcm working over a router let me know. It is much better than rdmacm but needs some changes to support using the GID.

[bharatpotnuri]

@jsquyres I see the stall at MPI_Finalize with openmpi-2.0.0rc3 for iWARP. With ompi-2.0.0, Issue is seen intermittently with iwarp too.

[bharatpotnuri]

Here is the part of log showing imb test stall:

|                          | #---------------------------------------------------                          |
|                          | # Benchmarking Barrier                                                        |
|                          | # #processes = 42                                                             |
|                          | #---------------------------------------------------                          |
|                          |  #repetitions  t_min[usec]  t_max[usec]  t_avg[usec]                          |
|                          |     1000       205.09       205.25       205.20                                        |
|                          |                                                                               |
|                          | # All processes entering MPI_Finalize                                         |
|                          | MTT killed mpirun via SIGTERM                                                 |
| start_timestamp          | 1467265499                                                                    |
| start_timestamp_human    | Thu Jun 30 05:44:59 2016                                                      |
| submit_id                |                                                                               |
| test_build_section_name  | imb                                                                           |
| test_name                | IMB-MPI1                                                                      |
| variant                  | 1                                                                             |
|                          |                                                                               |
|                          |                                                                               |
+--------------------------+-------------------------------------------------------------------------------+

[bharatpotnuri]

Backtrace of a rank (looks same as the one in issue description):

(gdb) bt
#0  0x0000003116a0b5bc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007fe9df9d0958 in rdmacm_endpoint_finalize (endpoint=0x135a940) at connect/btl_openib_connect_rdmacm.c:1229
#2  0x00007fe9df9bbaf3 in mca_btl_openib_endpoint_destruct (endpoint=0x135a940) at btl_openib_endpoint.c:368
#3  0x00007fe9df9a49a7 in opal_obj_run_destructors (object=0x135a940) at ../../../../opal/class/opal_object.h:460
#4  0x00007fe9df9a9e72 in mca_btl_openib_del_procs (btl=0x12df530, nprocs=1, procs=0x7fff5f997808, peers=0x135a680)
    at btl_openib.c:1328
#5  0x00007fe9e423f104 in mca_bml_r2_del_procs (nprocs=42, procs=0x53d47e0) at bml_r2.c:623
#6  0x00007fe9df7724ad in mca_pml_ob1_del_procs (procs=0x53d47e0, nprocs=42) at pml_ob1.c:455
#7  0x00007fe9e98a6854 in ompi_mpi_finalize () at runtime/ompi_mpi_finalize.c:333
#8  0x00007fe9e98d60e9 in PMPI_Finalize () at pfinalize.c:47
#9  0x0000000000402050 in main (argc=2, argv=0x7fff5f997c88) at IMB.c:403
(gdb) info thread
  3 Thread 0x7fe9e85c1700 (LWP 2999)  0x00000031166df1b3 in poll () from /lib64/libc.so.6
  2 Thread 0x7fe9e7727700 (LWP 3000)  0x00000031166e8fd3 in epoll_wait () from /lib64/libc.so.6
* 1 Thread 0x7fe9e91dc700 (LWP 2991)  0x0000003116a0b5bc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0

[hjelmn]

Can you test with #1830 and see if it fixes the hang?