Ompi: btl/uct: zcopy error with IB on large message.
The issue can be reproduced with any multithreaded communication with message size bigger than 64k.
[1538489194.112583] [a01:35024:1] rc_verbs_ep.c:344 UCX ERROR Invalid am_zcopy payload length: 65544 (expected: <=8192)
[1538489194.112590] [a01:35024:1] rc_verbs_ep.c:344 UCX ERROR Invalid am_zcopy payload length: 65544 (expected: <=8192)
[1538489194.112598] [a01:35024:1] rc_verbs_ep.c:344 UCX ERROR Invalid am_zcopy payload length: 65544 (expected: <=8192)
[1538489194.112605] [a01:35024:1] rc_verbs_ep.c:344 UCX ERROR Invalid am_zcopy payload length: 65544 (expected: <=8192)
I can reproduce this on my benchmark and also multithreaded chemistry application (MADNESS). We only have one uct_am_zcopy call in the BTL and it is here.
if (NULL != frag->base.super.registration) {
152 frag->comp.dev_context = context;
153
154 ucs_status = uct_ep_am_zcopy (ep_handle, MCA_BTL_UCT_FRAG, &frag->header, sizeof (frag->header),
155 &frag->uct_iov, 1, 0, &frag->comp.uct_comp);
156 } else {
157 /* short message */
158 /* restore original flags */
159 frag->base.des_flags = flags;
160
161 if (1 == frag->base.des_segment_count) {
162 ucs_status = uct_ep_am_short (ep_handle, MCA_BTL_UCT_FRAG, frag->header.value, frag->uct_iov.buffer,
163 frag->uct_iov.length);
164 } else {
165 ucs_status = uct_ep_am_bcopy (ep_handle, MCA_BTL_UCT_FRAG, mca_btl_uct_send_frag_pack, frag, 0);
166 }
167 }
I put assert(frag->uct_iov.length <= 8192) and it trips there. I have not tracked this problem down yet but create this issue as a tracker instead.
thananon
All 22 comments
I think I know the issue. I am working on an update to this code. Incoming shortly.
hjelmn
on 2 Oct 2018
fixed with #5837
thananon
on 10 Oct 2018
I'm gonna reopen this as I found this problem again but only in multithreaded case.
it runs with 2 threads.
✘ tpatinya@saturn î‚° ~/multirate î‚° î‚ master î‚° salloc -w a05,a08 mpirun -np 2 --map-by node --bind-to none -mca pml ob1 -mca btl uct,self -mca btl_uct_memory_domains ib/mlx5_0 -mca mpi_spc_attach all -mca mpi_spc_dump_enabled true ./pairwise -s 71024 -w 128 -i 100 -t 2
salloc: Granted job allocation 232351
salloc: Waiting for resource configuration
salloc: Nodes a[05,08] are ready for job
1 2 100 71024 147253.605503 0.173850 sec
Also I think the module lock might have to be recursive mutex to prevent the double lock (from progress_pendings)
diff --git a/opal/mca/btl/uct/btl_uct.h b/opal/mca/btl/uct/btl_uct.h
index 989fe64132..bdeb43f0c5 100644
--- a/opal/mca/btl/uct/btl_uct.h
+++ b/opal/mca/btl/uct/btl_uct.h
@@ -68,7 +68,7 @@ struct mca_btl_uct_module_t {
opal_hash_table_t id_to_endpoint;
/** mutex to protect the module */
- opal_mutex_t lock;
+ opal_recursive_mutex_t lock;
/** async context */
ucs_async_context_t *ucs_async;
diff --git a/opal/mca/btl/uct/btl_uct_component.c b/opal/mca/btl/uct/btl_uct_component.c
index 70f1726787..5c6019bfdf 100644
--- a/opal/mca/btl/uct/btl_uct_component.c
+++ b/opal/mca/btl/uct/btl_uct_component.c
@@ -272,7 +272,7 @@ static mca_btl_uct_module_t *mca_btl_uct_alloc_module (const char *md_name, mca_
OBJ_CONSTRUCT(&module->eager_frags, opal_free_list_t);
OBJ_CONSTRUCT(&module->max_frags, opal_free_list_t);
OBJ_CONSTRUCT(&module->pending_frags, opal_list_t);
- OBJ_CONSTRUCT(&module->lock, opal_mutex_t);
+ OBJ_CONSTRUCT(&module->lock, opal_recursive_mutex_t);
module->md = md;
module->md_name = strdup (md_name);
After the patch, OMPI stop complaining about deadlock but the behavior shows when I run with 4 threads.
✘ tpatinya@saturn î‚° ~/multirate î‚° î‚ master î‚° salloc -w a05,a08 mpirun -np 2 --map-by node --bind-to none -mca pml ob1 -mca btl uct,self -mca btl_uct_memory_domains ib/mlx5_0 -mca mpi_spc_attach all -mca mpi_spc_dump_enabled true ./pairwise -s 71024 -w 128 -i 100 -t 4
...
1539355671.192602] [a05:32295:1] rc_verbs_ep.c:344 UCX ERROR Invalid am_zcopy payload length: 65544 (expected: <= 8192)
[1539355671.192611] [a05:32295:1] rc_verbs_ep.c:344 UCX ERROR Invalid am_zcopy payload length: 65544 (expected: <= 8192)
[1539355671.192619] [a05:32295:1] rc_verbs_ep.c:344 UCX ERROR Invalid am_zcopy payload length: 65544 (expected: <= 8192)
[1539355671.192628] [a05:32295:1] rc_verbs_ep.c:344 UCX ERROR Invalid am_zcopy payload length: 65544 (expected: <= 8192)
...
huh, if I reduce the message size to 1k I got this. (Only occurs with multiple threads)
[1539356102.223203] [a08:26880:0] uct_iface.c:57 UCX WARN got active message id 0, but no handler installed
[1539356102.223205] [a08:26880:0] uct_iface.c:57 UCX WARN got active message id 0, but no handler installed
[1539356102.223208] [a08:26880:0] uct_iface.c:57 UCX WARN got active message id 0, but no handler installed
[1539356102.223210] [a08:26880:0] uct_iface.c:57 UCX WARN got active message id 0, but no handler installed
[1539356102.223212] [a08:26880:0] uct_iface.c:57 UCX WARN got active message id 0, but no handler installed
thananon
on 12 Oct 2018
Oh, thats a different issue. Should be fixed on current master.
hjelmn
on 12 Oct 2018
Hmm, though maybe not. The problem is that different TL instances may have different capabilities (really annoying). Its biting us here in a different way.
hjelmn
on 12 Oct 2018
We need to find the smallest possible zcopy limit for a TL to set for the limits for active message.
hjelmn
on 12 Oct 2018
Huh, or not. We just need to set btl_max_send_size correctly :D.
hjelmn
on 12 Oct 2018
will post a fix for that.
hjelmn
on 12 Oct 2018
Ah, I can just try with an MCA.
thananon
on 12 Oct 2018
yup. set the max send size based on the max zcopy limit from ucx_info -c
hjelmn
on 12 Oct 2018
Hmm, the max zcopy isn't in that output. Oh well. Its in the interface attributes .cap.am.max_zcopy. Try this:
diff --git a/opal/mca/btl/uct/btl_uct_tl.c b/opal/mca/btl/uct/btl_uct_tl.c
index bca62c4813..13b949938f 100644
--- a/opal/mca/btl/uct/btl_uct_tl.c
+++ b/opal/mca/btl/uct/btl_uct_tl.c
@@ -138,6 +138,8 @@ static void mca_btl_uct_tl_destructor (mca_btl_uct_tl_t *tl)
{
assert (((opal_object_t *) tl)->obj_reference_count == 0);
+ BTL_VERBOSE(("destroying tl %s", tl->uct_tl_name));
+
for (int context_id = 0 ; context_id < MCA_BTL_UCT_MAX_WORKERS ; ++context_id) {
if (NULL != tl->uct_dev_contexts[context_id]) {
mca_btl_uct_context_destroy (tl->uct_dev_contexts[context_id]);
@@ -284,7 +286,7 @@ mca_btl_uct_device_context_t *mca_btl_uct_context_create (mca_btl_uct_module_t *
* use our own locks just go ahead and use UCS_THREAD_MODE_SINGLE. if they ever fix their
* api then change this back to UCS_THREAD_MODE_MULTI and remove the locks around the
* various UCT calls. */
- ucs_status = uct_worker_create (module->ucs_async, UCS_THREAD_MODE_SERIALIZED, &context->uct_worker);
+ ucs_status = uct_worker_create (module->ucs_async, UCS_THREAD_MODE_SINGLE, &context->uct_worker);
if (OPAL_UNLIKELY(UCS_OK != ucs_status)) {
BTL_VERBOSE(("could not create a UCT worker"));
mca_btl_uct_context_destroy (context);
@@ -434,6 +436,8 @@ static void mca_btl_uct_set_tl_am (mca_btl_uct_module_t *module, mca_btl_uct_tl_
if (tl->max_device_contexts <= 1) {
tl->max_device_contexts = mca_btl_uct_component.num_contexts_per_module;
}
+
+ module->super.btl_max_send_size = MCA_BTL_UCT_TL_ATTR(tl, 0).cap.am.max_zcopy;
}
static int mca_btl_uct_set_tl_conn (mca_btl_uct_module_t *module, mca_btl_uct_tl_t *tl)
Ok, so there are remaining problems after setting the correct send size.
This still happens sometimes and I think this is the same problem as #5820 .
[1539356890.574382] [a08:28620:0] uct_iface.c:57 UCX WARN got active message id 0, but no handler installedThis, sometimes...
✘ tpatinya@saturn î‚° ~/multirate î‚° î‚ master î‚° salloc -w a05,a08 mpirun -np 2 --map-by node --bind-to none -mca pml ob1 -mca btl uct,self -mca btl_uct_memory_domains ib/mlx5_0 -mca mpi_spc_attach all -mca mpi_spc_dump_enabled true -mca btl_uct_max_send_size 8000 ./pairwise -s 71024 -w 128 -i 100 -t 4
salloc: Granted job allocation 232384
salloc: Waiting for resource configuration
salloc: Nodes a[05,08] are ready for job
[a08:28770:0:28776] Caught signal 11 (Segmentation fault: address not mapped to object at address 0x218)
/home/tpatinya/ompi/ompi/mca/pml/ob1/pml_ob1_recvreq.c: [ mca_pml_ob1_recv_request_progress_frag() ]
...
523 recvreq->req_recv.req_base.req_datatype);
524 );
525 MCA_PML_OB1_RECV_REQUEST_UNPACK( recvreq,
==> 526 segments,
527 num_segments,
528 sizeof(mca_pml_ob1_frag_hdr_t),
529 data_offset,
==== backtrace ====
0 0x000000000001d31e mca_pml_ob1_recv_request_progress_frag() /home/tpatinya/ompi/ompi/mca/pml/ob1/pml_ob1_recvreq.c:526
1 0x0000000000018721 mca_pml_ob1_recv_frag_callback_frag() /home/tpatinya/ompi/ompi/mca/pml/ob1/pml_ob1_recvfrag.c:660
2 0x0000000000007228 mca_btl_uct_am_handler() /home/tpatinya/ompi/opal/mca/btl/uct/btl_uct_component.c:303
3 0x000000000002b2b5 uct_iface_invoke_am() /home/tpatinya/Download/ucx/src/uct/base/uct_iface.h:526
4 0x000000000002b2b5 uct_rc_verbs_iface_handle_am() /home/tpatinya/Download/ucx/src/uct/ib/rc/verbs/rc_verbs_common.h:162
5 0x000000000002b2b5 uct_rc_verbs_iface_poll_rx_common() /home/tpatinya/Download/ucx/src/uct/ib/rc/verbs/rc_verbs_common.h:191
6 0x000000000002b2b5 uct_rc_verbs_iface_progress() /home/tpatinya/Download/ucx/src/uct/ib/rc/verbs/rc_verbs_iface.c:111
7 0x0000000000005e0e ucs_callbackq_dispatch() /home/tpatinya/opt/ucx/include/ucs/datastruct/callbackq.h:208
8 0x0000000000006179 uct_worker_progress() /home/tpatinya/opt/ucx/include/uct/api/uct.h:1676
9 0x0000000000007bda mca_btl_uct_tl_progress() /home/tpatinya/ompi/opal/mca/btl/uct/btl_uct_component.c:470
10 0x0000000000007d89 mca_btl_uct_component_progress() /home/tpatinya/ompi/opal/mca/btl/uct/btl_uct_component.c:519
11 0x0000000000036a9a opal_progress() /home/tpatinya/ompi/opal/runtime/opal_progress.c:231
12 0x000000000003f0bd ompi_sync_wait_mt() /home/tpatinya/ompi/opal/threads/wait_sync.c:85
13 0x000000000005fb3e ompi_request_default_wait_all() /home/tpatinya/ompi/ompi/request/req_wait.c:243
14 0x00000000000da99d PMPI_Waitall() /home/tpatinya/ompi/ompi/mpi/c/profile/pwaitall.c:80
15 0x0000000000401956 thread_work() /home/tpatinya/multirate/pairwise.c:233
16 0x0000000000007e25 start_thread() /usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:308
17 0x00000000000f834d __clone() /usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113
===================
- This sometimes..
✘ tpatinya@saturn î‚° ~/multirate î‚° î‚ master î‚° salloc -w a05,a08 mpirun -np 2 --map-by node --bind-to none -mca pml ob1 -mca btl uct,self -mca btl_uct_memory_domains ib/mlx5_0 -mca mpi_spc_attach all -mca mpi_spc_dump_enabled true -mca btl_uct_max_send_size 8000 ./pairwise -s 71024 -w 128 -i 100 -t 4 -c
salloc: Granted job allocation 232376
salloc: Waiting for resource configuration
salloc: Nodes a[05,08] are ready for job
[a08:28379:0:28385] Caught signal 11 (Segmentation fault: address not mapped to object at address (nil))
==== backtrace ====
===================
That happens just when multi-threading, correct?
hjelmn
on 12 Oct 2018
Can you send me your reproducer? The safest way to send it would be transfer.lanl.gov
hjelmn
on 12 Oct 2018
Only multithreaded, yes. Code sent.
You can run in single threaded mode with argument -Dthrds.
thananon
on 12 Oct 2018
Hasn't arrived on my end. Did you use my hjelmn at lanl dot gov email and make sure the file uploaded? There is a button (I think) to do so. Never used the external version of that service myself.
hjelmn
on 12 Oct 2018
You could also just post it in gist.github.com
jsquyres
on 12 Oct 2018
@hjelmn I mistyped the email address and sent it to random dude. You should have it now.
thananon
on 12 Oct 2018
@jsquyres Can gists be private?
hjelmn
on 12 Oct 2018
@thananon Have it now. Thanks!
hjelmn
on 12 Oct 2018
ok, i know how it locks up, not sure as to the why exactly. have a fix. testing now.
hjelmn
on 12 Oct 2018
Related issues
leofang
·
4Comments
yoshihingis
·
3Comments
egorgam
·
5Comments
pozdneev
·
4Comments
jsquyres
·
4Comments
Most helpful comment
You could also just post it in gist.github.com