Repository navigation
Cello/Enzo-P hangs with UCX machine layer (in nonSMP mode) on Frontera #2635
Description
Activity
- changed the title
[-]Cello/Enzo-P hangs with the UCX machine layer (in nonSMP mode) on Frontera[/-][+]Cello/Enzo-P hangs with UCX machine layer (in nonSMP mode) on Frontera[/+]on Dec 4, 2019 While attempting to reproduce this issue, I got this HDF5 related error while linking the final binary:
Install file: "build/Cello/libcello.a" as "lib/libcello.a" /home1/03808/nbhat4/software/charm/ucx-linux-x86_64-prod/bin/charmc -language charm++ -o build/Enzo/enzo-p -O3 -Wall -g -ffast-math -funroll-loops -rdynamic -module CommonLBs build/Enzo/enzo-p.o build/Cello/main_enzo.o -Llib -L/home1/03808/nbhat4/software/hdf5-1.8.14/build/lib -L/opt/apps/gcc9_1/boost/1.69/lib -L/usr/lib64/lib -lenzo -lcharm -lsimulation -ldata -lproblem -lcompute -lcontrol -lmesh -lio -ldisk -lmemory -lparameters -lerror -lmonitor -lparallel -lperformance -ltest -lcello -lexternal -lhdf5 -lz -ldl -lpng -lgfortran -lboost_filesystem -lboost_system /opt/apps/gcc/9.1.0/bin/ld: lib/libdisk.a(disk_FileHdf5.o): in function `FileHdf5::FileHdf5(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >)': /home1/03808/nbhat4/software/enzo-e/build/Cello/disk_FileHdf5.cpp:43: undefined reference to `H5P_CLS_DATASET_CREATE_ID_g' collect2: error: ld returned 1 exit status Fatal Error by charmc in directory /home1/03808/nbhat4/software/enzo-e Command g++ -rdynamic -L/usr/lib64/ -O3 -Wall -g -ffast-math -funroll-loops -rdynamic -Llib -L/home1/03808/nbhat4/software/hdf5-1.8.14/build/lib -L/opt/apps/gcc9_1/boost/1.69/lib -L/usr/lib64/lib build/Enzo/enzo-p.o build/Cello/main_enzo.o moduleinit123437.o -L/home1/03808/nbhat4/software/charm/ucx-linux-x86_64-prod/bin/../lib -lmoduleCommonLBs -lckmain -lck -lmemory-default -lthreads-default -lconv-machine -lconv-core -ltmgr -lconv-util -lconv-partition -lhwloc_embedded -lm -lmemory-default -lthreads-default -lldb-rand -lconv-ldb -lckqt -lucp -luct -lucs -lucm -ldl -lenzo -lcharm -lsimulation -ldata -lproblem -lcompute -lcontrol -lmesh -lio -ldisk -lmemory -lparameters -lerror -lmonitor -lparallel -lperformance -ltest -lcello -lexternal -lhdf5 -lz -ldl -lpng -lgfortran -lboost_filesystem -lboost_system -lmoduleCommonLBs -lmoduleNDMeshStreamer -lmodulecompletion -lz -lm /home1/03808/nbhat4/software/charm/ucx-linux-x86_64-prod/bin/../lib/conv-static.o -o build/Enzo/enzo-p returned error code 1 charmc exiting... scons: *** [build/Enzo/enzo-p] Error 1I got past it by using HDF5 version 1.8.13. (all other newer version gave me this ^ error)
Another setting that can simplify the build process is setting
"use_grackle = 0" in the SConstruct file line 102As previously stated by James over email, the program ran successfully when exectued on 1/2 nodes. However, the bug appeared while running on 4, 8 and 64 nodes.
The last output printed before the hang for a 4 node run is as follows:
0 00386.25 Performance refresh_store time-usec 0 0 00386.25 Performance refresh_child time-usec 0 0 00386.25 Performance refresh_exit time-usec 0 0 00386.25 Performance refresh_store_sync time-usec 0 0 00386.25 Performance refresh_child_sync time-usec 0 0 00386.25 Performance refresh_exit_sync time-usec 0 0 00386.25 Performance control time-usec 80702761 0 00386.25 Performance compute time-usec 14184066599 0 00386.25 Performance output time-usec 133512 0 00386.25 Performance stopping time-usec 4354327957 0 00386.25 Performance block time-usec 57974302110 0 00386.25 Performance exit time-usec 0 0 00386.25 Performance simulation max-proc-blocks 199 0 00386.25 Performance simulation max-proc-particles 618658 0 00386.25 Performance simulation balance-blocks 19.031216 0 00386.25 Performance simulation balance-eff-blocks 0.840116 (167/199) 0 00386.25 Performance simulation balance-particles 3.249693 0 00386.25 Performance simulation balance-eff-particles 0.968526 (599186/618658)Since @brminich suggested
export UCX_ZCOPY_THRESH=-1for ChaNGa, I used that for a 64 node Cello/Enzo-P run and was able to successfully run without a hang. (Tried about 10 times and it ran successfully every time).This was my run script:
#!/bin/bash #SBATCH -J enzo #SBATCH -p normal #SBATCH -t 00:05:00 #SBATCH -N 64 #SBATCH -n 3584 #SBATCH --ntasks-per-node=56 cd /home1/03808/nbhat4/software/enzo-e export UCX_ZCOPY_THRESH=-1 ibrun ./enzo-p-nonsmp ./enzoe-frontera-ucx.in@brminich: Since the hang exists without
UCX_ZCOPY_THRESH=-1and doesn't hang withUCX_ZCOPY_THRESH=-1, I'm guessing the abundance of small eager messages being copied with the auto threshold are causing the hang? It'll be good if UCX complains about an error rather than just showing a hang.Reacted by Ophir Maor@brminich just confirmed that setting
UCX_ZCOPY_THRESH=-1actually means that the Zerocopy threshold will be set to infinite i.e all sends will be buffered and will complete immediately.So, setting
UCX_ZCOPY_THRESH=-1should ideally take up more memory than the default UCX_ZCOPY_THRESH being 8k or 16k.I was able to get enzo-P to hang on 4 nodes and attach gdb to each process and get stack traces for it. I'm attaching the stack traces here.
stack_1node.txt
stack_2node.txt
stack_3node.txt
stack_4node.txtThis is the typical size/count of messages sent by one of the processes in the application for a 64 node (3584 process run) (other processes also seem to follow a similar profile):
Msg Size Count 96 630602 1184 216714 416 144234 4256 107880 160 34736 80 24294 3248 12119 4272 12119 6336 12119 9440 12119 12480 11943 944 8039 1200 8039 1728 8039 2528 8039 5312 7967 12464 5980 16560 5980 24768 5980 32960 5980 37088 5980 36992 2147 2144 2000 672 1284 192 424 320 372 112 336 208 301 128 295 1712 214 2224 214 3264 214 4544 214 4832 214 7360 176 960 144 1328 101 224 100 2944 72 656 62 816 62 1152 62 1664 62 3712 62 2576 24 3376 24 4992 24 7424 24 8192 24 14368 4 272 3 304 3 384 3 512 3 2048 3 20 1 452 1 35 remaining items
From Tommy Minyard @ TACC:
this appears to be from job 775543, here's what we get in the log when your jobs was running:
[198307.229554] TACC: Running job 775543 for user nbhat4 [198542.853543] mlx5_core 0000:5e:00.0: device's health compromised - reached miss count [198542.861625] mlx5_core 0000:5e:00.0: assert_var[0] 0x00000001 [198542.867495] mlx5_core 0000:5e:00.0: assert_var[1] 0x2097ce84 [198542.873367] mlx5_core 0000:5e:00.0: assert_var[2] 0x00000000 [198542.879232] mlx5_core 0000:5e:00.0: assert_var[3] 0x00000000 [198542.885107] mlx5_core 0000:5e:00.0: assert_var[4] 0x00000000 [198542.890975] mlx5_core 0000:5e:00.0: assert_exit_ptr 0x20a4996c [198542.897021] mlx5_core 0000:5e:00.0: assert_callra 0x20a49a10 [198542.902895] mlx5_core 0000:5e:00.0: fw_ver 20.26.4012 [198542.908161] mlx5_core 0000:5e:00.0: hw_id 0x0000020f [198542.913332] mlx5_core 0000:5e:00.0: irisc_index 0 [198542.918249] mlx5_core 0000:5e:00.0: synd 0x7: irisc not responding [198542.924637] mlx5_core 0000:5e:00.0: ext_synd 0x40d0 [198542.929726] mlx5_core 0000:5e:00.0: raw fw_ver 0x141a0facthat was from node c122-021, there were crashes on at least two other nodes with similar errors for other jobs, here is the one that crashed node c138-061:
[263011.149752] TACC: Running job 776827 for user nbhat4 [263212.049785] mlx5_core 0000:5e:00.0: device's health compromised - reached miss count [263212.057864] mlx5_core 0000:5e:00.0: assert_var[0] 0x00000001 [263212.063730] mlx5_core 0000:5e:00.0: assert_var[1] 0x2097dc04 [263212.069592] mlx5_core 0000:5e:00.0: assert_var[2] 0x00000000 [263212.075455] mlx5_core 0000:5e:00.0: assert_var[3] 0x00000000 [263212.081316] mlx5_core 0000:5e:00.0: assert_var[4] 0x00000000 [263212.087180] mlx5_core 0000:5e:00.0: assert_exit_ptr 0x2080e34c [263212.093220] mlx5_core 0000:5e:00.0: assert_callra 0x20ac8944 [263212.099088] mlx5_core 0000:5e:00.0: fw_ver 20.26.4012 [263212.104349] mlx5_core 0000:5e:00.0: hw_id 0x0000020f [263212.109520] mlx5_core 0000:5e:00.0: irisc_index 2 [263212.114433] mlx5_core 0000:5e:00.0: synd 0x7: irisc not responding [263212.120813] mlx5_core 0000:5e:00.0: ext_synd 0x40c0 [263212.125894] mlx5_core 0000:5e:00.0: raw fw_ver 0x141a0facunfortunately, that's about all we get from the system side, once the card is in this state, Lustre errors start and threads just hang and start dumping stack traces
[263393.108635] INFO: task enzo-p-nonsmp-u:336412 blocked for more than 120 seconds. [263393.116352] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [263393.124508] enzo-p-nonsmp-u D ffff937d01f64100 0 336412 1 0x00000084 [263393.132017] Call Trace: [263393.134689] [<ffffffff939ea896>] ? handle_pte_fault+0x316/0xd10 [263393.140915] [<ffffffff93b969cd>] ? list_del+0xd/0x30 [263393.146183] [<ffffffff93f69f19>] schedule+0x29/0x70 [263393.151360] [<ffffffff93f67a21>] schedule_timeout+0x221/0x2d0 [263393.157427] [<ffffffffc04c5be7>] ? _mlx5_ib_post_send+0x3b7/0x13e0 [mlx5_ib] [263393.164887] [<ffffffff93f6a2cd>] wait_for_completion+0xfd/0x140 [263393.171099] [<ffffffff938d7c40>] ? wake_up_state+0x20/0x20 [263393.176887] [<ffffffffc04cfebb>] mlx5_ib_post_send_wait+0x9b/0x150 [mlx5_ib] [263393.184350] [<ffffffffc04cfbb0>] ? get_nchild+0x70/0x70 [mlx5_ib] [263393.190739] [<ffffffffc04d0be9>] unreg_umr+0x89/0xc0 [mlx5_ib] [263393.196867] [<ffffffffc04d1075>] dereg_mr+0x195/0x1e0 [mlx5_ib] [263393.203087] [<ffffffffc04d4de3>] mlx5_ib_dereg_mr+0x83/0x90 [mlx5_ib] [263393.209823] [<ffffffffc0469884>] ib_dereg_mr+0x34/0x50 [ib_core] [263393.216126] [<ffffffffc030a6b2>] uverbs_free_mr+0x12/0x20 [ib_uverbs] [263393.222856] [<ffffffffc0306a52>] destroy_hw_idr_uobject+0x22/0x60 [ib_uverbs] [263393.230408] [<ffffffffc0307184>] uverbs_destroy_uobject+0x34/0x190 [ib_uverbs] [263393.238042] [<ffffffffc03074e2>] uobj_destroy+0x52/0x70 [ib_uverbs] [263393.244605] [<ffffffffc0307841>] __uobj_get_destroy+0x31/0x60 [ib_uverbs] [263393.251686] [<ffffffffc0307881>] __uobj_perform_destroy+0x11/0x30 [ib_uverbs] [263393.259236] [<ffffffffc02fdadc>] ib_uverbs_dereg_mr+0x8c/0xc0 [ib_uverbs] [263393.266316] [<ffffffffc02f9190>] ib_uverbs_write+0x530/0x590 [ib_uverbs] [263393.273313] [<ffffffff938e143c>] ? update_curr+0x14c/0x1e0 [263393.279094] [<ffffffff93afa597>] ? security_file_permission+0x27/0xa0 [263393.285832] [<ffffffff93a42700>] vfs_write+0xc0/0x1f0 [263393.291175] [<ffffffff93a4351f>] SyS_write+0x7f/0xf0 [263393.296441] [<ffffffff93f76ddb>] system_call_fastpath+0x22/0x27When I try running Enzo with the message tracking infrastructure to determine the undelivered messages, for some runs, I see a crash with the following stack trace. Any idea why this is being caused @brminich? Enzo here was built on top of charm++ master (includes your polling perf improvement patch) and uses ucx/1.8.0.
5381 [c137-064:228344:0:228344] Caught signal 11 (Segmentation fault: address not mapped to object at address (nil))$ 5382 ==== backtrace (tid: 228344) ====$ 5383 0 0x0000000000050dfe ucs_debug_print_backtrace() /work/00410/huang/frontera/ucx/ucx-1.8.0-rc1/src/ucs/debug/debug.c:625$ 5384 1 0x0000000000036340 killpg() ???:0$ 5385 2 0x0000000000049fa0 ucs_arbiter_dispatch_nonempty() /work/00410/huang/frontera/ucx/ucx-1.8.0-rc1/src/ucs/datastruct/arbiter.c:327$ 5386 3 0x000000000003e9c5 ucs_arbiter_dispatch() /work/00410/huang/frontera/ucx/ucx-1.8.0-rc1/src/ucs/datastruct/arbiter.h:356$ 5387 4 0x000000000003e9c5 uct_dc_mlx5_iface_progress_pending() /work/00410/huang/frontera/ucx/ucx-1.8.0-rc1/src/uct/ib/dc/dc_mlx5_ep.h:310$ 5388 5 0x000000000003e9c5 uct_dc_mlx5_poll_tx() /work/00410/huang/frontera/ucx/ucx-1.8.0-rc1/src/uct/ib/dc/dc_mlx5.c:225$ 5389 6 0x000000000003e9c5 uct_dc_mlx5_iface_progress() /work/00410/huang/frontera/ucx/ucx-1.8.0-rc1/src/uct/ib/dc/dc_mlx5.c:238$ 5390 7 0x0000000000021602 ucs_callbackq_dispatch() /work/00410/huang/frontera/ucx/ucx-1.8.0-rc1/src/ucs/datastruct/callbackq.h:211$ 5391 8 0x0000000000021602 uct_worker_progress() /work/00410/huang/frontera/ucx/ucx-1.8.0-rc1/src/uct/api/uct.h:2221$ 5392 9 0x0000000000021602 ucp_worker_progress() /work/00410/huang/frontera/ucx/ucx-1.8.0-rc1/src/ucp/core/ucp_worker.c:1951$ 5393 10 0x000000000065aa8d LrtsAdvanceCommunication() ???:0$ 5394 11 0x000000000065abb7 CmiGetNonLocal() ???:0$ 5395 12 0x000000000065cc5d CsdNextMessage() ???:0$ 5396 13 0x000000000065cd20 CsdScheduleForever() ???:0$ 5397 14 0x000000000065cfd5 CsdScheduler() ???:0$ 5398 15 0x000000000065b33a ConverseInit() ???:0$ 5399 16 0x0000000000577857 charm_main() ???:0$ 5400 17 0x0000000000022495 __libc_start_main() ???:0$ 5401 18 0x000000000053ae5c _start() ???:0$ 5402 =================================$@nitbhat, checking it. Can be one of the issues we fixed in the arbiter recently.
Can you please try using UCX master instead?
Or, as a workaround, you could try to set this UCX env var: UCX_TLS=sm,self,ud
you can also use RC instead of UD, but it has scalability limitations, so it may not work with all-to-all kind of patterns with many processesOkay, thanks @brminich.
I am trying to build ucx master (ed6b365dc9193dac8a4243f8c00b0ab8db368d89).
My configure line is as follows:
./configure --prefix=/scratch1/03808/nbhat4/ucx/build_master --enable-compiler-opt=3 --enable-optimizations --disable-logging --disable-debug --disable-assertions --disable-params-check --with-mcpu --with-march --with-rc --with-ud --with-dc --with-cm --with-mlx5-dv --with-ib-hw-tm --with-dm --with-knem=/opt/knem-1.1.3.90mlnx1 --enable-static=yes --enable-shared=yesConfigure ends with
checking for process_vm_readv... yes checking whether KNEM_CMD_GET_INFO is declared... yes configure: XPMEM - failed to open the requested location (guess), guessing ... checking cray-ugni... no checking that generated files are newer than configure... done configure: creating ./config.status config.status: creating src/ucm/cuda/Makefile config.status: creating src/ucm/rocm/Makefile config.status: creating src/ucm/Makefile config.status: creating src/uct/cuda/gdr_copy/Makefile config.status: creating src/uct/cuda/Makefile config.status: creating src/uct/ib/cm/Makefile config.status: creating src/uct/ib/rdmacm/Makefile config.status: creating src/uct/ib/Makefile config.status: creating src/uct/rocm/gdr/Makefile config.status: creating src/uct/rocm/Makefile config.status: creating src/uct/sm/cma/Makefile config.status: creating src/uct/sm/knem/Makefile config.status: creating src/uct/sm/mm/xpmem/Makefile config.status: creating src/uct/sm/mm/Makefile config.status: creating src/uct/sm/Makefile config.status: creating src/uct/ugni/Makefile config.status: creating src/uct/Makefile config.status: creating src/tools/perf/lib/Makefile config.status: creating src/tools/perf/cuda/Makefile config.status: creating src/tools/perf/Makefile config.status: creating test/gtest/ucm/test_dlopen/Makefile config.status: creating test/gtest/ucs/test_module/Makefile config.status: creating test/gtest/Makefile config.status: creating Makefile config.status: error: cannot find input file: `doc/doxygen/header.tex.in'Then, on running make, I see:
login1.frontera(1045)$ make cd . && /bin/sh ./config.status config.h config.status: creating config.h config.status: config.h is unchanged make all-recursive make[1]: Entering directory `/scratch1/03808/nbhat4/ucx' Making all in src/ucm make[2]: Entering directory `/scratch1/03808/nbhat4/ucx/src/ucm' Making all in . make[3]: Entering directory `/scratch1/03808/nbhat4/ucx/src/ucm' CC malloc/libucm_la-malloc_hook.lo malloc/malloc_hook.c: In function ‘ucm_malloc_init_orig_funcs’: malloc/malloc_hook.c:794:65: error: ‘malloc_usable_size’ undeclared (first use in this function); did you mean ‘dlmalloc_usable_size’? 794 | ucm_malloc_hook_state.usable_size = (size_t (*)(void *))malloc_usable_size; | ^~~~~~~~~~~~~~~~~~ | dlmalloc_usable_size malloc/malloc_hook.c:794:65: note: each undeclared identifier is reported only once for each function it appears in malloc/malloc_hook.c: In function ‘ucm_malloc_install’: malloc/malloc_hook.c:848:13: error: ‘__free_hook’ undeclared (first use in this function) 848 | __free_hook = ucm_free; | ^~~~~~~~~~~ malloc/malloc_hook.c:849:13: error: ‘__realloc_hook’ undeclared (first use in this function) 849 | __realloc_hook = ucm_realloc; | ^~~~~~~~~~~~~~ malloc/malloc_hook.c:850:13: error: ‘__malloc_hook’ undeclared (first use in this function) 850 | __malloc_hook = ucm_malloc; | ^~~~~~~~~~~~~ malloc/malloc_hook.c:851:13: error: ‘__memalign_hook’ undeclared (first use in this function) 851 | __memalign_hook = ucm_memalign; | ^~~~~~~~~~~~~~~ make[3]: *** [malloc/libucm_la-malloc_hook.lo] Error 1 make[3]: Leaving directory `/scratch1/03808/nbhat4/ucx/src/ucm' make[2]: *** [all-recursive] Error 1 make[2]: Leaving directory `/scratch1/03808/nbhat4/ucx/src/ucm' make[1]: *** [all-recursive] Error 1 make[1]: Leaving directory `/scratch1/03808/nbhat4/ucx' make: *** [all] Error 2I see that with the
ucxmaster (HEAD at b72cd117d474a3963640db72a1ac4de4e7442c81), the enzo hang occurs rarely. The hang percentage has dropped significantly. ( Was there any specific change that affected small messages (that could've caused this)? That might help us identify the bug better. @brminichI compared with both
ucx/1.6.1anducx/1.8.0on Frontera. With both of those the hang rate is much higher. For example, for 4 nodes, withucx/1.6.1anducx/1.8.0, it hangs 5/10 times. Similarily, for 64 nodes, it hangs 8/10 times.But with the new ucx master, I haven't seen it hang for 4 nodes so far. (0/20 runs)
But for 64 nodes, it hangs rarely. (1/20 runs). So, the problem occurs much less frequently but isn't entirely gone.I tried this experiment again where I updated ucx to
master(openucx/ucx@b72cd11) and I see that Enzo doesn't hang on 4 nodes or 64 nodes. I tried about 20 jobs each starting from 4 up to 64 nodes, going 2x every time and all the submitted jobs with charm based on ucx master ran successfully. This makes me believe that the hang I saw earlier with the ucx master was either a very rare hang or an error on my part, where I killed the job thinking it was a hang).On bisecting, I found that this commit (openucx/ucx@7147812) seems to be the one that is fixing the hang. And the commit message mentions the fix to a ‘deadlock’. Do you think this is applicable to what was seen on Frontera? If so, can the bug be characterized as the deadlock as described in the commit message? @brminich
On testing Enzo with the latest UCX release candidate v1.8.1-rc1, I see that Enzo continues to hang (as it did previously with v1.6.1 and v1.8.0). However, on testing with the current master, Enzo doesn't hang. Similar behavior is seen with NAMD as well i.e. NAMD hangs with ucx 1.8.1-rc1, but not with current master. (as mentioned in #2716)
I verified that this issue is solved when using UCX v1.9.0-rc1 (https://github.com/openucx/ucx/releases/tag/v1.9.0-rc1). The fix should be available in the upcoming UCX release.
This bug was reported by James Bordner/Mike Norman at the Charm++ BoF at SC 19.
Bug reproduction details:
Enzo-E/Cello version: https://github.com/jobordner/enzo-e.git (solver-dd branch)Modules:
module load gcc ucx boostEnvironment:
Input files:
Input file: see attached
enzoe-frontera-ucx.in.txt
Batch script:
Run command used: charmrun +p3584 ./enzo-p enzoe-frontera-ucx.in.txt