Error in mlx5dv_create_qp in the DC transport

[lyu]

Describe the bug

ucx_info and ucx_perftest reports dc_mlx5.c:329 UCX ERROR mlx5dv_create_qp(mlx5_0:1, DCI): failed: Invalid argument.

Steps to Reproduce

UCX version: UCT version=1.10.0 revision c7add93
UCX build config: --prefix=$PREFIX --enable-debug --enable-assertions --enable-params-check --enable-frame-pointer --enable-backtrace-detail

Setup and versions

• lsb_release -a:

LSB Version:	:core-4.1-aarch64:core-4.1-noarch
Distributor ID:	CentOS
Description:	CentOS Linux release 8.1.1911 (Core) 
Release:	8.1.1911
Codename:	Core

• ofed_info -s: MLNX_OFED_LINUX-5.1-0.6.6.0
• rpm -q rdma-core: rdma-core-51mlnx1-1.51066.aarch64
• rpm -q libibverbs: libibverbs-51mlnx1-1.51066.aarch64

Additional information (depending on the issue)

For ucx_info -d, this happens when it tries to print info about the dc_mlx5 transport.
For ucx_perftest, it happens when running any UCP test without any environment variable set.

All issues go away if I add --without-dc to the configure script.

This doesn't happen with UCX 1.9.0, dc transport will be enabled and work correctly.

This also doesn't happen when built against MLNX_OFED_LINUX-4.5-1.0.1.0 on another ThunderX2 machine, but it looks like dc is automatically disabled there.

[yosefe]

@lyu this is MLNX_OFED issue. Can you pls try MLNX_OFED 5.1-2 or higher?

[lyu]

@yosefe Sorry can't do, I don't have admin access.

[tonycurtis]

Similar issues here with TX2 and MLNX_OFED_LINUX-5.1-0.6.6.0

I just built UCX --without-dc for now.

[alex--m]

@yosefe it reproduces on the course setup in HUJI, which doesn't have MOFED (I can give you access to it, it's 4 hosts with CX3). Looks like UCX incorrectly detects DC is supported on the device when in fact it isn't, and fails the entire worker when DCT creation fails. This is still relevant to the current master branch.

BTW - a simpler workaround (without rebuilding UCX) would be setting UCX_TLS (this is what I do on that setup until this is resolved).

[yosefe]

@alex--m can you pls upload the output of "ucx_info -dvb" command, with UCX_LOG_LEVEL=data?

[alex--m]

[1629615907.871546] [mlx-stud-01:26236:0]           stats.c:861  UCX  TRACE statistics disabled
[1629615907.871566] [mlx-stud-01:26236:0]        memtrack.c:379  UCX  TRACE memtrack disabled
[1629615907.871587] [mlx-stud-01:26236:0]           debug.c:1197 UCX  DEBUG using signal stack 0x7f23d820d000 size 141824
[1629615907.884343] [mlx-stud-01:26236:0]            init.c:115  UCX  DEBUG /cs/labs/amnon/alexam02/ucg/ucx-orig/build"
#define UCX_MODULE_SUBDIR         "ucx"
#define VERSION                   "1.12"
#define restrict                  __restrict
#define test_MODULES              ":module"
#define ucm_MODULES               ""
#define ucs_MODULES               ""
#define uct_MODULES               ":ib:cma"
#define uct_cuda_MODULES          ""
#define uct_ib_MODULES            ""
#define uct_rocm_MODULES          ""
#define ucx_perftest_MODULES      ""
[1629615907.884543] [mlx-stud-01:26236:0]          module.c:251  UCX  DEBUG loading modules for uct
[1629615907.887885] [mlx-stud-01:26236:0]          module.c:180  UCX  TRACE loaded /cs/labs/amnon/alexam02/ucg/ucx-orig/build/lib/ucx/libuct_cma.so.0
[1629615907.888804] [mlx-stud-01:26236:0]             sys.c:1354 UCX  DEBUG failed to stat(/proc/self/ns/pid): No such file or directory
#
# Memory domain: posix
#     Component: posix
#             allocate: <= 8201860K
#           remote key: 40 bytes
#           rkey_ptr is supported
#
#      Transport: posix
#         Device: memory
#  System device: <unknown>
[1629615907.888919] [mlx-stud-01:26236:0]         uct_mem.c:106  UCX  TRACE allocating mm_recv_fifo: host memory length 8447 flags 0x3e0
[1629615907.888924] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method md
[1629615907.889126] [mlx-stud-01:26236:0]             sys.c:652  UCX  TRACE   detected huge page size: 2097152
[1629615907.889144] [mlx-stud-01:26236:0]        mm_posix.c:531  UCX  DEBUG   allocated posix shared memory at 0x7f23d81e8000 length 12288
[1629615907.889148] [mlx-stud-01:26236:0]         uct_mem.c:304  UCX  TRACE   allocated 12288 bytes at 0x7f23d81e8000 using posix
[1629615907.889193] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool mm_recv_desc: align 64, maxelems 4294967295, elemsize 8288
[1629615907.889203] [mlx-stud-01:26236:0]         uct_mem.c:106  UCX  TRACE allocating mm_recv_desc: host memory length 4259952 flags 0x3e0
[1629615907.889205] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method md
[1629615907.891300] [mlx-stud-01:26236:0]        mm_posix.c:326  UCX  DEBUG   shared memory mmap(addr=(nil), length=6291456, flags= HUGETLB, fd=5) failed: Invalid argument
[1629615907.891315] [mlx-stud-01:26236:0]        mm_posix.c:531  UCX  DEBUG   allocated posix shared memory at 0x7f23d70ba000 length 4263936
[1629615907.891319] [mlx-stud-01:26236:0]         uct_mem.c:304  UCX  TRACE   allocated 4263936 bytes at 0x7f23d70ba000 using posix
[1629615907.891332] [mlx-stud-01:26236:0]           mpool.c:218  UCX  DEBUG mpool mm_recv_desc: allocated chunk 0x7f23d70ba018 of 4263912 bytes with 512 elements
[1629615907.892341] [mlx-stud-01:26236:0]        mm_iface.c:603  UCX  DEBUG created mm iface 0x55873057f880 FIFO id 0xc0000000c000667c va 0x7f23d81e8000 size 12288 (128 x 64 elems)
#
#      capabilities:
[1629615907.892378] [mlx-stud-01:26236:0]             sys.c:1354 UCX  DEBUG failed to stat(/proc/self/ns/ipc): No such file or directory
#            bandwidth: 0.00/ppn + 12179.00 MB/sec
#              latency: 80 nsec
#             overhead: 10 nsec
#            put_short: <= 4294967295
#            put_bcopy: unlimited
#            get_bcopy: unlimited
#             am_short: <= 100
#             am_bcopy: <= 8256
#               domain: cpu
#           atomic_add: 32, 64 bit
#           atomic_and: 32, 64 bit
#            atomic_or: 32, 64 bit
#           atomic_xor: 32, 64 bit
#          atomic_fadd: 32, 64 bit
#          atomic_fand: 32, 64 bit
#           atomic_for: 32, 64 bit
#          atomic_fxor: 32, 64 bit
#          atomic_swap: 32, 64 bit
#         atomic_cswap: 32, 64 bit
#           connection: to iface
#      device priority: 0
#     device num paths: 1
#              max eps: inf
#       device address: 8 bytes
#        iface address: 8 bytes
#       error handling: ep_check
[1629615907.893258] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool mm_recv_desc destroyed
#
#
# Memory domain: sysv
#     Component: sysv
#             allocate: unlimited
#           remote key: 28 bytes
#           rkey_ptr is supported
#
#      Transport: sysv
#         Device: memory
#  System device: <unknown>
[1629615907.893367] [mlx-stud-01:26236:0]         uct_mem.c:106  UCX  TRACE allocating mm_recv_fifo: host memory length 8447 flags 0x3e0
[1629615907.893371] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method md
[1629615907.893378] [mlx-stud-01:26236:0]         mm_sysv.c:94   UCX  DEBUG   mm failed to allocate 8447 bytes with hugetlb
[1629615907.893411] [mlx-stud-01:26236:0]         uct_mem.c:304  UCX  TRACE   allocated 12288 bytes at 0x7f23d81e8000 using sysv
[1629615907.893440] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool mm_recv_desc: align 64, maxelems 4294967295, elemsize 8288
[1629615907.893445] [mlx-stud-01:26236:0]         uct_mem.c:106  UCX  TRACE allocating mm_recv_desc: host memory length 4259952 flags 0x3e0
[1629615907.893448] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method md
[1629615907.893476] [mlx-stud-01:26236:0]         mm_sysv.c:94   UCX  DEBUG   mm failed to allocate 4259952 bytes with hugetlb
[1629615907.893498] [mlx-stud-01:26236:0]         uct_mem.c:304  UCX  TRACE   allocated 4263936 bytes at 0x7f23d70ba000 using sysv
[1629615907.893511] [mlx-stud-01:26236:0]           mpool.c:218  UCX  DEBUG mpool mm_recv_desc: allocated chunk 0x7f23d70ba018 of 4263912 bytes with 512 elements
[1629615907.895105] [mlx-stud-01:26236:0]        mm_iface.c:603  UCX  DEBUG created mm iface 0x558730580230 FIFO id 0x30032 va 0x7f23d81e8000 size 12288 (128 x 64 elems)
#
#      capabilities:
#            bandwidth: 0.00/ppn + 12179.00 MB/sec
#              latency: 80 nsec
#             overhead: 10 nsec
#            put_short: <= 4294967295
#            put_bcopy: unlimited
#            get_bcopy: unlimited
#             am_short: <= 100
#             am_bcopy: <= 8256
#               domain: cpu
#           atomic_add: 32, 64 bit
#           atomic_and: 32, 64 bit
#            atomic_or: 32, 64 bit
#           atomic_xor: 32, 64 bit
#          atomic_fadd: 32, 64 bit
#          atomic_fand: 32, 64 bit
#           atomic_for: 32, 64 bit
#          atomic_fxor: 32, 64 bit
#          atomic_swap: 32, 64 bit
#         atomic_cswap: 32, 64 bit
#           connection: to iface
#      device priority: 0
#     device num paths: 1
#              max eps: inf
#       device address: 8 bytes
#        iface address: 8 bytes
#       error handling: ep_check
[1629615907.895401] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool mm_recv_desc destroyed
#
#
# Memory domain: self
#     Component: self
#             register: unlimited, cost: 0 nsec
#           remote key: 16 bytes
#
#      Transport: self
#         Device: memory0
#  System device: <unknown>
[1629615907.895471] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool self_msg_desc: align 64, maxelems 4294967295, elemsize 8200
[1629615907.895474] [mlx-stud-01:26236:0]            self.c:222  UCX  DEBUG created self iface id 0x251cca833a57c43e send_size 8192
#
#      capabilities:
#            bandwidth: 0.00/ppn + 6911.00 MB/sec
#              latency: 0 nsec
#             overhead: 10 nsec
#            put_short: <= 4294967295
#            put_bcopy: unlimited
#            get_bcopy: unlimited
#             am_short: <= 8K
#             am_bcopy: <= 8K
#               domain: cpu
#           atomic_add: 32, 64 bit
#           atomic_and: 32, 64 bit
#            atomic_or: 32, 64 bit
#           atomic_xor: 32, 64 bit
#          atomic_fadd: 32, 64 bit
#          atomic_fand: 32, 64 bit
#           atomic_for: 32, 64 bit
#          atomic_fxor: 32, 64 bit
#          atomic_swap: 32, 64 bit
#         atomic_cswap: 32, 64 bit
#           connection: to iface
#      device priority: 0
#     device num paths: 1
#              max eps: inf
#       device address: 0 bytes
#        iface address: 8 bytes
#       error handling: ep_check
[1629615907.895491] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool self_msg_desc destroyed
#
[1629615907.895542] [mlx-stud-01:26236:0]            sock.c:90   UCX  DEBUG ioctl(req=35093, ifr_name=ibp7s0d1) failed: Cannot assign requested address
[1629615907.895602] [mlx-stud-01:26236:0]            sock.c:90   UCX  DEBUG ioctl(req=35093, ifr_name=enp5s0f1) failed: Cannot assign requested address
#
# Memory domain: tcp
#     Component: tcp
#             register: unlimited, cost: 0 nsec
#           remote key: 16 bytes
#
[1629615907.896115] [mlx-stud-01:26236:0]            time.c:22   UCX  DEBUG measured arch clock speed: 2670000000.00 Hz
#      Transport: tcp
#         Device: ib0
#  System device: <unknown>
[1629615907.896132] [mlx-stud-01:26236:0]       tcp_iface.c:547  UCX  DEBUG using TCP port range: 0-0
[1629615907.896136] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool uct_tcp_iface_tx_buf_mp: align 64, maxelems 4294967295, elemsize 8205
[1629615907.896138] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool uct_tcp_iface_rx_buf_mp: align 64, maxelems 4294967295, elemsize 131090
[1629615907.898873] [mlx-stud-01:26236:0]           async.c:231  UCX  DEBUG added async handler 0x55873057cfe0 [id=4 ref 1] uct_tcp_iface_connect_handler() to hash
[1629615907.898994] [mlx-stud-01:26236:0]           async.c:509  UCX  DEBUG listening to async event fd 4 events 0x5 mode thread_spinlock
[1629615907.899005] [mlx-stud-01:26236:0]       tcp_iface.c:497  UCX  DEBUG tcp_iface 0x55873057d4b0: listening for connections (fd=4) on 10.164.164.101:54659
#
#      capabilities:
#            bandwidth: 6239.81/ppn + 0.00 MB/sec
#              latency: 5210 nsec
#             overhead: 50000 nsec
#            put_zcopy: <= 18446744073709551590, up to 6 iov
#  put_opt_zcopy_align: <= 1
#        put_align_mtu: <= 0
#             am_short: <= 8K
#             am_bcopy: <= 8K
#             am_zcopy: <= 64K, up to 6 iov
#   am_opt_zcopy_align: <= 1
#         am_align_mtu: <= 0
#            am header: <= 8037
#           connection: to ep, to iface
#      device priority: 1
#     device num paths: 1
#              max eps: 256
#       device address: 6 bytes
#        iface address: 2 bytes
#           ep address: 10 bytes
#       error handling: peer failure, ep_check, keepalive
[1629615907.901740] [mlx-stud-01:26236:0]       tcp_iface.c:772  UCX  DEBUG tcp_iface 0x55873057d4b0: destroying
[1629615907.901746] [mlx-stud-01:26236:0]           async.c:156  UCX  DEBUG removed async handler 0x55873057cfe0 [id=4 ref 1] uct_tcp_iface_connect_handler() from hash
[1629615907.901748] [mlx-stud-01:26236:0]           async.c:562  UCX  DEBUG removing async handler 0x55873057cfe0 [id=4 ref 1] uct_tcp_iface_connect_handler()
[1629615907.901903] [mlx-stud-01:26236:0]           async.c:582  UCX  TRACE waiting for 0x55873057cfe0 [id=4 ref 1] uct_tcp_iface_connect_handler() completion (called=0)
[1629615907.901908] [mlx-stud-01:26236:0]           async.c:171  UCX  DEBUG release async handler 0x55873057cfe0 [id=4 ref 0] uct_tcp_iface_connect_handler()
[1629615907.901913] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool uct_tcp_iface_rx_buf_mp destroyed
[1629615907.901916] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool uct_tcp_iface_tx_buf_mp destroyed
#
#      Transport: tcp
#         Device: eth0
#  System device: <unknown>
[1629615907.901970] [mlx-stud-01:26236:0]       tcp_iface.c:547  UCX  DEBUG using TCP port range: 0-0
[1629615907.901978] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool uct_tcp_iface_tx_buf_mp: align 64, maxelems 4294967295, elemsize 8205
[1629615907.901980] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool uct_tcp_iface_rx_buf_mp: align 64, maxelems 4294967295, elemsize 131090
[1629615907.902015] [mlx-stud-01:26236:0]           async.c:231  UCX  DEBUG added async handler 0x55873064bec0 [id=4 ref 1] uct_tcp_iface_connect_handler() to hash
[1629615907.902070] [mlx-stud-01:26236:0]           async.c:509  UCX  DEBUG listening to async event fd 4 events 0x5 mode thread_spinlock
[1629615907.902074] [mlx-stud-01:26236:0]       tcp_iface.c:497  UCX  DEBUG tcp_iface 0x55873057d4b0: listening for connections (fd=4) on 132.65.164.101:44115
#
#      capabilities:
#            bandwidth: 113.16/ppn + 0.00 MB/sec
#              latency: 5776 nsec
#             overhead: 50000 nsec
#            put_zcopy: <= 18446744073709551590, up to 6 iov
#  put_opt_zcopy_align: <= 1
#        put_align_mtu: <= 0
#             am_short: <= 8K
#             am_bcopy: <= 8K
#             am_zcopy: <= 64K, up to 6 iov
#   am_opt_zcopy_align: <= 1
#         am_align_mtu: <= 0
#            am header: <= 8037
#           connection: to ep, to iface
#      device priority: 0
#     device num paths: 1
#              max eps: 256
#       device address: 6 bytes
#        iface address: 2 bytes
#           ep address: 10 bytes
#       error handling: peer failure, ep_check, keepalive
[1629615907.902151] [mlx-stud-01:26236:0]       tcp_iface.c:772  UCX  DEBUG tcp_iface 0x55873057d4b0: destroying
[1629615907.902155] [mlx-stud-01:26236:0]           async.c:156  UCX  DEBUG removed async handler 0x55873064bec0 [id=4 ref 1] uct_tcp_iface_connect_handler() from hash
[1629615907.902157] [mlx-stud-01:26236:0]           async.c:562  UCX  DEBUG removing async handler 0x55873064bec0 [id=4 ref 1] uct_tcp_iface_connect_handler()
[1629615907.902258] [mlx-stud-01:26236:0]           async.c:582  UCX  TRACE waiting for 0x55873064bec0 [id=4 ref 1] uct_tcp_iface_connect_handler() completion (called=0)
[1629615907.902263] [mlx-stud-01:26236:0]           async.c:171  UCX  DEBUG release async handler 0x55873064bec0 [id=4 ref 0] uct_tcp_iface_connect_handler()
[1629615907.902266] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool uct_tcp_iface_rx_buf_mp destroyed
[1629615907.902269] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool uct_tcp_iface_tx_buf_mp destroyed
#
#      Transport: tcp
#         Device: lo
#  System device: <unknown>
[1629615907.902318] [mlx-stud-01:26236:0]       tcp_iface.c:547  UCX  DEBUG using TCP port range: 0-0
[1629615907.902324] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool uct_tcp_iface_tx_buf_mp: align 64, maxelems 4294967295, elemsize 8205
[1629615907.902327] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool uct_tcp_iface_rx_buf_mp: align 64, maxelems 4294967295, elemsize 131090
[1629615907.902365] [mlx-stud-01:26236:0]           async.c:231  UCX  DEBUG added async handler 0x55873064bec0 [id=4 ref 1] uct_tcp_iface_connect_handler() to hash
[1629615907.902421] [mlx-stud-01:26236:0]           async.c:509  UCX  DEBUG listening to async event fd 4 events 0x5 mode thread_spinlock
[1629615907.902425] [mlx-stud-01:26236:0]       tcp_iface.c:497  UCX  DEBUG tcp_iface 0x55873057d4b0: listening for connections (fd=4) on 127.0.0.1:46701
#
#      capabilities:
[1629615907.902442] [mlx-stud-01:26236:0]            sock.c:90   UCX  DEBUG ioctl(req=35142, ifr_name=lo) failed: Operation not supported
[1629615907.902461] [mlx-stud-01:26236:0]         tcp_net.c:61   UCX  DEBUG speed of lo is UNKNOWN, assuming 100 Mbps
#            bandwidth: 11.91/ppn + 0.00 MB/sec
#              latency: 10960 nsec
#             overhead: 50000 nsec
#            put_zcopy: <= 18446744073709551590, up to 6 iov
#  put_opt_zcopy_align: <= 1
#        put_align_mtu: <= 0
#             am_short: <= 8K
#             am_bcopy: <= 8K
#             am_zcopy: <= 64K, up to 6 iov
#   am_opt_zcopy_align: <= 1
#         am_align_mtu: <= 0
#            am header: <= 8037
#           connection: to ep, to iface
#      device priority: 1
#     device num paths: 1
#              max eps: 256
#       device address: 18 bytes
#        iface address: 2 bytes
#           ep address: 10 bytes
#       error handling: peer failure, ep_check, keepalive
[1629615907.902523] [mlx-stud-01:26236:0]       tcp_iface.c:772  UCX  DEBUG tcp_iface 0x55873057d4b0: destroying
[1629615907.902527] [mlx-stud-01:26236:0]           async.c:156  UCX  DEBUG removed async handler 0x55873064bec0 [id=4 ref 1] uct_tcp_iface_connect_handler() from hash
[1629615907.902529] [mlx-stud-01:26236:0]           async.c:562  UCX  DEBUG removing async handler 0x55873064bec0 [id=4 ref 1] uct_tcp_iface_connect_handler()
[1629615907.902592] [mlx-stud-01:26236:0]           async.c:582  UCX  TRACE waiting for 0x55873064bec0 [id=4 ref 1] uct_tcp_iface_connect_handler() completion (called=0)
[1629615907.902595] [mlx-stud-01:26236:0]           async.c:171  UCX  DEBUG release async handler 0x55873064bec0 [id=4 ref 0] uct_tcp_iface_connect_handler()
[1629615907.902597] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool uct_tcp_iface_rx_buf_mp destroyed
[1629615907.902599] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool uct_tcp_iface_tx_buf_mp destroyed
#
[1629615907.902628] [mlx-stud-01:26236:0]      tcp_sockcm.c:215  UCX  DEBUG created tcp_sockcm 0x558730618df0
#
# Connection manager: tcp
#      max_conn_priv: 2064 bytes
[1629615907.902682] [mlx-stud-01:26236:0]          module.c:251  UCX  DEBUG loading modules for uct_ib
[1629615907.902951] [mlx-stud-01:26236:0]           ib_md.c:1588 UCX  TRACE opening IB device mlx5_0
[1629615907.917534] [mlx-stud-01:26236:0]    ib_mlx5dv_md.c:630  UCX  DEBUG mlx5dv_open_device(mlx5_0) failed: Bad file descriptor
[1629615907.917539] [mlx-stud-01:26236:0]           ib_md.c:1648 UCX  DEBUG mlx5_0: md open by 'uct_ib_mlx5_devx_md_ops' failed, trying next
[1629615907.929781] [mlx-stud-01:26236:0]       ib_device.c:554  UCX  DEBUG PF: mlx5_0 vendor_id: 0x15b3 device_id: 4113
[1629615907.929788] [mlx-stud-01:26236:0]    ib_mlx5dv_md.c:863  UCX  DEBUG checking for DC support on mlx5_0
[1629615907.937372] [mlx-stud-01:26236:0]    ib_mlx5dv_md.c:937  UCX  DEBUG DC is supported on mlx5_0
[1629615908.026471] [mlx-stud-01:26236:0]           async.c:231  UCX  DEBUG added async handler 0x55873064bf90 [id=4 ref 1] uct_ib_async_event_handler() to hash
[1629615908.026567] [mlx-stud-01:26236:0]           async.c:509  UCX  DEBUG listening to async event fd 4 events 0x1 mode thread_spinlock
[1629615908.026581] [mlx-stud-01:26236:0]       ib_device.c:668  UCX  DEBUG initialized device 'mlx5_0' (InfiniBand channel adapter) with 2 ports
[1629615908.027462] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.027478] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
[1629615908.027502] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool rcache_mp: align 8, maxelems 4294967295, elemsize 144
[1629615908.030501] [mlx-stud-01:26236:0]           async.c:231  UCX  DEBUG added async handler 0x5587307970a0 [id=8 ref 1] ucs_rcache_invalidate_handler() to hash
[1629615908.030515] [mlx-stud-01:26236:0]           async.c:509  UCX  DEBUG listening to async event fd 8 events 0x1 mode thread_spinlock
[1629615908.030711] [mlx-stud-01:26236:0]          module.c:251  UCX  DEBUG loading modules for ucm
[1629615908.030717] [mlx-stud-01:26236:0]           ib_md.c:1356 UCX  DEBUG mlx5_0: using registration cache
[1629615908.030849] [mlx-stud-01:26236:0]           ib_md.c:1554 UCX  TRACE mlx5_0: PCIe gen2 16x, effective throughput 6877.201 MB/s 57.690 Gb/s
[1629615908.030852] [mlx-stud-01:26236:0]           ib_md.c:1641 UCX  DEBUG mlx5_0: md open by 'uct_ib_mlx5_md_ops' is successful
[1629615908.043460] [mlx-stud-01:26236:0]            topo.c:100  UCX  DEBUG bus id 0x70000 doesn't exist. sys_dev = 0
[1629615908.043465] [mlx-stud-01:26236:0]       ib_device.c:1137 UCX  DEBUG mlx5_0 bus id 0:7:0.0 sys_dev 0
[1629615908.043468] [mlx-stud-01:26236:0]       ib_device.c:768  UCX  TRACE mlx5_0:2 is not active (state: 1)
[1629615908.043472] [mlx-stud-01:26236:0]       ib_device.c:1168 UCX  TRACE mlx5_0:2 does not support flags 0x0: Destination is unreachable
[1629615908.043562] [mlx-stud-01:26236:0]            topo.c:92   UCX  DEBUG bus id 0x70000 exists. sys_dev = 0
[1629615908.043566] [mlx-stud-01:26236:0]       ib_device.c:1137 UCX  DEBUG mlx5_0 bus id 0:7:0.0 sys_dev 0
[1629615908.043568] [mlx-stud-01:26236:0]       ib_device.c:768  UCX  TRACE mlx5_0:2 is not active (state: 1)
[1629615908.043570] [mlx-stud-01:26236:0]       ib_device.c:1168 UCX  TRACE mlx5_0:2 does not support flags 0x4: Destination is unreachable
[1629615908.043668] [mlx-stud-01:26236:0]            topo.c:92   UCX  DEBUG bus id 0x70000 exists. sys_dev = 0
[1629615908.043672] [mlx-stud-01:26236:0]       ib_device.c:1137 UCX  DEBUG mlx5_0 bus id 0:7:0.0 sys_dev 0
[1629615908.043674] [mlx-stud-01:26236:0]       ib_device.c:768  UCX  TRACE mlx5_0:2 is not active (state: 1)
[1629615908.043677] [mlx-stud-01:26236:0]       ib_device.c:1168 UCX  TRACE mlx5_0:2 does not support flags 0xc4: Destination is unreachable
[1629615908.043762] [mlx-stud-01:26236:0]            topo.c:92   UCX  DEBUG bus id 0x70000 exists. sys_dev = 0
[1629615908.043766] [mlx-stud-01:26236:0]       ib_device.c:1137 UCX  DEBUG mlx5_0 bus id 0:7:0.0 sys_dev 0
[1629615908.043768] [mlx-stud-01:26236:0]       ib_device.c:768  UCX  TRACE mlx5_0:2 is not active (state: 1)
[1629615908.043771] [mlx-stud-01:26236:0]       ib_device.c:1168 UCX  TRACE mlx5_0:2 does not support flags 0x0: Destination is unreachable
[1629615908.043848] [mlx-stud-01:26236:0]            topo.c:92   UCX  DEBUG bus id 0x70000 exists. sys_dev = 0
[1629615908.043851] [mlx-stud-01:26236:0]       ib_device.c:1137 UCX  DEBUG mlx5_0 bus id 0:7:0.0 sys_dev 0
[1629615908.043853] [mlx-stud-01:26236:0]       ib_device.c:768  UCX  TRACE mlx5_0:2 is not active (state: 1)
[1629615908.043856] [mlx-stud-01:26236:0]       ib_device.c:1168 UCX  TRACE mlx5_0:2 does not support flags 0x4: Destination is unreachable
[1629615908.043868] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.043876] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
#
# Memory domain: mlx5_0
#     Component: ib
#             register: unlimited, cost: 180 nsec
#           remote key: 24 bytes
#           local memory handle is required for zcopy
#
[1629615908.043903] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.043910] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
#      Transport: rc_verbs
#         Device: mlx5_0:1
#  System device: 0000:07:00.0 (0)
[1629615908.044005] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.044013] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
[1629615908.044485] [mlx-stud-01:26236:0]        ib_iface.c:858  UCX  DEBUG using pkey[0] 0xffff on mlx5_0:1
[1629615908.046011] [mlx-stud-01:26236:0]        ib_iface.c:1471 UCX  DEBUG created uct_ib_iface_t headroom_ofs 12 payload_ofs 12 hdr_ofs 11 data_sz 8256
[1629615908.046051] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool rc_recv_desc: align 64, maxelems 4294967295, elemsize 8276
[1629615908.046078] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool rc_send_desc: align 64, maxelems 4294967295, elemsize 8328
[1629615908.046118] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool send-ops-mpool: align 64, maxelems 4294967295, elemsize 56
[1629615908.048492] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool pending-ops: align 1, maxelems 4294967295, elemsize 64
[1629615908.048501] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool rc_verbs_short_desc: align 64, maxelems 4294967295, elemsize 200
[1629615908.053088] [mlx-stud-01:26236:0]        ib_iface.c:1001 UCX  DEBUG iface=0x558730592ed0: created RC QP 0x3370 on mlx5_0:1 TX wr:409 sge:5 inl:124 resp:64 RX wr:0 sge:0 resp:64
#
#      capabilities:
#            bandwidth: 6433.22/ppn + 0.00 MB/sec
#              latency: 700 + 1.000 * N nsec
#             overhead: 75 nsec
#            put_short: <= 124
#            put_bcopy: <= 8256
#            put_zcopy: <= 1G, up to 5 iov
#  put_opt_zcopy_align: <= 512
#        put_align_mtu: <= 4K
#            get_bcopy: <= 8256
#            get_zcopy: 65..1G, up to 5 iov
#  get_opt_zcopy_align: <= 512
#        get_align_mtu: <= 4K
#             am_short: <= 123
#             am_bcopy: <= 8255
#             am_zcopy: <= 8255, up to 4 iov
#   am_opt_zcopy_align: <= 512
#         am_align_mtu: <= 4K
#            am header: <= 127
#           connection: to ep
#      device priority: 20
#     device num paths: 1
#              max eps: 256
#       device address: 3 bytes
#           ep address: 4 bytes
#       error handling: peer failure, ep_check
[1629615908.057087] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool rc_verbs_short_desc destroyed
[1629615908.058710] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool send-ops-mpool destroyed
[1629615908.058715] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool rc_send_desc destroyed
[1629615908.058718] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool rc_recv_desc destroyed
[1629615908.058720] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool pending-ops destroyed
#
#
[1629615908.059759] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.059770] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
#      Transport: rc_mlx5
#         Device: mlx5_0:1
#  System device: 0000:07:00.0 (0)
[1629615908.059880] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.059889] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
[1629615908.060174] [mlx-stud-01:26236:0]        ib_iface.c:858  UCX  DEBUG using pkey[0] 0xffff on mlx5_0:1
[1629615908.060252] [mlx-stud-01:26236:0]       ib_device.c:1405 UCX  DEBUG max IB CQE size is 128
[1629615908.062659] [mlx-stud-01:26236:0]        ib_iface.c:1471 UCX  DEBUG created uct_ib_iface_t headroom_ofs 12 payload_ofs 12 hdr_ofs 10 data_sz 8256
[1629615908.062670] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool rc_recv_desc: align 64, maxelems 4294967295, elemsize 8276
[1629615908.062674] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool rc_send_desc: align 64, maxelems 4294967295, elemsize 8328
[1629615908.062717] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool send-ops-mpool: align 64, maxelems 4294967295, elemsize 56
[1629615908.064902] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool pending-ops: align 1, maxelems 4294967295, elemsize 64
[1629615908.064920] [mlx-stud-01:26236:0]         ib_mlx5.c:898  UCX  DEBUG SL=0 (AR support - unknown) was selected on mlx5_0:1, SLs with AR support = { <none> }, SLs without AR support = { <none> }
[1629615908.065015] [mlx-stud-01:26236:0]  rc_mlx5_common.c:737  UCX  DEBUG ibv_alloc_dm(dev=mlx5_0 length=2048) failed: Invalid argument
[1629615908.065020] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool rc_mlx5_atomic_desc: align 64, maxelems 4294967295, elemsize 80
#
#      capabilities:
#            bandwidth: 6433.22/ppn + 0.00 MB/sec
#              latency: 700 + 1.000 * N nsec
#             overhead: 40 nsec
#            put_short: <= 220
#            put_bcopy: <= 8256
#            put_zcopy: <= 1G, up to 14 iov
#  put_opt_zcopy_align: <= 512
#        put_align_mtu: <= 4K
#            get_bcopy: <= 8256
#            get_zcopy: 65..1G, up to 14 iov
#  get_opt_zcopy_align: <= 512
#        get_align_mtu: <= 4K
#             am_short: <= 234
#             am_bcopy: <= 8254
#             am_zcopy: <= 8254, up to 3 iov
#   am_opt_zcopy_align: <= 512
#         am_align_mtu: <= 4K
#            am header: <= 186
#           connection: to ep
#      device priority: 20
#     device num paths: 1
#              max eps: 256
#       device address: 3 bytes
#           ep address: 7 bytes
#       error handling: buffer (zcopy), remote access, peer failure, ep_check
[1629615908.065067] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool rc_mlx5_atomic_desc destroyed
[1629615908.066577] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool send-ops-mpool destroyed
[1629615908.066581] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool rc_send_desc destroyed
[1629615908.066584] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool rc_recv_desc destroyed
[1629615908.066586] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool pending-ops destroyed
#
#
[1629615908.067940] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.067951] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
#      Transport: dc_mlx5
#         Device: mlx5_0:1
#  System device: 0000:07:00.0 (0)
[1629615908.068093] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.068102] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
[1629615908.068407] [mlx-stud-01:26236:0]        ib_iface.c:858  UCX  DEBUG using pkey[0] 0xffff on mlx5_0:1
[1629615908.070270] [mlx-stud-01:26236:0]        ib_iface.c:1471 UCX  DEBUG created uct_ib_iface_t headroom_ofs 12 payload_ofs 12 hdr_ofs 10 data_sz 8256
[1629615908.070281] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool rc_recv_desc: align 64, maxelems 4294967295, elemsize 8276
[1629615908.070285] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool rc_send_desc: align 64, maxelems 4294967295, elemsize 8328
[1629615908.070333] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool send-ops-mpool: align 64, maxelems 4294967295, elemsize 56
[1629615908.072564] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool pending-ops: align 1, maxelems 4294967295, elemsize 112
[1629615908.072572] [mlx-stud-01:26236:0]         ib_mlx5.c:898  UCX  DEBUG SL=0 (AR support - unknown) was selected on mlx5_0:1, SLs with AR support = { <none> }, SLs without AR support = { <none> }
[1629615908.072719] [mlx-stud-01:26236:0]  rc_mlx5_common.c:737  UCX  DEBUG ibv_alloc_dm(dev=mlx5_0 length=2048) failed: Invalid argument
[1629615908.072724] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool rc_mlx5_atomic_desc: align 64, maxelems 4294967295, elemsize 80
[1629615908.072742] [mlx-stud-01:26236:0]         dc_mlx5.c:503  UCX  ERROR mlx5dv_create_qp(DCT) failed: Invalid argument
[1629615908.072764] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool rc_mlx5_atomic_desc destroyed
[1629615908.074284] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool send-ops-mpool destroyed
[1629615908.074288] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool rc_send_desc destroyed
[1629615908.074290] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool rc_recv_desc destroyed
[1629615908.074292] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool pending-ops destroyed
#   < failed to open interface >
#
[1629615908.075630] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.075639] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
#      Transport: ud_verbs
#         Device: mlx5_0:1
#  System device: 0000:07:00.0 (0)
[1629615908.075714] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.075721] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
[1629615908.076027] [mlx-stud-01:26236:0]        ib_iface.c:858  UCX  DEBUG using pkey[0] 0xffff on mlx5_0:1
[1629615908.077406] [mlx-stud-01:26236:0]        ib_iface.c:1471 UCX  DEBUG created uct_ib_iface_t headroom_ofs 88 payload_ofs 88 hdr_ofs 40 data_sz 4096
[1629615908.082621] [mlx-stud-01:26236:0]        ib_iface.c:1001 UCX  DEBUG iface=0x558730619880: created UD QP 0x3373 on mlx5_0:1 TX wr:341 sge:6 inl:124 resp:0 RX wr:4096 sge:1 resp:0
[1629615908.084415] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool ud_recv_skb: align 64, maxelems 4294967295, elemsize 4192
[1629615908.084424] [mlx-stud-01:26236:0]         uct_mem.c:106  UCX  TRACE allocating ud_recv_skb: host memory length 540784 flags 0x3e0
[1629615908.084427] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method huge
[1629615908.084433] [mlx-stud-01:26236:0]         uct_mem.c:283  UCX  TRACE   failed to allocate 540784 bytes from hugetlb: User-defined limit was reached
[1629615908.084435] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method thp
[1629615908.084468] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method md
[1629615908.084485] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG   mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.084494] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG   mlx5_0: rocm GPUDirect RDMA is disabled
[1629615908.084500] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method mmap
[1629615908.084512] [mlx-stud-01:26236:0]         uct_mem.c:304  UCX  TRACE   allocated 544768 bytes at 0x7f23d6c45000 using mmap
[1629615908.084521] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.084529] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
[1629615908.084561] [mlx-stud-01:26236:0]           mpool.c:218  UCX  DEBUG mpool rcache_mp: allocated chunk 0x7f23d79cf008 of 151544 bytes with 1052 elements
[1629615908.084974] [mlx-stud-01:26236:0]           ib_md.c:577  UCX  TRACE ibv_reg_mr(0x55873057cef0, 0x7f23d6c45000, 544768) took 0.256 msec
[1629615908.084980] [mlx-stud-01:26236:0]           ib_md.c:817  UCX  DEBUG registered memory 0x7f23d6c45000..0x7f23d6cca000 on mlx5_0 lkey 0x922b93 rkey 0x922b93 access 0xf flags 0x3e4
[1629615908.084992] [mlx-stud-01:26236:0]          rcache.c:945  UCX  TRACE mlx5_0: created region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] gt rw ref 2 lkey 0x922b93 rkey 0x922b93 atomic_rkey 0xffffffff
[1629615908.084997] [mlx-stud-01:26236:0]           mpool.c:218  UCX  DEBUG mpool ud_recv_skb: allocated chunk 0x7f23d6c45018 of 544744 bytes with 128 elements
[1629615908.085006] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool ud_tx_skb: align 64, maxelems 4294967295, elemsize 4168
[1629615908.085073] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x558730619880: adding gid fe80::f452:1403:18:8470 to hash on device mlx5_0 port 1 index 0)
[1629615908.085125] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x558730619880: adding gid fe80:: to hash on device mlx5_0 port 1 index 1)
[1629615908.085169] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x558730619880: adding gid fe80:: to hash on device mlx5_0 port 1 index 2)
[1629615908.085212] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x558730619880: adding gid fe80:: to hash on device mlx5_0 port 1 index 3)
[1629615908.085254] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x558730619880: adding gid fe80:: to hash on device mlx5_0 port 1 index 4)
[1629615908.085297] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x558730619880: adding gid fe80:: to hash on device mlx5_0 port 1 index 5)
[1629615908.085339] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x558730619880: adding gid fe80:: to hash on device mlx5_0 port 1 index 6)
[1629615908.085382] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x558730619880: adding gid fe80:: to hash on device mlx5_0 port 1 index 7)
[1629615908.085876] [mlx-stud-01:26236:0]     timer_wheel.c:41   UCX  DEBUG high res timer created log=23 resolution=3141.800749 usec wanted: 2500.000000 usec
#
#      capabilities:
#            bandwidth: 6433.22/ppn + 0.00 MB/sec
#              latency: 730 nsec
#             overhead: 105 nsec
#             am_short: <= 116
#             am_bcopy: <= 4088
#             am_zcopy: <= 4088, up to 5 iov
#   am_opt_zcopy_align: <= 512
#         am_align_mtu: <= 4K
#            am header: <= 3952
#           connection: to ep, to iface
#      device priority: 20
#     device num paths: 1
#              max eps: inf
#       device address: 3 bytes
#        iface address: 3 bytes
#           ep address: 6 bytes
#       error handling: peer failure, ep_check
[1629615908.085928] [mlx-stud-01:26236:0]        ud_iface.c:615  UCX  DEBUG iface(0x558730619880): cep cleanup
[1629615908.085931] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool ud_tx_skb destroyed
[1629615908.085938] [mlx-stud-01:26236:0]          rcache.c:331  UCX  TRACE mlx5_0: lru add region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] gt rw ref 2 lkey 0x922b93 rkey 0x922b93 atomic_rkey 0xffffffff
[1629615908.085943] [mlx-stud-01:26236:0]          rcache.c:419  UCX  TRACE mlx5_0: put region, flags 0x1 region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] gt rw ref 2 lkey 0x922b93 rkey 0x922b93 atomic_rkey 0xffffffff
[1629615908.085953] [mlx-stud-01:26236:0]          rcache.c:456  UCX  TRACE mlx5_0: invalidate region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] gt rw ref 1 lkey 0x922b93 rkey 0x922b93 atomic_rkey 0xffffffff
[1629615908.085962] [mlx-stud-01:26236:0]          rcache.c:419  UCX  TRACE mlx5_0: put region, flags 0xa region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] g- rw ref 1 lkey 0x922b93 rkey 0x922b93 atomic_rkey 0xffffffff
[1629615908.085966] [mlx-stud-01:26236:0]          rcache.c:430  UCX  TRACE mlx5_0: put on GC list region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] g- rw ref 0 lkey 0x922b93 rkey 0x922b93 atomic_rkey 0xffffffff
[1629615908.085992] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool ud_recv_skb destroyed
[1629615908.092124] [mlx-stud-01:26236:0]        ud_iface.c:622  UCX  DEBUG iface(0x558730619880): ptr_array cleanup
#
#
[1629615908.093127] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.093137] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
#      Transport: ud_mlx5
#         Device: mlx5_0:1
#  System device: 0000:07:00.0 (0)
[1629615908.093210] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.093218] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
[1629615908.093559] [mlx-stud-01:26236:0]        ib_iface.c:858  UCX  DEBUG using pkey[0] 0xffff on mlx5_0:1
[1629615908.094946] [mlx-stud-01:26236:0]        ib_iface.c:1471 UCX  DEBUG created uct_ib_iface_t headroom_ofs 88 payload_ofs 88 hdr_ofs 40 data_sz 4096
[1629615908.100203] [mlx-stud-01:26236:0]        ib_iface.c:1001 UCX  DEBUG iface=0x5587306175d0: created UD QP 0x3374 on mlx5_0:1 TX wr:341 sge:6 inl:124 resp:0 RX wr:4096 sge:1 resp:0
[1629615908.100213] [mlx-stud-01:26236:0]         ib_mlx5.c:577  UCX  DEBUG tx wq 65536 bytes [bb=64, nwqe=1024] mmio_mode bf_post
[1629615908.101347] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool ud_recv_skb: align 64, maxelems 4294967295, elemsize 4192
[1629615908.101352] [mlx-stud-01:26236:0]         uct_mem.c:106  UCX  TRACE allocating ud_recv_skb: host memory length 540784 flags 0x3e0
[1629615908.101355] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method huge
[1629615908.101359] [mlx-stud-01:26236:0]         uct_mem.c:283  UCX  TRACE   failed to allocate 540784 bytes from hugetlb: User-defined limit was reached
[1629615908.101362] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method thp
[1629615908.101387] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method md
[1629615908.101405] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG   mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.101414] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG   mlx5_0: rocm GPUDirect RDMA is disabled
[1629615908.101419] [mlx-stud-01:26236:0]         uct_mem.c:110  UCX  TRACE   trying allocation method mmap
[1629615908.101429] [mlx-stud-01:26236:0]         uct_mem.c:304  UCX  TRACE   allocated 544768 bytes at 0x7f23d6c45000 using mmap
[1629615908.101439] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: cuda GPUDirect RDMA is disabled
[1629615908.101446] [mlx-stud-01:26236:0]           ib_md.c:300  UCX  DEBUG mlx5_0: rocm GPUDirect RDMA is disabled
[1629615908.101455] [mlx-stud-01:26236:0]          rcache.c:375  UCX  TRACE mlx5_0: destroy region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] g- rw ref 0 lkey 0x922b93 rkey 0x922b93 atomic_rkey 0xffffffff
[1629615908.101565] [mlx-stud-01:26236:0]          rcache.c:345  UCX  TRACE mlx5_0: lru remove region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] g- rw ref 0 lkey 0x922b93 rkey 0x922b93 atomic_rkey 0xffffffff
[1629615908.101786] [mlx-stud-01:26236:0]           ib_md.c:577  UCX  TRACE ibv_reg_mr(0x55873057cef0, 0x7f23d6c45000, 544768) took 0.208 msec
[1629615908.101792] [mlx-stud-01:26236:0]           ib_md.c:817  UCX  DEBUG registered memory 0x7f23d6c45000..0x7f23d6cca000 on mlx5_0 lkey 0x922a90 rkey 0x922a90 access 0xf flags 0x3e4
[1629615908.101798] [mlx-stud-01:26236:0]          rcache.c:945  UCX  TRACE mlx5_0: created region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] gt rw ref 2 lkey 0x922a90 rkey 0x922a90 atomic_rkey 0xffffffff
[1629615908.101802] [mlx-stud-01:26236:0]           mpool.c:218  UCX  DEBUG mpool ud_recv_skb: allocated chunk 0x7f23d6c45018 of 544744 bytes with 128 elements
[1629615908.101810] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool ud_tx_skb: align 64, maxelems 4294967295, elemsize 4168
[1629615908.101871] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x5587306175d0: adding gid fe80::f452:1403:18:8470 to hash on device mlx5_0 port 1 index 0)
[1629615908.101916] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x5587306175d0: adding gid fe80:: to hash on device mlx5_0 port 1 index 1)
[1629615908.101958] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x5587306175d0: adding gid fe80:: to hash on device mlx5_0 port 1 index 2)
[1629615908.102000] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x5587306175d0: adding gid fe80:: to hash on device mlx5_0 port 1 index 3)
[1629615908.102042] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x5587306175d0: adding gid fe80:: to hash on device mlx5_0 port 1 index 4)
[1629615908.102083] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x5587306175d0: adding gid fe80:: to hash on device mlx5_0 port 1 index 5)
[1629615908.102125] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x5587306175d0: adding gid fe80:: to hash on device mlx5_0 port 1 index 6)
[1629615908.102167] [mlx-stud-01:26236:0]        ud_iface.c:398  UCX  DEBUG iface 0x5587306175d0: adding gid fe80:: to hash on device mlx5_0 port 1 index 7)
[1629615908.102173] [mlx-stud-01:26236:0]         ib_mlx5.c:898  UCX  DEBUG SL=0 (AR support - unknown) was selected on mlx5_0:1, SLs with AR support = { <none> }, SLs without AR support = { <none> }
[1629615908.102255] [mlx-stud-01:26236:0]     timer_wheel.c:41   UCX  DEBUG high res timer created log=23 resolution=3141.800749 usec wanted: 2500.000000 usec
#
#      capabilities:
#            bandwidth: 6433.22/ppn + 0.00 MB/sec
#              latency: 730 nsec
#             overhead: 80 nsec
#             am_short: <= 180
#             am_bcopy: <= 4088
#             am_zcopy: <= 4088, up to 3 iov
#   am_opt_zcopy_align: <= 512
#         am_align_mtu: <= 4K
#            am header: <= 132
#           connection: to ep, to iface
#      device priority: 20
#     device num paths: 1
#              max eps: inf
#       device address: 3 bytes
#        iface address: 3 bytes
#           ep address: 6 bytes
#       error handling: peer failure, ep_check
[1629615908.102287] [mlx-stud-01:26236:0]        ud_iface.c:615  UCX  DEBUG iface(0x5587306175d0): cep cleanup
[1629615908.102290] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool ud_tx_skb destroyed
[1629615908.102295] [mlx-stud-01:26236:0]          rcache.c:331  UCX  TRACE mlx5_0: lru add region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] gt rw ref 2 lkey 0x922a90 rkey 0x922a90 atomic_rkey 0xffffffff
[1629615908.102300] [mlx-stud-01:26236:0]          rcache.c:419  UCX  TRACE mlx5_0: put region, flags 0x1 region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] gt rw ref 2 lkey 0x922a90 rkey 0x922a90 atomic_rkey 0xffffffff
[1629615908.102307] [mlx-stud-01:26236:0]          rcache.c:456  UCX  TRACE mlx5_0: invalidate region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] gt rw ref 1 lkey 0x922a90 rkey 0x922a90 atomic_rkey 0xffffffff
[1629615908.102313] [mlx-stud-01:26236:0]          rcache.c:419  UCX  TRACE mlx5_0: put region, flags 0xa region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] g- rw ref 1 lkey 0x922a90 rkey 0x922a90 atomic_rkey 0xffffffff
[1629615908.102317] [mlx-stud-01:26236:0]          rcache.c:430  UCX  TRACE mlx5_0: put on GC list region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] g- rw ref 0 lkey 0x922a90 rkey 0x922a90 atomic_rkey 0xffffffff
[1629615908.102340] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool ud_recv_skb destroyed
[1629615908.107487] [mlx-stud-01:26236:0]        ud_iface.c:622  UCX  DEBUG iface(0x5587306175d0): ptr_array cleanup
#
[1629615908.108488] [mlx-stud-01:26236:0]           async.c:156  UCX  DEBUG removed async handler 0x5587307970a0 [id=8 ref 1] ucs_rcache_invalidate_handler() from hash
[1629615908.108493] [mlx-stud-01:26236:0]           async.c:562  UCX  DEBUG removing async handler 0x5587307970a0 [id=8 ref 1] ucs_rcache_invalidate_handler()
[1629615908.108505] [mlx-stud-01:26236:0]           async.c:582  UCX  TRACE waiting for 0x5587307970a0 [id=8 ref 1] ucs_rcache_invalidate_handler() completion (called=0)
[1629615908.108508] [mlx-stud-01:26236:0]           async.c:171  UCX  DEBUG release async handler 0x5587307970a0 [id=8 ref 0] ucs_rcache_invalidate_handler()
[1629615908.108520] [mlx-stud-01:26236:0]          rcache.c:375  UCX  TRACE mlx5_0: destroy region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] g- rw ref 0 lkey 0x922a90 rkey 0x922a90 atomic_rkey 0xffffffff
[1629615908.108615] [mlx-stud-01:26236:0]          rcache.c:345  UCX  TRACE mlx5_0: lru remove region 0x558730712010 [0x7f23d6c45000..0x7f23d6cca000] g- rw ref 0 lkey 0x922a90 rkey 0x922a90 atomic_rkey 0xffffffff
[1629615908.108709] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool rcache_mp destroyed
[1629615908.109097] [mlx-stud-01:26236:0]       ib_device.c:686  UCX  DEBUG destroying ib device mlx5_0
[1629615908.109129] [mlx-stud-01:26236:0]           async.c:156  UCX  DEBUG removed async handler 0x55873064bf90 [id=4 ref 1] uct_ib_async_event_handler() from hash
[1629615908.109133] [mlx-stud-01:26236:0]           async.c:562  UCX  DEBUG removing async handler 0x55873064bf90 [id=4 ref 1] uct_ib_async_event_handler()
[1629615908.109293] [mlx-stud-01:26236:0]           async.c:582  UCX  TRACE waiting for 0x55873064bf90 [id=4 ref 1] uct_ib_async_event_handler() completion (called=0)
[1629615908.109298] [mlx-stud-01:26236:0]           async.c:171  UCX  DEBUG release async handler 0x55873064bf90 [id=4 ref 0] uct_ib_async_event_handler()
[1629615908.111936] [mlx-stud-01:26236:0]          cma_md.c:46   UCX  DEBUG could not read '/proc/sys/kernel/yama/ptrace_scope' - assuming Yama security is not enforced
[1629615908.111963] [mlx-stud-01:26236:0]          cma_md.c:46   UCX  DEBUG could not read '/proc/sys/kernel/yama/ptrace_scope' - assuming Yama security is not enforced
#
# Memory domain: cma
#     Component: cma
#             register: unlimited, cost: 9 nsec
#
#      Transport: cma
#         Device: memory
#  System device: <unknown>
[1629615908.112023] [mlx-stud-01:26236:0]           mpool.c:101  UCX  DEBUG mpool uct_scopy_iface_tx_mp: align 64, maxelems 4294967295, elemsize 736
#
#      capabilities:
#            bandwidth: 0.00/ppn + 11145.00 MB/sec
#              latency: 80 nsec
#             overhead: 400 nsec
#            put_zcopy: unlimited, up to 16 iov
#  put_opt_zcopy_align: <= 1
#        put_align_mtu: <= 1
#            get_zcopy: unlimited, up to 16 iov
#  get_opt_zcopy_align: <= 1
#        get_align_mtu: <= 1
#           connection: to iface
#      device priority: 0
#     device num paths: 1
#              max eps: inf
#       device address: 8 bytes
#        iface address: 4 bytes
#       error handling: peer failure, ep_check
[1629615908.112047] [mlx-stud-01:26236:0]           mpool.c:155  UCX  DEBUG mpool uct_scopy_iface_tx_mp destroyed
#

[alex--m]

Also, this ibstat output may be helpful:

CA 'mlx5_0'
	CA type: MT4113
	Number of ports: 2
	Firmware version: 10.16.1020
	Hardware version: 0
	Node GUID: 0xf452140300188470
	System image GUID: 0xf452140300188470
	Port 1:
		State: Active
		Physical state: LinkUp
		Rate: 56
		Base lid: 13
		LMC: 0
		SM lid: 33
		Capability mask: 0x26516848
		Port GUID: 0xf452140300188470
		Link layer: InfiniBand
	Port 2:
		State: Down
		Physical state: Disabled
		Rate: 10
		Base lid: 65535
		LMC: 0
		SM lid: 0
		Capability mask: 0x26516848
		Port GUID: 0xf452140300188478
		Link layer: InfiniBand

[yosefe]

@alex--m i see there is a COnnect-IB card (which supports DC) and DC iface create does not have any error

[alex--m]

@yosefe this looks problematic (and also OMPI crashes during MPI_Init() on worker creation following a similar DCT failure):

[1629615908.072742] [mlx-stud-01:26236:0]         dc_mlx5.c:503  UCX  ERROR mlx5dv_create_qp(DCT) failed: Invalid argument

[yosefe]

@alex--m seems it could be issue with scatter-to-cqe initialization on DC
What is the version of rdma-core and kernel / MLNX_OFED in the machine?

[alex--m]

Kernel 5.4.81, no MOFED, rdma-core version unclear (no privs to check, ofed_info not installed) - any Ideas how to query?
I got this from ibstat, if it helps: /sbin/ibstat BUILD VERSION: 2.1.0 Build date: Dec 14 2018 07:54:41

P.S. I can help you or a member of your team to connect to those servers, if it helps.

[yosefe]

Kernel 5.4.81, no MOFED, rdma-core version unclear (no privs to check, ofed_info not installed) - any Ideas how to query?

rpm -q rdma-core
rpm -q libibverbs
rpm -q libmlx5

P.S. I can help you or a member of your team to connect to those servers, if it helps.

Yes can u pls send access info by mail?