{"action":"created","issue":{"url":"https://api.github.com/repos/openucx/ucx/issues/1492","repository_url":"https://api.github.com/repos/openucx/ucx","labels_url":"https://api.github.com/repos/openucx/ucx/issues/1492/labels{/name}","comments_url":"https://api.github.com/repos/openucx/ucx/issues/1492/comments","events_url":"https://api.github.com/repos/openucx/ucx/issues/1492/events","html_url":"https://github.com/openucx/ucx/issues/1492","id":227756432,"number":1492,"title":"Hang when using polling fd","user":{"login":"artpol84","id":7534910,"avatar_url":"https://avatars2.githubusercontent.com/u/7534910?v=3","gravatar_id":"","url":"https://api.github.com/users/artpol84","html_url":"https://github.com/artpol84","followers_url":"https://api.github.com/users/artpol84/followers","following_url":"https://api.github.com/users/artpol84/following{/other_user}","gists_url":"https://api.github.com/users/artpol84/gists{/gist_id}","starred_url":"https://api.github.com/users/artpol84/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/artpol84/subscriptions","organizations_url":"https://api.github.com/users/artpol84/orgs","repos_url":"https://api.github.com/users/artpol84/repos","events_url":"https://api.github.com/users/artpol84/events{/privacy}","received_events_url":"https://api.github.com/users/artpol84/received_events","type":"User","site_admin":false},"labels":[{"id":138949041,"url":"https://api.github.com/repos/openucx/ucx/labels/bug","name":"bug","color":"fc2929","default":true}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":{"url":"https://api.github.com/repos/openucx/ucx/milestones/6","html_url":"https://github.com/openucx/ucx/milestone/6","labels_url":"https://api.github.com/repos/openucx/ucx/milestones/6/labels","id":1411834,"number":6,"title":"v1.2 - release","description":"Production release ","creator":{"login":"miked-mellanox","id":2255576,"avatar_url":"https://avatars0.githubusercontent.com/u/2255576?v=3","gravatar_id":"","url":"https://api.github.com/users/miked-mellanox","html_url":"https://github.com/miked-mellanox","followers_url":"https://api.github.com/users/miked-mellanox/followers","following_url":"https://api.github.com/users/miked-mellanox/following{/other_user}","gists_url":"https://api.github.com/users/miked-mellanox/gists{/gist_id}","starred_url":"https://api.github.com/users/miked-mellanox/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/miked-mellanox/subscriptions","organizations_url":"https://api.github.com/users/miked-mellanox/orgs","repos_url":"https://api.github.com/users/miked-mellanox/repos","events_url":"https://api.github.com/users/miked-mellanox/events{/privacy}","received_events_url":"https://api.github.com/users/miked-mellanox/received_events","type":"User","site_admin":false},"open_issues":10,"closed_issues":30,"state":"open","created_at":"2015-11-14T20:29:19Z","updated_at":"2017-05-11T14:56:30Z","due_on":"2017-05-31T07:00:00Z","closed_at":null},"comments":0,"created_at":"2017-05-10T17:36:17Z","updated_at":"2017-05-11T16:32:47Z","closed_at":null,"body":"I'm seeing hangs when using my custom-made latency test that was derived from ucp_hello_world.c:\r\nhttps://github.com/artpol84/poc/tree/ucx_hang_demo/ucx/latency.\r\n\r\nCommand line is the same, here is how you can reproduce the issue:\r\n```\r\nserver: ./launch.sh ./ucp_latency -f\r\ncli: ./launch.sh ./ucp_latency -f -n vegas06 -p 13337\r\n```\r\n\r\nSince communication is symmetric, hang may occur on either side.\r\nFor one particular case, sender side is not hanging, but waiting for the message send completion:\r\n```\r\n(gdb) bt\r\n#0  0x00007ffff6516213 in pthread_spin_lock () from /usr/lib64/libpthread.so.0\r\n#1  0x00007ffff562b9e6 in mlx5_poll_cq () from /usr/lib64/libmlx5-rdmav2.so\r\n#2  0x00007ffff72a0e33 in ibv_poll_cq (wc=0x7fffffffd888, num_entries=<optimized out>, cq=<optimized out>)\r\n    at /usr/include/infiniband/verbs.h:1360\r\n#3  uct_ib_poll_cq (wcs=0x7fffffffd888, count=<synthetic pointer>, cq=<optimized out>)\r\n    at /hpc/local/benchmarks/hpcx_install_Tuesday/src/hpcx-gcc-redhat7.2/ucx-master/src/uct/ib/base/ib_device.h:270\r\n#4  uct_ud_verbs_iface_poll_rx (is_async=0, iface=0x6bd020) at ib/ud/verbs/ud_verbs.c:320\r\n#5  uct_ud_verbs_iface_progress (arg=0x6bd020) at ib/ud/verbs/ud_verbs.c:368\r\n#6  0x00007ffff727d68e in ucs_callbackq_dispatch (cbq=0x648f18, cbq=0x648f18)\r\n    at /hpc/local/benchmarks/hpcx_install_Tuesday/src/hpcx-gcc-redhat7.2/ucx-master/src/ucs/datastruct/callbackq.inl:39\r\n#7  uct_worker_progress (worker=0x648f10) at base/uct_md.c:233\r\n#8  0x00007ffff7bc71dd in ucp_worker_progress (worker=0x656030) at core/ucp_worker.c:719\r\n#9  0x0000000000401a77 in wait (ucp_worker=0x656030, context=0x6e1748) at ucp_latency.c:123\r\n#10 0x0000000000401ec3 in send_msg (ucp_worker=0x656030, server_ep=0x611280, msg_len=262144) at ucp_latency.c:284\r\n#11 0x0000000000401f35 in pong_ping (ucp_worker=0x656030, ep=0x611280) at ucp_latency.c:301\r\n#12 0x000000000040215e in run_ucx_client (ucp_worker=0x656030) at ucp_latency.c:372\r\n#13 0x0000000000402553 in run_test (server=0x7fffffffe34e \"vegas06\", ucp_worker=0x656030) at ucp_latency.c:486\r\n#14 0x00000000004029e4 in main (argc=6, argv=0x7fffffffdfe8) at ucp_latency.c:617\r\n```\r\n\r\nreceiver side (one that actually hangs):\r\n```\r\n(gdb) bt\r\n#0  0x00007ffff75bfd13 in epoll_wait () from /usr/lib64/libc.so.6\r\n#1  0x0000000000401b5d in test_poll_wait (ucp_worker=0x61f2d0) at ucp_latency.c:161\r\n#2  0x0000000000401bd4 in recv_msg (ucp_worker=0x61f2d0, server_ep=0x6248e0) at ucp_latency.c:194\r\n#3  0x0000000000401f73 in ping_pong (ucp_worker=0x61f2d0, ep=0x6248e0, len=262144) at ucp_latency.c:307\r\n#4  0x000000000040247c in run_ucx_server (ucp_worker=0x61f2d0) at ucp_latency.c:470\r\n#5  0x0000000000402561 in run_test (server=0x0, ucp_worker=0x61f2d0) at ucp_latency.c:488\r\n#6  0x00000000004029e4 in main (argc=2, argv=0x7fffffffe018) at ucp_latency.c:617\r\n```\r\n\r\nIf I manually interrupt poll and fake ret value and force it to go to processing, I see that actually receive event has occurred, but poll wasn't interrupted for some reasons (or *_arm hasn't captured existing event)\r\n```\r\n(gdb) fini\r\nRun till exit from #0  0x00007ffff75bfd13 in epoll_wait () from /usr/lib64/libc.so.6\r\n0x0000000000401b5d in test_poll_wait (ucp_worker=0x61f2d0) at ucp_latency.c:161\r\n161             ret = epoll_wait(epoll_fd_local, &ev, 1, -1);\r\n(gdb) n\r\n162         } while ((ret == -1) && (errno == EINTR));\r\n(gdb) set ret = 0\r\n(gdb) n\r\n164         ret = UCS_OK;\r\n(gdb)\r\n167         close(epoll_fd_local);\r\n(gdb)\r\n169         return ret;\r\n(gdb)\r\n170     }\r\n(gdb)\r\nrecv_msg (ucp_worker=0x61f2d0, server_ep=0x6248e0) at ucp_latency.c:195\r\n195                 if (status != UCS_OK) {\r\n(gdb)\r\n201             ucp_worker_progress(ucp_worker);\r\n(gdb)\r\n204             msg_tag = ucp_tag_probe_nb(ucp_worker, tag, tag_mask, 1, &info_tag);\r\n(gdb)\r\n205         } while (msg_tag == NULL);\r\n(gdb)\r\n207         if( same_buf ) {\r\n(gdb) p msg_tag\r\n$1 = (ucp_tag_message_h) 0x7ffff49ed2a9\r\n```\r\n\r\nIf I introduce artificial delay at the sender side:\r\nhttps://github.com/artpol84/poc/blob/ucx_hang_demo/ucx/latency/ucp_latency.c#L270\r\nhang goes away."},"comment":{"url":"https://api.github.com/repos/openucx/ucx/issues/comments/300845036","html_url":"https://github.com/openucx/ucx/issues/1492#issuecomment-300845036","issue_url":"https://api.github.com/repos/openucx/ucx/issues/1492","id":300845036,"user":{"login":"evgeny-leksikov","id":15216359,"avatar_url":"https://avatars0.githubusercontent.com/u/15216359?v=3","gravatar_id":"","url":"https://api.github.com/users/evgeny-leksikov","html_url":"https://github.com/evgeny-leksikov","followers_url":"https://api.github.com/users/evgeny-leksikov/followers","following_url":"https://api.github.com/users/evgeny-leksikov/following{/other_user}","gists_url":"https://api.github.com/users/evgeny-leksikov/gists{/gist_id}","starred_url":"https://api.github.com/users/evgeny-leksikov/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/evgeny-leksikov/subscriptions","organizations_url":"https://api.github.com/users/evgeny-leksikov/orgs","repos_url":"https://api.github.com/users/evgeny-leksikov/repos","events_url":"https://api.github.com/users/evgeny-leksikov/events{/privacy}","received_events_url":"https://api.github.com/users/evgeny-leksikov/received_events","type":"User","site_admin":false},"created_at":"2017-05-11T16:32:46Z","updated_at":"2017-05-11T16:32:46Z","body":"Since it's reproduced only for large messages, it looks like side effect from RNDV protocol. Receiver catches only RTS packet with event which is processed earlier than UCX request is completed."}}
{"actor":{"display_login":"evgeny-leksikov"}}