Xla: DLRM with real dataset segfault around 20k steps
🐛 Bug
To Reproduce
Steps to reproduce the behavior:
- git clone -b tpu-criteo-kaggle https://github.com/taylanbil/dlrm.git
- Running DLRM with args
python dlrm/dlrm_tpu_runner.py \
--arch-sparse-feature-size=16 \
--arch-mlp-bot="13-512-256-64-16" \
--arch-mlp-top="512-256-1" \
--data-generation=dataset \
--data-set=kaggle \
--raw-data-file=$data/train.txt \
--processed-data-file=$data/kaggleAdDisplayChallenge_processed.npz \
--loss-function=bce \
--round-targets=True \
--learning-rate=0.1 \
--mini-batch-size=128 \
--print-freq=1024 \
--print-time \
--test-mini-batch-size=16384 \
--test-num-workers=16 \
--use-tpu \
--memory-map \
--num-indices-per-lookup=1 \
--num-indices-per-lookup-fixed \
--tpu-model-parallel-group-len 8 \
--tpu-metrics-debug \
--tpu-cores=8
Expected behavior
finish training without segfault.
Environment
- Reproducible on XLA backend TPU
- torch_xla version: nightly
Additional context
I used the core generated by @taylanbil's run and see the frame
#0 0x00007efe41d0da63 in std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow (this=0x7efc00000002, __c=84)
at /home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-l
inux-gnu/libstdc++-v3/include/ext/new_allocator.h:89
#1 0x00007efe41d10cc3 in std::basic_streambuf<char, std::char_traits<char> >::xsputn (this=0x7efcfe7eb868, __s=0x7efe363f7ded "Tensor(", __n=22)
at /home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-l
inux-gnu/libstdc++-v3/include/bits/char_traits.h:384
#2 0x00007efe41d0ba40 in std::__ostream_write<char, std::char_traits<char> > (__out=..., __s=<optimized out>, __n=22)
at /home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-l
inux-gnu/libstdc++-v3/include/bits/ostream_insert.h:44
#3 0x00007efe41d0bb18 in std::__ostream_insert<char, std::char_traits<char> > (__out=..., __s=0x7efe363f7dde "XRTAllocateFromTensor(", __n=22)
at /home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-l
inux-gnu/libstdc++-v3/include/bits/basic_ios.h:180
#4 0x00007efe2d40a8fd in xla::XrtComputationClient::GetAllocateNode(xla::XrtSession*, tensorflow::Scope const&, std::__cxx11::basic_string<char, std
::char_traits<char>, std::allocator<char> > const&, xla::Shape const&) const ()
from /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so
#5 0x00007efe2d412791 in std::_Function_handler<void (), xla::XrtComputationClient::TransferToServerInternal(absl::lts_2020_02_25::Span<xla::Computa
tionClient::TensorSource const>)::$_1>::_M_invoke(std::_Any_data const&) ()
from /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so
#6 0x00007efe2d3e4a43 in std::_Function_handler<void (), xla::util::MultiWait::Completer(std::function<void ()>)::$_2>::_M_invoke(std::_Any_data con
st&) () from /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so
#7 0x00007efe2d3e7a61 in std::thread::_State_impl<std::_Bind_simple<xla::env::(anonymous namespace)::ThreadPool::ThreadPool(unsigned long)::{lambda(
)#1} ()> >::_M_run() () from /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so
#8 0x00007efe41cde19d in std::execute_native_thread_routine (__p=0x5605183cd170)
at /home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/src/gcc/libstdc++-v3/src/c++11/thread.cc:80
#9 0x00007efe5382d4a4 in start_thread (arg=0x7efcfe7ec700) at pthread_create.c:456
#10 0x00007efe5356fd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
I think what happened was we error out while transferring data from host to the device. Looking at the core dump, the error came from when we try to allocate the node when calling TransferToServerInternal. It seems like we are trying to write 22 character to buffer's controlled output sequence, and then that output sequence does not have enough space. basic_stringbuf::overflow is called to rearrange/reallocate the buffer to make enough space. However we error out in this phase.
I was suspecting if this is due to host oom, but the memory usage was pretty stable through the training
jackcao@pytorch-xla-img-eu:~$ free -h
total used free shared buff/cache available
Mem: 236G 36G 190G 68M 9.2G 197G
Swap: 0B 0B 0B
Looking into basic_stringbuf::overflow to check what might cause the segfault.
There is another failure that is related to XRTAllocateFromTensor but seems to be different.
Exception in thread Thread-2:
Traceback (most recent call last):
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/threading.py", line 916, in _bootstrap_inner
self.run()
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/threading.py", line 864, in run
self._target(*self._args, **self._kwargs)
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/distributed/parallel_loader.py", line 172, in _worker
batch = xm.send_cpu_data_to_device(batch, device)
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/core/xla_model.py", line 841, in send_cpu_data_to_device
return ToXlaTensorArena(convert_fn, select_fn).transform(data)
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/core/xla_model.py", line 410, in transform
self._convert()
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/core/xla_model.py", line 382, in _convert
self._converted_tensors = self._convert_fn(self._tensors)
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/core/xla_model.py", line 836, in convert_fn
return torch_xla._XLAC._xla_tensors_from_aten(tensors, devices)
RuntimeError: tensorflow/compiler/xla/xla_client/xrt_computation_client.cc:381 : Check failed: session->session()->Run( session_work->feed_inputs, session_work->outputs_handles, &outputs) == ::tensorflow::Status::OK() (Invalid argument: From /job:tpu_worker/replica:0/task:0:
2 root error(s) found.
(0) Invalid argument: Input tensor must have the number of elements specified in the matching input shape: 128 vs. 1664 at index 0
[[{{node XRTAllocateFromTensor_19}}]]
[[_recv_Placeholder_13_0_G151]]
(1) Invalid argument: Input tensor must have the number of elements specified in the matching input shape: 128 vs. 1664 at index 0
[[{{node XRTAllocateFromTensor_19}}]]
0 successful operations.
0 derived errors ignored. vs. OK)
*** Begin stack trace ***
tensorflow::CurrentStackTrace[abi:cxx11]()
JackCaoG
All 63 comments
Now I looked at the frame more closely, failure actually is unrelated to the tensor nor shape. The actually failure came from
std::stringstream ss;
ss << "XRTAllocateFromTensor(" << shape << ")";
This is used to construct the key to do the cache lookup below
XrtSession::NodeCache* cache =
session->GetNodeCache(XrtSession::GetCacheKey(ss.str(), device));
Trying to think how can we seg fault from writing to stringstream
JackCaoG
on 22 Jul 2020
Log and the core dump seems to be two different problems, although all related to XRTAllocateFromTensor. Rerunning the training with ulimit -c 10000000.
JackCaoG
on 22 Jul 2020
I'd add git clone -b tpu-criteo-kaggle https://github.com/taylanbil/dlrm.git to the repro instructions. Oh and to download and process the criteo-kaggle dataset :/
Others have reported that the code on this branch runs fine for them on a beefier GCE vm than the one I have. That's what I'm trying to repro now.
taylanbil
on 22 Jul 2020
I made an n1-hihgmem-96 and my first run completed e2e succesfully. Unfortunately, my second run failed.
taylanbil
on 22 Jul 2020
Sorry, still a bit busy with the move, and I still have to setup my personal laptop so can't go deep.
This is using nightly, 100% sure, right? We did a change last week that might have led to issues.
Does it happen single core?
davidel
on 23 Jul 2020
Ah it's actually using a nightly from a few days ago.
In [3]: torch_xla.__version__
Out[3]: '1.6+9b55685'
I'm trying now w/ latest nightly.
taylanbil
on 23 Jul 2020
The single core version of this model won't have any complicated collective ops etc, and also I cannot run this model single core because it doesn't fit all 26 tables in 1 core..
taylanbil
on 23 Jul 2020
Crash happens w/ latest nightly.
taylanbil
on 24 Jul 2020
And it is consistently in the same place?
davidel
on 24 Jul 2020
No, it s different every time.
On Thu, Jul 23, 2020, 22:03 Davide Libenzi notifications@github.com wrote:
And it is consistently in the same place?
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/pytorch/xla/issues/2366#issuecomment-663347748, or
unsubscribe
https://github.com/notifications/unsubscribe-auth/ABDAQYPCAORWU2V73TC2CNLR5EIZRANCNFSM4PEGP6JQ
.
taylanbil
on 24 Jul 2020
But the crash stack trace is the same, right?
davidel
on 24 Jul 2020
I have seen two versions. One that occurs 85-90÷ of the time, and another
that occurs in the rest. I can paste both tmrw here.
On Thu, Jul 23, 2020, 22:12 Davide Libenzi notifications@github.com wrote:
But the crash stack trace is the same, right?
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/pytorch/xla/issues/2366#issuecomment-663349677, or
unsubscribe
https://github.com/notifications/unsubscribe-auth/ABDAQYIWO3Z3HBBMWJENHULR5EJ3TANCNFSM4PEGP6JQ
.
taylanbil
on 24 Jul 2020
This trace occurs for almost all the runs: https://gist.github.com/taylanbil/7b6bd83ceb937b665a9f67e47e19f514
I've also seen this once:
Exception in thread Thread-2:
Traceback (most recent call last):
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/threading.py", line 916, in _bootstrap_inner
self.run()
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/threading.py", line 864, in run
self._target(*self._args, **self._kwargs)
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/distributed/parallel_loader.py", line 172, in _worker
batch = xm.send_cpu_data_to_device(batch, device)
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/core/xla_model.py", line 841, in send_cpu_data_to_device
return ToXlaTensorArena(convert_fn, select_fn).transform(data)
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/core/xla_model.py", line 410, in transform
self._convert()
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/core/xla_model.py", line 382, in _convert
self._converted_tensors = self._convert_fn(self._tensors)
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/core/xla_model.py", line 836, in convert_fn
return torch_xla._XLAC._xla_tensors_from_aten(tensors, devices)
RuntimeError: tensorflow/compiler/xla/xla_client/xrt_computation_client.cc:381 : Check failed: session->session()->Run( session_work->feed_inputs, session_work->outputs_handles, &outputs) == ::tensorflow::Status::OK() (Invalid argument: From /job:tpu_worker/replica:0/task:0:
2 root error(s) found.
(0) Invalid argument: Input tensor must have the number of elements specified in the matching input shape: 128 vs. 1664 at index 0
[[{{node XRTAllocateFromTensor_19}}]]
[[_recv_Placeholder_13_0_G151]]
(1) Invalid argument: Input tensor must have the number of elements specified in the matching input shape: 128 vs. 1664 at index 0
[[{{node XRTAllocateFromTensor_19}}]]
0 successful operations.
0 derived errors ignored. vs. OK)
*** Begin stack trace ***
tensorflow::CurrentStackTrace[abi:cxx11]()
clone
*** End stack trace ***
I looked at the core file a bit more and here is my finding(bt is at the first comment).
FYI I did a set substitute-path '/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include' '/usr/include/c++/6' in gdb so the C++ source code mapping might not be 100% correct, but the assembly code shouldn't be impacted.
- I installed the debug info and run
disas/s. I saw
(gdb) disas/s
Dump of assembler code for function std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int):
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/bits
/ios_base.h:
125 operator&(_Ios_Openmode __a, _Ios_Openmode __b)
126 { return _Ios_Openmode(static_cast<int>(__a) & static_cast<int>(__b)); }
0x00007efe41d0d960 <+0>: push %r13
0x00007efe41d0d962 <+2>: push %r12
0x00007efe41d0d964 <+4>: push %rbp
0x00007efe41d0d965 <+5>: push %rbx
0x00007efe41d0d966 <+6>: sub $0x28,%rsp
0x00007efe41d0d96a <+10>: testb $0x10,0x40(%rdi)
0x00007efe41d0d96e <+14>: je 0x7efe41d0dac7 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+359>
0x00007efe41d0d974 <+20>: mov %esi,%r12d
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/bits
/char_traits.h:
388 return __s;
0x00007efe41d0d977 <+23>: cmp $0xffffffff,%esi
0x00007efe41d0d97a <+26>: je 0x7efe41d0dac2 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+354>
0x00007efe41d0d980 <+32>: mov 0x48(%rdi),%rbp
0x00007efe41d0d984 <+36>: lea 0x58(%rdi),%rax
0x00007efe41d0d988 <+40>: mov %rdi,%rbx
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/bits
/basic_string.h:
993 */
0x00007efe41d0d98b <+43>: mov $0xf,%edx
0x00007efe41d0d990 <+48>: cmp %rax,%rbp
0x00007efe41d0d993 <+51>: je 0x7efe41d0d999 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+57>
0x00007efe41d0d995 <+53>: mov 0x58(%rdi),%rdx
0x00007efe41d0d999 <+57>: mov 0x30(%rbx),%rax
0x00007efe41d0d99d <+61>: mov 0x20(%rbx),%rsi
0x00007efe41d0d9a1 <+65>: mov 0x28(%rbx),%rcx
0x00007efe41d0d9a5 <+69>: mov %rax,%rdi
0x00007efe41d0d9a8 <+72>: sub %rsi,%rdi
0x00007efe41d0d9ab <+75>: cmp %rdx,%rdi
0x00007efe41d0d9ae <+78>: jae 0x7efe41d0d9f9 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+153>
0x00007efe41d0d9b0 <+80>: sub %rsi,%rcx
0x00007efe41d0d9b3 <+83>: add %rbp,%rdx
0x00007efe41d0d9b6 <+86>: mov %rbp,%rsi
0x00007efe41d0d9b9 <+89>: mov %rbx,%rdi
0x00007efe41d0d9bc <+92>: callq 0x7efe41cbaf10 <_ZNSt7__cxx1115basic_stringbufIcSt11char_traitsIcESaIcEE8_M_pbumpEPcS5_l@plt>
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/bits
/ios_base.h:
126 { return _Ios_Openmode(static_cast<int>(__a) & static_cast<int>(__b)); }
0x00007efe41d0d9c1 <+97>: testb $0x8,0x40(%rbx)
0x00007efe41d0d9c5 <+101>: je 0x7efe41d0d9ed <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+141>
0x00007efe41d0d9c7 <+103>: mov 0x8(%rbx),%rdx
0x00007efe41d0d9cb <+107>: mov 0x18(%rbx),%rax
0x00007efe41d0d9cf <+111>: mov %rbp,0x8(%rbx)
0x00007efe41d0d9d3 <+115>: sub %rdx,%rax
0x00007efe41d0d9d6 <+118>: lea 0x1(%rbp,%rax,1),%rcx
0x00007efe41d0d9db <+123>: mov 0x10(%rbx),%rax
0x00007efe41d0d9df <+127>: mov %rcx,0x18(%rbx)
0x00007efe41d0d9e3 <+131>: add %rbp,%rax
0x00007efe41d0d9e6 <+134>: sub %rdx,%rax
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/stre
ambuf:
516 // [27.5.2.3.2] put area access
0x00007efe41d0d9e9 <+137>: mov %rax,0x10(%rbx)
0x00007efe41d0d9ed <+141>: mov 0x28(%rbx),%rax
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/bits
/char_traits.h:
378 {
0x00007efe41d0d9f1 <+145>: mov %r12b,(%rax)
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/stre
ambuf:
552 * @a __pend == @c epptr()
0x00007efe41d0d9f4 <+148>: jmpq 0x7efe41d0dabc <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+348>
0x00007efe41d0d9f9 <+153>: movabs $0x3fffffffffffffff,%rsi
0x00007efe41d0da03 <+163>: cmp %rsi,%rdx
0x00007efe41d0da06 <+166>: jne 0x7efe41d0da11 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+177>
0x00007efe41d0da08 <+168>: cmp %rax,%rcx
0x00007efe41d0da0b <+171>: jae 0x7efe41d0dac7 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+359>
0x00007efe41d0da11 <+177>: mov %r12d,%r13d
0x00007efe41d0da14 <+180>: cmp %rax,%rcx
0x00007efe41d0da17 <+183>: jb 0x7efe41d0dab9 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+345>
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/ext/
new_allocator.h:
---Type <return> to continue, or q <return> to quit---
83 template<typename _Tp1>
0x00007efe41d0da1d <+189>: add %rdx,%rdx
0x00007efe41d0da20 <+192>: mov $0x200,%esi
0x00007efe41d0da25 <+197>: lea 0x10(%rsp),%rax
0x00007efe41d0da2a <+202>: mov %rsp,%rbp
0x00007efe41d0da2d <+205>: cmp $0x200,%rdx
0x00007efe41d0da34 <+212>: mov %rax,(%rsp)
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/bits/basic_string.h:
214 typedef typename std::__is_integer<_InIterator>::__type _Integral;
0x00007efe41d0da38 <+216>: movabs $0x3fffffffffffffff,%rax
0x00007efe41d0da42 <+226>: mov %rbp,%rdi
0x00007efe41d0da45 <+229>: cmovae %rdx,%rsi
0x00007efe41d0da49 <+233>: movb $0x0,0x10(%rsp)
0x00007efe41d0da4e <+238>: movq $0x0,0x8(%rsp)
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/ext/new_allocator.h:
89 address(reference __x) const _GLIBCXX_NOEXCEPT
0x00007efe41d0da57 <+247>: cmp %rax,%rsi
0x00007efe41d0da5a <+250>: cmova %rax,%rsi
0x00007efe41d0da5e <+254>: callq 0x7efe41cbddf0 <_ZNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEE7reserveEm@plt>
=> 0x00007efe41d0da63 <+259>: mov 0x20(%rbx),%rsi
0x00007efe41d0da67 <+263>: test %rsi,%rsi
0x00007efe41d0da6a <+266>: je 0x7efe41d0da7b <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+283>
0x00007efe41d0da6c <+268>: mov 0x30(%rbx),%rdx
0x00007efe41d0da70 <+272>: mov %rbp,%rdi
0x00007efe41d0da73 <+275>: sub %rsi,%rdx
0x00007efe41d0da76 <+278>: callq 0x7efe41cb8250 <_ZNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEE6assignEPKcm@plt>
0x00007efe41d0da7b <+283>: movsbl %r13b,%esi
0x00007efe41d0da7f <+287>: mov %rbp,%rdi
0x00007efe41d0da82 <+290>: callq 0x7efe41cbd270 <_ZNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEE9push_backEc@plt>
0x00007efe41d0da87 <+295>: lea 0x48(%rbx),%rdi
0x00007efe41d0da8b <+299>: mov %rbp,%rsi
0x00007efe41d0da8e <+302>: callq 0x7efe41cbc770 <_ZNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEE4swapERS4_@plt>
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/bits/basic_string.h:
2312 * @return Index of first occurrence.
0x00007efe41d0da93 <+307>: mov 0x48(%rbx),%rsi
0x00007efe41d0da97 <+311>: mov 0x28(%rbx),%rcx
0x00007efe41d0da9b <+315>: mov %rbx,%rdi
0x00007efe41d0da9e <+318>: mov 0x10(%rbx),%rdx
0x00007efe41d0daa2 <+322>: sub 0x20(%rbx),%rcx
0x00007efe41d0daa6 <+326>: sub 0x8(%rbx),%rdx
0x00007efe41d0daaa <+330>: callq 0x7efe41cbc6c0 <_ZNSt7__cxx1115basic_stringbufIcSt11char_traitsIcESaIcEE7_M_syncEPcmm@plt>
657 {
0x00007efe41d0daaf <+335>: mov %rbp,%rdi
0x00007efe41d0dab2 <+338>: callq 0x7efe41cbd480 <_ZNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEE10_M_disposeEv@plt>
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/ext/new_allocator.h:
89 address(reference __x) const _GLIBCXX_NOEXCEPT
0x00007efe41d0dab7 <+343>: jmp 0x7efe41d0dabc <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+348>
0x00007efe41d0dab9 <+345>: mov %r12b,(%rcx)
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/streambuf:
552 * @a __pend == @c epptr()
0x00007efe41d0dabc <+348>: incq 0x28(%rbx)
0x00007efe41d0dac0 <+352>: jmp 0x7efe41d0dae0 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+384>
0x00007efe41d0dac2 <+354>: xor %r12d,%r12d
0x00007efe41d0dac5 <+357>: jmp 0x7efe41d0dae0 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+384>
0x00007efe41d0dac7 <+359>: or $0xffffffff,%r12d
0x00007efe41d0dacb <+363>: jmp 0x7efe41d0dae0 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+384>
0x00007efe41d0dacd <+365>: mov %rax,%r12
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/bits/basic_string.h:
657 {
0x00007efe41d0dad0 <+368>: mov %rbp,%rdi
0x00007efe41d0dad3 <+371>: callq 0x7efe41cbd480 <_ZNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEE10_M_disposeEv@plt>
/home/nwani/m3/conda-bld/compilers_linux-64_1560109574129/work/.build/x86_64-conda_cos6-linux-gnu/build/build-cc-gcc-final/x86_64-conda_cos6-linux-gnu/libstdc++-v3/include/ext/new_allocator.h:
89 address(reference __x) const _GLIBCXX_NOEXCEPT
0x00007efe41d0dad8 <+376>: mov %r12,%rdi
0x00007efe41d0dadb <+379>: callq 0x7efe41cbe4c0 <_Unwind_Resume@plt>
0x00007efe41d0dae0 <+384>: add $0x28,%rsp
0x00007efe41d0dae4 <+388>: mov %r12d,%eax
0x00007efe41d0dae7 <+391>: pop %rbx
0x00007efe41d0dae8 <+392>: pop %rbp
---Type <return> to continue, or q <return> to quit---
0x00007efe41d0dae9 <+393>: pop %r12
0x00007efe41d0daeb <+395>: pop %r13
0x00007efe41d0daed <+397>: retq
End of assembler dump.
I used my /usr/include/lib as the source code, which might not be 100% match with the lib that this core used so I also find this. In line 89 where the segfault happens we have
88 pointer
89 address(reference __x) const _GLIBCXX_NOEXCEPT
90 { return std::__addressof(__x); }
Looking at the assembly and register state,
0x00007efe41d0da5e <+254>: callq 0x7efe41cbddf0 <_ZNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEE7reserveEm@plt>
=> 0x00007efe41d0da63 <+259>: mov 0x20(%rbx),%rsi
0x00007efe41d0da67 <+263>: test %rsi,%rsi
(gdb) i r
rax 0x200 512
rbx 0x7efc00000002 139620796858370
rcx 0x7efb2c000020 139617240088608
rdx 0x1 1
rsi 0x7efcfe7eb610 139625066575376
rdi 0x7efcfe7eb610 139625066575376
rbp 0x7efcfe7eb600 0x7efcfe7eb600
rsp 0x7efcfe7eb600 0x7efcfe7eb600
r8 0x7efcfe7eb610 139625066575376
r9 0x210 528
r10 0x5 5
r11 0x7efe535f1060 139630785532000
r12 0x54 84
r13 0x54 84
r14 0x7efe363f7dde 139630296923614
r15 0x7efcfe7ebb30 139625066576688
rip 0x7efe41d0da63 0x7efe41d0da63 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+259>
eflags 0x10206 [ PF IF RF ]
cs 0x33 51
ss 0x2b 43
ds 0x0 0
es 0x0 0
fs 0x0 0
gs 0x0 0
k0 0x0 0
k1 0xff00 65280
k2 0xf0 240
k3 0x0 0
k4 0x0 0
k5 0x0 0
k6 0x0 0
k7 0x0 0
md5-f580e7af1a02dbe64ef7faa9d7553850
(gdb) x/8b 0x7efc00000002
0x7efc00000002: Cannot access memory at address 0x7efc00000002
(gdb) x/8b 0x7efc00000022
0x7efc00000022: Cannot access memory at address 0x7efc00000022
(gdb) x/8b 0x7efe41d0da63
0x7efe41d0da63 <std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+259>: 72 -117 115 32 72 -123 -10 116
(gdb) x/8b 0x7efcfe7eb610
0x7efcfe7eb610: 0 2 0 0 0 0 0 0
Since %rbx has been used in previous assembly code, I am suspecting the call to std::basic_string::reserve right above is the function that set's the corrupted value to the %rbx. If my theory is correct, then the question become why std::basic_string::reserve move register to a memory address that can not be accessed..
JackCaoG
on 25 Jul 2020
Also posting the memory map as a reference to the register value
Mapped address spaces:
Start Addr End Addr Size Offset objfile
0x560513610000 0x560513667000 0x57000 0x0 /anaconda3/envs/torch-xla-nightly/bin/python3.6
0x560513667000 0x56051382f000 0x1c8000 0x57000 /anaconda3/envs/torch-xla-nightly/bin/python3.6
0x56051382f000 0x5605138cd000 0x9e000 0x21f000 /anaconda3/envs/torch-xla-nightly/bin/python3.6
0x5605138cd000 0x5605138d0000 0x3000 0x2bc000 /anaconda3/envs/torch-xla-nightly/bin/python3.6
0x5605138d0000 0x560513933000 0x63000 0x2bf000 /anaconda3/envs/torch-xla-nightly/bin/python3.6
0x7efe25c48000 0x7efe25c52000 0xa000 0x0 /lib/x86_64-linux-gnu/libnss_files-2.24.so
0x7efe25c52000 0x7efe25e52000 0x200000 0xa000 /lib/x86_64-linux-gnu/libnss_files-2.24.so
0x7efe25e52000 0x7efe25e53000 0x1000 0xa000 /lib/x86_64-linux-gnu/libnss_files-2.24.so
0x7efe25e53000 0x7efe25e54000 0x1000 0xb000 /lib/x86_64-linux-gnu/libnss_files-2.24.so
0x7efe26e63000 0x7efe26e6c000 0x9000 0x0 /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/sklearn/utils/_cython_blas.cpython-36m-x86_64-linux-gnu.so
0x7efe26e6c000 0x7efe26eb8000 0x4c000 0x9000 /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/sklearn/utils/_cython_blas.cpython-36m-x86_64-linux-gnu.so
0x7efe26eb8000 0x7efe26ec4000 0xc000 0x55000 /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/sklearn/utils/_cython_blas.cpython-36m-x86_64-linux-gnu.so
It's hard to see from the dumps, but it looks like a memory corruption to me.
It could also be a stdc++ library version linking mismatch, but I'd shoot for memory corruption first.
Can the same VM pass the C++ and Python tests? This is to try first.
I'd also try to run under tcmalloc to see whether it reveals more info or failure mode (the path where the library is install might vary depending on the distro and OS version):
apt-get install -y gperftools
LD_PRELOAD=/usr/lib/libtcmalloc_minimal_debug.so.VER ...
The slowest but likely more effective catcher is to run under Valgrind memcheck.
davidel
on 25 Jul 2020
Can the same VM pass the C++ and Python tests? This is to try first.
I'll try this on Monday, but I had the suspiician that there was something wrong w/ my specific vm, so I made a brand new vm on Friday and the crash happened there as well.
Along with your suggestions, I'll also try to just iterate on the data. I suspect there could be a bug in that part of things.
taylanbil
on 25 Jul 2020
Running the Python and C++ tests clears the idea of libraries being linked correctly.
You should also disable shuffling, which could give a better idea if this is data related.
davidel
on 26 Jul 2020
After setting the shuffle to False in here, segfault happens in 70k steps(instead of 200k). The python traceback suggest the failure is in the same palce
File "/home/taylanbil/dlrm/dlrm_s_pytorch.py", line 478, in forward
return self.tpu_parallel_forward(dense_x, lS_o, lS_i)
File "/home/taylanbil/dlrm/dlrm_s_pytorch.py", line 583, in tpu_parallel_forward
ly = self._collect_distribute_embeddings(ly_local)
File "/home/taylanbil/dlrm/dlrm_s_pytorch.py", line 583, in tpu_parallel_forward
ly = self._collect_distribute_embeddings(ly_local)
File "/home/taylanbil/dlrm/dlrm_s_pytorch.py", line 521, in _collect_distribute_embeddings
full_data = full_data[self._non_pad_indices]
File "/home/taylanbil/dlrm/dlrm_s_pytorch.py", line 521, in _collect_distribute_embeddings
full_data = full_data[self._non_pad_indices]
Taylan was using update_torch_wheels.sh to update the pt/xla. Directlly running the cpp test gave me error like
/usr/include/c++/6/bits/locale_facets_nonio.tcc:352:33: error: operator '&&' has no right operand
&& _GLIBCXX_USE_CXX11_ABI == 0
and
In file included from /usr/share/torch-xla-nightly/pytorch/xla/test/cpp/test_xla_util_cache.cpp:5:0:
/usr/share/torch-xla-nightly/pytorch/xla/test/cpp/cpp_test_util.h:11:29: fatal error: absl/types/span.h: No such file or directory
#include "absl/types/span.h"
Trying to build from the source and see if I can run the test
JackCaoG
on 27 Jul 2020
After setting the shuffle to False in here, segfault happens in 70k steps(instead of 200k). The python traceback suggest the failure is in the same palce
File "/home/taylanbil/dlrm/dlrm_s_pytorch.py", line 478, in forward return self.tpu_parallel_forward(dense_x, lS_o, lS_i) File "/home/taylanbil/dlrm/dlrm_s_pytorch.py", line 583, in tpu_parallel_forward ly = self._collect_distribute_embeddings(ly_local) File "/home/taylanbil/dlrm/dlrm_s_pytorch.py", line 583, in tpu_parallel_forward ly = self._collect_distribute_embeddings(ly_local) File "/home/taylanbil/dlrm/dlrm_s_pytorch.py", line 521, in _collect_distribute_embeddings full_data = full_data[self._non_pad_indices] File "/home/taylanbil/dlrm/dlrm_s_pytorch.py", line 521, in _collect_distribute_embeddings full_data = full_data[self._non_pad_indices]
Good hint. It likely means it is data related.
I'd debug around that path from tensor_util.cpp and xrt_computation_client.cpp.
Could be there is a weird tensor for which we compute wrong size, and end up overriding memory.
Running under valgrind (maybe trying to isolate the offending sample data to speed up debugging) would help here.
Linking bad libstdc++ was the other thing under suspect. This is why I was asking to run vanilla tests.
I'd follow both leads.
davidel
on 27 Jul 2020
I built the pytorch and the pytorch/xla from the source and run all python and cpp tests, all of them passed. I started a run without valgrind to verify if pt/xla built from source will behave any different than the pt/xla installed by the wheel. This time the dlrm successfully finished.
I will start another run and report the result when it is done. It takes around 3 hour to finish a successful run.
JackCaoG
on 28 Jul 2020
second run crashed around 120k steps, will try valgrind tomorrow.
JackCaoG
on 28 Jul 2020
If you are able to isolate the sample where the crash happen (without shuffle), it can help with valgrind testing.
This especially if you have to run a few times.
valgrind uses dynamic recompilation and adds a lot of memory checks, so the speed is quite a bit slower than native.
I guess you can start running once and check how long it takes to get there.
It can produce a loy of data, so you may want to pipe the output to a file.
davidel
on 28 Jul 2020
Thanks @davidel! @taylanbil could you help isolating the offending sample?
JackCaoG
on 28 Jul 2020
valgrind speed is in the ballpark of 1/10 of native.
Our case is a bit different because a lot of time is TPU execution time, but those tensor memory conversions might be costly.
You could start one run to see how long it takes.
If we are lucky we get enough info from the first run (remember to pipe to a file).
davidel
on 28 Jul 2020
Taylan suggested we might be able to repo the issue with only iterating the data. I tried this idea and saw the segfault around 90k and 240k steps (It doesn't print any python frame when segfault through).
246525
246526
246527
246528
246529
Traceback (most recent call last):
File "dlrm/dlrm_tpu_runner.py", line 15, in <module>
xmp.spawn(main, args=(), nprocs=pre_spawn_flags.tpu_cores)
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/distributed/xla_multiprocessing.py", line 395, in spawn
start_method=start_method)
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch/multiprocessing/spawn.py", line 158, in start_processes
while not context.join():
File "/anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch/multiprocessing/spawn.py", line 108, in join
(error_index, name)
Exception: process 7 terminated with signal SIGSEGV
I am trying to use valgrind with this iteration only script to see if I can find anything. However there are too many errors about PyObject_Free****. I will add a suppression file and rerun it under valgrind.
JackCaoG
on 28 Jul 2020
Jack, could you see if we disable parallelloader, we re able to iterate
fully? I suspect this could be an upstream dlrm data issue.
Also, does crash happen always the same place in this mode?
On Tue, Jul 28, 2020, 13:55 JackCaoG notifications@github.com wrote:
Taylan suggested we might be able to repo the issue with only iterating
the data. I tried this idea and saw the segfault around 90k steps (It
doesn't print any python frame when segfault through). I am trying to use
valgrind with this iteration only script to see if I can find anything.
However there are too many errors about PyObject_Free**. I will add a
suppression file and rerun it under valgrind.—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/pytorch/xla/issues/2366#issuecomment-665277698, or
unsubscribe
https://github.com/notifications/unsubscribe-auth/ABDAQYOXSFXGFGE22JDOWLTR543LDANCNFSM4PEGP6JQ
.
taylanbil
on 28 Jul 2020
I am running without parallelloader to verify. The crash (of only iterating the data with parallelloader) happens first time around 90k, and then 240k.
JackCaoG
on 29 Jul 2020
All runs without parallelloader passed. Then I tried to run with the parallelloader (original segfault case) with the valgrind.
However valgrind exited with following message
==91803==
==91803== Process terminating with default action of signal 4 (SIGILL)
==91803== Illegal opcode at address 0xB83AC80
==91803== at 0xB83AC80: __intel_mkl_features_init_x (in /anaconda3/envs/torch-xla-nightly/lib/libmkl_core.so)
==91803== by 0x92D9DD6: mkl_serv_domain_get_max_threads (in /anaconda3/envs/torch-xla-nightly/lib/libmkl_intel_thread.so)
==91803== by 0x11FE4945: at::init_num_threads() (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch/lib/libtorch_cpu.so)
==91803== by 0x104B42A6: initModule (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch/lib/libtorch_python.so)
==91803== by 0x31F334: ??? (in /anaconda3/envs/torch-xla-nightly/bin/python3.6)
==91803== by 0x35C18A: ??? (in /anaconda3/envs/torch-xla-nightly/bin/python3.6)
==91803==
==91803== HEAP SUMMARY:
==91803== in use at exit: 22,973,452 bytes in 150,359 blocks
==91803== total heap usage: 457,678 allocs, 307,319 frees, 65,365,698 bytes allocated
==91803==
==91803== LEAK SUMMARY:
==91803== definitely lost: 47 bytes in 1 blocks
==91803== indirectly lost: 0 bytes in 0 blocks
==91803== possibly lost: 1,845,399 bytes in 17,753 blocks
==91803== still reachable: 21,128,006 bytes in 132,605 blocks
==91803== suppressed: 0 bytes in 0 blocks
==91803== Rerun with --leak-check=full to see details of leaked memory
I don't think this error has anything to do with the real segfault. This look like a compatibility issue between valgrind and our code. I am not sure where init_num_threads comes from since we should be using multi-processing but that function is using op codes that is not recognized by the Valgrind. My valgrind version is valgrind-3.12.0.SVN. Trying to see if there is a newer version that can resolve this issue.
JackCaoG
on 29 Jul 2020
I updated to Valgrind-3.16.1 solve the Illegal opcode issune. The command I used to run the dlrm is
valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp ./jack-bench-criteo-KAGGLE-fullmp.sh > /home/jackcao/allout.txt 2>&1
The run has not finished(no crash) but it does very few writes to the file after ~10 minutes. Not sure if this has to be with our multiprocess uses spawn instead of fork (so valgrind doesn't really track child process) or there just isn't anything wrong in the child process. Note that in this run we are not doing any training, we just iterating through the data. I had seen crashed happened just by iterating through the data.
The result of ps looks like
ps -aux | grep valgrind
jackcao 6866 0.0 0.0 103980 49732 pts/4 S+ 00:25 0:00 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp ./jack-bench-criteo-KAGGLE-fullmp.sh
jackcao 6890 2.4 0.1 1822740 1164976 pts/4 S+ 00:26 1:35 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 dlrm/dlrm_tpu_runner.py --arch-sparse-feature-size=16 --arch-mlp-bot=13-512-256-64-16 --arch-mlp-top=512-256-1 --data-generation=dataset --data-set=kaggle --raw-data-file=/home/taylanbil/debug/20200610-dlrm/geeta-data2//train.txt --processed-data-file=/home/taylanbil/debug/20200610-dlrm/geeta-data2//kaggleAdDisplayChallenge_processed.npz --loss-function=bce --round-targets=True --learning-rate=0.1 --mini-batch-size=128 --print-freq=1024 --print-time --test-mini-batch-size=16384 --test-num-workers=16 --use-tpu --num-indices-per-lookup=1 --num-indices-per-lookup-fixed --tpu-model-parallel-group-len 8 --tpu-metrics-debug --tpu-cores=8
jackcao 6911 0.1 0.0 156912 105488 pts/4 S+ 00:27 0:04 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.semaphore_tracker import main;main(5)
jackcao 6912 100 9.3 61453560 60204100 pts/4 Rl+ 00:27 63:55 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=10) --multiprocessing-fork
jackcao 6913 100 9.3 61171332 59941808 pts/4 Rl+ 00:27 63:49 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=13) --multiprocessing-fork
jackcao 6914 100 9.3 61368400 60126480 pts/4 Rl+ 00:27 63:46 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=16) --multiprocessing-fork
jackcao 6915 100 9.3 61206232 59982532 pts/4 Rl+ 00:27 63:45 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=19) --multiprocessing-fork
jackcao 6916 100 9.3 61184164 59953632 pts/4 Rl+ 00:27 63:49 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=22) --multiprocessing-fork
jackcao 6917 100 9.3 61263336 60016616 pts/4 Rl+ 00:27 63:57 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=25) --multiprocessing-fork
jackcao 6918 100 9.3 61309568 60083336 pts/4 Rl+ 00:27 63:45 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=28) --multiprocessing-fork
jackcao 6919 100 9.3 61377380 60138476 pts/4 Rl+ 00:27 63:45 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=31) --multiprocessing-fork
jackcao 6960 0.1 0.0 156912 105484 pts/4 S+ 00:29 0:04 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.semaphore_tracker import main;main(8)
jackcao 6961 0.1 0.0 156912 105480 pts/4 S+ 00:29 0:04 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.semaphore_tracker import main;main(5)
jackcao 6962 0.1 0.0 156912 105484 pts/4 S+ 00:29 0:04 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.semaphore_tracker import main;main(5)
jackcao 6975 0.1 0.0 156912 105480 pts/4 S+ 00:29 0:04 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.semaphore_tracker import main;main(5)
jackcao 6976 0.1 0.0 156912 105480 pts/4 S+ 00:29 0:04 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.semaphore_tracker import main;main(5)
jackcao 6978 0.1 0.0 156912 105480 pts/4 S+ 00:29 0:04 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.semaphore_tracker import main;main(5)
jackcao 6979 0.1 0.0 156912 105480 pts/4 S+ 00:29 0:04 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.semaphore_tracker import main;main(5)
jackcao 6980 0.1 0.0 156912 105484 pts/4 S+ 00:29 0:04 valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/home/jackcao/valgrind-python.supp /anaconda3/envs/torch-xla-nightly/bin/python3 -c from multiprocessing.semaphore_tracker import main;main(5)
jackcao 8127 0.0 0.0 12780 960 pts/3 S+ 01:31 0:00 grep valgrind
Attaching the output file.
allout (1).txt
I grep the xla related messages and didn't see much interesting stuff. Most invalid message are from /usr/bin/python2.7 or file descriptor. Will update or add a new comment when the run finishes or segfault.
JackCaoG
on 29 Jul 2020
Couple process exited with the message
==6914== Process terminating with default action of signal 15 (SIGTERM)
==6914== at 0x4E4617F: pthread_cond_wait@@GLIBC_2.3.2 (pthread_cond_wait.S:185)
==6914== by 0x194384CA: __gthread_cond_wait (gthr-default.h:878)
==6914== by 0x194384CA: std::condition_variable::wait(std::unique_lock<std::mutex>&) (condition_variable.cc:53)
==6914== by 0x275ED5AA: xla::util::MultiWait::Wait() (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==6914== by 0x275FB27D: xla::XrtComputationClient::TransferToServerInternal(absl::lts_2020_02_25::Span<xla::ComputationClient::TensorSource const>) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==6914== by 0x275FAA3E: xla::XrtComputationClient::TransferToServer(absl::lts_2020_02_25::Span<xla::ComputationClient::TensorSource const>) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==6914== by 0x24024A4D: TensorToXlaData (tensor_util.cpp:591)
==6914== by 0x24024A4D: torch_xla::TensorToXlaData(at::Tensor const&, torch_xla::Device const&) (tensor_util.cpp:727)
==6914== by 0x23EBA1A0: torch_xla::XLATensor::GetIrValueForTensor(at::Tensor const&, torch_xla::Device const&) const (tensor.cpp:702)
==6914== by 0x23EBDBCD: torch_xla::XLATensor::UpdateFromTensor(at::Tensor, bool) (tensor.cpp:859)
==6914== by 0x23F3C46F: torch_xla::AtenXlaType::copy_(at::Tensor&, at::Tensor const&, bool) (aten_xla_type.cpp:917)
==6914== by 0x12D7FB64: at::Tensor& c10::Dispatcher::callWithDispatchKey<at::Tensor&, at::Tensor&, at::Tensor const&, bool>(c10::TypedOperatorHandle<at::Tensor& (at::Tensor&, at::Tensor const&, bool)> const&, c10::DispatchKey, at::Tensor&, at::Tensor const&, bool) const (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch/lib/libtorch_cpu.so)
==6914== by 0x14DF1826: torch::autograd::VariableType::(anonymous namespace)::copy_(at::Tensor&, at::Tensor const&, bool) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch/lib/libtorch_cpu.so)
==6914== by 0x12D7FB64: at::Tensor& c10::Dispatcher::callWithDispatchKey<at::Tensor&, at::Tensor&, at::Tensor const&, bool>(c10::TypedOperatorHandle<at::Tensor& (at::Tensor&, at::Tensor const&, bool)> const&, c10::DispatchKey, at::Tensor&, at::Tensor const&, bool) const (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch/lib/libtorch_cpu.so)
This does look like a different issue, and the memory usage is really high
free -h
total used free shared buff/cache available
Mem: 614G 399G 214G 37M 736M 212G
Swap: 0B 0B 0B
I used PYTHONMALLOC=malloc python3 dlrm/dlrm_tpu_runner.py to avoid PyObject_Free log. I will remove the malloc flag and rerun the code.
JackCaoG
on 29 Jul 2020
After removing PYTHONMALLOC=malloc I kicked off second run with valgrind. It still haven't finished and the memory usage is very high.
free -h
total used free shared buff/cache available
Mem: 614G 520G 90G 37M 3.4G 90G
Swap: 0B 0B 0B
This time log does have something pretty interesting
==12373== Invalid read of size 4
==12373== at 0x1EB0CA: address_in_range (obmalloc.c:1218)
==12373== by 0x1EB0CA: _PyObject_Free (obmalloc.c:1486)
==12373== by 0x2A13CE: subtype_dealloc (typeobject.c:1222)
==12373== by 0x1F9857: dict_dealloc (dictobject.c:2017)
==12373== by 0x2A13B0: subtype_dealloc (typeobject.c:1207)
==12373== by 0x1F866A: free_keys_object (dictobject.c:562)
==12373== by 0x1F866A: PyDict_Clear (dictobject.c:1753)
==12373== by 0x1FC0F8: type_clear (typeobject.c:3384)
==12373== by 0x270EA1: delete_garbage (gcmodule.c:864)
==12373== by 0x270EA1: collect (gcmodule.c:1016)
==12373== by 0x2F8CF9: _PyGC_CollectNoFail (gcmodule.c:1626)
==12373== by 0x2ABA0D: PyImport_Cleanup (import.c:484)
==12373== by 0x3175F0: Py_FinalizeEx (pylifecycle.c:608)
==12373== by 0x317758: Py_Exit (pylifecycle.c:1561)
==12373== by 0x317847: handle_system_exit (pythonrun.c:626)
==12373== Address 0x3311d020 is 16 bytes before a block of size 64 alloc'd
==12373== at 0x4C2C59C: operator new(unsigned long) (vg_replace_malloc.c:342)
==12373== by 0x2EBE324D: std::_Function_base::_Base_manager<tensorflow::variant_op_registry_fn_registration::UnaryVariantUnaryOpRegistration<double>::UnaryVariantUnaryOpRegistration(tensorflow::Varia\
ntUnaryOp, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, tensorflow::TypeIndex const&, std::function<tensorflow::Status (tensorflow::OpKernelContext*, double co\
nst&, double*)> const&)::{lambda(tensorflow::OpKernelContext*, tensorflow::Variant const&, tensorflow::Variant*)#1}>::_M_clone(std::_Any_data&, std::_Function_base::_Base_manager<tensorflow::variant_op_\
registry_fn_registration::UnaryVariantUnaryOpRegistration<double>::UnaryVariantUnaryOpRegistration(tensorflow::VariantUnaryOp, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<cha\
r> > const&, tensorflow::TypeIndex const&, std::function<tensorflow::Status (tensorflow::OpKernelContext*, double const&, double*)> const&)::{lambda(tensorflow::OpKernelContext*, tensorflow::Variant con\
st&, tensorflow::Variant*)#1}> const&, std::integral_constant<bool, false>) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12373== by 0x2EBE2E45: std::_Function_base::_Base_manager<tensorflow::variant_op_registry_fn_registration::UnaryVariantUnaryOpRegistration<double>::UnaryVariantUnaryOpRegistration(tensorflow::Varia\
ntUnaryOp, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, tensorflow::TypeIndex const&, std::function<tensorflow::Status (tensorflow::OpKernelContext*, double co\
nst&, double*)> const&)::{lambda(tensorflow::OpKernelContext*, tensorflow::Variant const&, tensorflow::Variant*)#1}>::_M_manager(std::_Any_data&, std::_Function_base::_Base_manager<tensorflow::variant_o\
p_registry_fn_registration::UnaryVariantUnaryOpRegistration<double>::UnaryVariantUnaryOpRegistration(tensorflow::VariantUnaryOp, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<c\
har> > const&, tensorflow::TypeIndex const&, std::function<tensorflow::Status (tensorflow::OpKernelContext*, double const&, double*)> const&)::{lambda(tensorflow::OpKernelContext*, tensorflow::Variant c\
onst&, tensorflow::Variant*)#1}> const&, std::_Manager_operation) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12373== by 0x2BA90796: tensorflow::UnaryVariantOpRegistry::RegisterUnaryOpFn(tensorflow::VariantUnaryOp, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, tens\
orflow::TypeIndex const&, std::function<tensorflow::Status (tensorflow::OpKernelContext*, tensorflow::Variant const&, tensorflow::Variant*)> const&) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/s\
ite-packages/torch_xla/lib/libxla_computation_client.so)
==12373== by 0x2EBDCA75: tensorflow::variant_op_registry_fn_registration::UnaryVariantUnaryOpRegistration<double>::UnaryVariantUnaryOpRegistration(tensorflow::VariantUnaryOp, std::__cxx11::basic_stri\
ng<char, std::char_traits<char>, std::allocator<char> > const&, tensorflow::TypeIndex const&, std::function<tensorflow::Status (tensorflow::OpKernelContext*, double const&, double*)> const&) (in /anacon\
da3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12373== by 0x26253808: _GLOBAL__sub_I_variant_op_registry.cc (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12373== by 0x400F799: call_init.part.0 (dl-init.c:72)
==12373== by 0x400F8AA: call_init (dl-init.c:30)
==12373== by 0x400F8AA: _dl_init (dl-init.c:120)
==12373== by 0x4013E57: dl_open_worker (dl-open.c:575)
==12373== by 0x400F643: _dl_catch_error (dl-error.c:187)
==12373== by 0x4013608: _dl_open (dl-open.c:660)
==12373== by 0x53F5EE8: dlopen_doit (dlopen.c:66)
searching for libxla_computation_client.so in the log gave me quite a few more example like.
==12370== Invalid read of size 4
==12370== at 0x1EB0CA: address_in_range (obmalloc.c:1218)
==12370== by 0x1EB0CA: _PyObject_Free (obmalloc.c:1486)
==12370== by 0x1F68D3: freechildren (node.c:146)
==12370== by 0x1F68D3: freechildren (node.c:144)
==12370== by 0x1F68D3: freechildren (node.c:144)
==12370== by 0x1F68D3: freechildren (node.c:144)
==12370== by 0x1F68D3: freechildren (node.c:144)
==12370== by 0x1F68D3: freechildren (node.c:144)
==12370== by 0x1F68D3: freechildren (node.c:144)
==12370== by 0x1F68D3: freechildren (node.c:144)
==12370== by 0x1F68D3: PyNode_Free (node.c:124)
==12370== by 0x319999: PyParser_ASTFromStringObject (pythonrun.c:1174)
==12370== by 0x31DC44: Py_CompileStringObject (pythonrun.c:1081)
==12370== by 0x31EC2B: builtin_compile_impl.isra.14 (bltinmodule.c:782)
==12370== by 0x31EC2B: builtin_compile (bltinmodule.c.h:177)
==12370== by 0x2197CF: _PyCFunction_FastCallDict (methodobject.c:250)
==12370== by 0x21C684: PyCFunction_Call (methodobject.c:103)
==12370== by 0x2CA4AC: do_call_core (ceval.c:5116)
==12370== by 0x2CA4AC: _PyEval_EvalFrameDefault (ceval.c:3404)
==12370== by 0x2998E3: _PyEval_EvalCodeWithName (ceval.c:4166)
==12370== by 0x29A770: fast_function (ceval.c:4992)
==12370== by 0x2A0504: call_function (ceval.c:4872)
==12370== by 0x2C6146: _PyEval_EvalFrameDefault (ceval.c:3351)
==12370== Address 0x5f6b020 is 48 bytes inside a block of size 64 free'd
==12370== at 0x4C2D5BA: operator delete(void*) (vg_replace_malloc.c:584)
==12370== by 0x27D9865D: tensorflow::OpDefBuilder::~OpDefBuilder() (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12370== by 0x2EB343C7: std::_Function_base::_Base_manager<tensorflow::register_op::OpDefBuilderReceiver::OpDefBuilderReceiver(tensorflow::register_op::OpDefBuilderWrapper<true> const&)::$_1>::_M_manager(std::_Any_data&, std::_Any_data const&, std::_Manager_operation) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12370== by 0x2EB3168A: tensorflow::register_op::OpDefBuilderReceiver::OpDefBuilderReceiver(tensorflow::register_op::OpDefBuilderWrapper<true> const&) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12370== by 0x2616682F: _GLOBAL__sub_I_string_ops.cc (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12370== by 0x400F799: call_init.part.0 (dl-init.c:72)
==12370== by 0x400F8AA: call_init (dl-init.c:30)
==12370== by 0x400F8AA: _dl_init (dl-init.c:120)
==12370== by 0x4013E57: dl_open_worker (dl-open.c:575)
==12370== by 0x400F643: _dl_catch_error (dl-error.c:187)
==12370== by 0x4013608: _dl_open (dl-open.c:660)
==12370== by 0x53F5EE8: dlopen_doit (dlopen.c:66)
==12370== by 0x400F643: _dl_catch_error (dl-error.c:187)
==12370== Block was alloc'd at
==12370== at 0x4C2C59C: operator new(unsigned long) (vg_replace_malloc.c:342)
==12370== by 0x2629A98F: std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >::vector(std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12370== by 0x2EB31958: tensorflow::OpDefBuilder::OpDefBuilder(tensorflow::OpDefBuilder const&) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12370== by 0x2EB3163B: tensorflow::register_op::OpDefBuilderReceiver::OpDefBuilderReceiver(tensorflow::register_op::OpDefBuilderWrapper<true> const&) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12370== by 0x2616682F: _GLOBAL__sub_I_string_ops.cc (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/site-packages/torch_xla/lib/libxla_computation_client.so)
==12370== by 0x400F799: call_init.part.0 (dl-init.c:72)
==12370== by 0x400F8AA: call_init (dl-init.c:30)
==12370== by 0x400F8AA: _dl_init (dl-init.c:120)
==12370== by 0x4013E57: dl_open_worker (dl-open.c:575)
==12370== by 0x400F643: _dl_catch_error (dl-error.c:187)
==12370== by 0x4013608: _dl_open (dl-open.c:660)
==12370== by 0x53F5EE8: dlopen_doit (dlopen.c:66)
==12370== by 0x400F643: _dl_catch_error (dl-error.c:187)
Attaching the log below.
allout3.txt
JackCaoG
on 29 Jul 2020
Wow! Python under Valgrind is noisy! 😐
I see a mix of python2.* and python3.* binaries and libraries.
Is there some mixup issue? Ia m not sure whether that is OK or not.
Have you tried @JackCaoG to build everything from scratch and run directly on the same build machine?
davidel
on 29 Jul 2020
@davidel I manually built pytorch and pytorch/xla from our repo and run all these tests. As python2.* and python3.* I think python2.* comes from outside of conda environment(/usr/bin/python) and python3.* is from within the conda environment I am in.
jackcao@beefy-pytorch-xla-eu:~$ which python
/usr/bin/python
jackcao@beefy-pytorch-xla-eu:~$ python --version
Python 2.7.13
jackcao@beefy-pytorch-xla-eu:~$ conda activate torch-xla-nightly
(torch-xla-nightly) jackcao@beefy-pytorch-xla-eu:~$ which python
/anaconda3/envs/torch-xla-nightly/bin/python
(torch-xla-nightly) jackcao@beefy-pytorch-xla-eu:~$ python --version
Python 3.6.8 :: Anaconda, Inc.
(torch-xla-nightly) jackcao@beefy-pytorch-xla-eu:~$
I run the test within the torch-xla-nightly conda environment but I scrath my head about where that python2.* stuff coming from. Looking at the allout3.txt, python2.7 stuff shows up only on the first part of the log and from around 1/3 of the log everything is python3.6. I think the python that is used to run the actual code is python3.6
python dlrm/dlrm_tpu_runner.py \
...
otherwise it will be complaining about print() syntax. but this is also the only python command within the script
(torch-xla-nightly) jackcao@beefy-pytorch-xla-eu:/home/taylanbil/debug/20200610-dlrm$ more jack-bench-criteo-KAGGLE-fullmp.sh | grep python
pkill -9 python
#gdb --args python dlrm/dlrm_tpu_runner.py \
python dlrm/dlrm_tpu_runner.py \
I used valgrind --tool=memcheck --trace-children=yes --error-limit=no --suppressions=/ho
me/jackcao/valgrind-python.supp ./jack-bench-criteo-KAGGLE-fullmp.sh > /home/jackcao/allout4.txt 2>&1 to run the test.
JackCaoG
on 29 Jul 2020
If you search for tpu_worker; you will see everything under that is python3.6. That line is what we print at the beginning of the test_script.
JackCaoG
on 29 Jul 2020
@JackCaoG I see a bunch of /anaconda3/envs/torch-xla-nightly/ in your logs. That means your self-built stuff is not getting picked up.
I ran into this when rebuilding after having run the build_*.sh script once.
Try to do, before building:
pip uninstall -y torch_xla torchvision torch
Never mind 😄 ... that's the env name!
But still, I got weird errors when rebuilding w/out explicit pip-uninstall.
I'd try that ....
davidel
on 29 Jul 2020
Sounds good, let me uninstall, rebuild and rerun the valgrind.
JackCaoG
on 29 Jul 2020
Internet went down for me, I will come back tomorrow... For some reason
tensorflow gave me compilation error( didn’t happened last time) I think
it is related to gcc version being too old on that machine, trying to
update it to gcc8.2. I already uninstalled pt-xla so the model is currently
no runnable.
On Tue, Jul 28, 2020 at 11:32 PM Davide Libenzi notifications@github.com
wrote:
Never mind 😄 ... that's the env name!
But still, I got weird errors when rebuilding w/out explicit pip-uninstall.
I'd try that ....—
You are receiving this because you modified the open/close state.Reply to this email directly, view it on GitHub
https://github.com/pytorch/xla/issues/2366#issuecomment-665462219, or
unsubscribe
https://github.com/notifications/unsubscribe-auth/AOCWEA7N5NMUZUHO436MNQDR567APANCNFSM4PEGP6JQ
.
JackCaoG
on 29 Jul 2020
I managed to repo the segfault with only one process (pt and pt/xla build from scrath, pip uninstall is performed before the build) around 30k steps with log
SHAPE 296000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
SHAPE 297000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
SHAPE 298000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
SHAPE 299000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
SHAPE 300000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
./jack-bench-criteo-KAGGLE-fullmp.sh: line 46: 49335 Segmentation fault python dlrm/dlrm_tpu_runner.py --arch-sparse-feature-size=16 --arch-mlp-bo
t="13-512-256-64-16" --arch-mlp-top="512-256-1" --data-generation=dataset --data-set=kaggle --raw-data-file=$data/train.txt --processed-data-file=$data
/kaggleAdDisplayChallenge_processed.npz --loss-function=bce --round-targets=True --learning-rate=0.1 --mini-batch-size=128 --print-freq=1024 --print-ti
me --test-mini-batch-size=16384 --test-num-workers=16 --use-tpu --num-indices-per-lookup=1 --num-indices-per-lookup-fixed --tpu-model-parallel-group-le
n 1 --tpu-metrics-debug --tpu-cores=1
Running it under valgrind and see if I can see the failure.
JackCaoG
on 1 Aug 2020
It takes 7 hours for the script to reach 190k steps, I will wait for it to finish or crashed and post the log tomorrow. If it doesn't crash I will stress it until it does.
JackCaoG
on 1 Aug 2020
Both run under Valgrind finishes successfully, I checked the log and most of the warning comes from PyObject_Free which is a known issue of running python under Valgrind. More explanation in here(I tried the supression file but it does not help, I searched a bit and saw running with flag PYTHONMALLOC=malloc should help that but will drop python speed to around 1/5).
test6.log
Also attaching the test output
tpu_worker;0;10.204.74.250:8470
Using 1 TPU core(s)...
Criteo datasets have offset = 1, forcing the arguments..
XLA replica groups for Model Parallel:
[[0]]
XLA replica groups for Data Parallel:
[[0]]
TPU data-parallel mode, setting --tpu-data-parallel to True
`torch_xla` async execution is not compatible with ms/it reporting, turning --print-time off.
Reading pre-processed data=/home/taylanbil/debug/20200610-dlrm/geeta-data2//kaggleAdDisplayChallenge_processed.npz
Sparse fea = 26, Dense fea = 13
Defined train indices...
Randomized indices across days ...
Split data according to indices...
Reading pre-processed data=/home/taylanbil/debug/20200610-dlrm/geeta-data2//kaggleAdDisplayChallenge_processed.npz
Sparse fea = 26, Dense fea = 13
Defined test indices...
Randomized indices across days ...
Split data according to indices...
time/loss/accuracy (if enabled): 2020-08-01 21:12:08.819563
SHAPE 0 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
SHAPE 1000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
SHAPE 2000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
SHAPE 3000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
SHAPE 4000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
....
SHAPE 306000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
Metric: CompileTime
....
I notice that majority of the invalid_read message is outputted before we actually iterating through the data. Everything after
==68270== Warning: set address range perms: large range [0xcd4487c28, 0xcf42456d8) (noaccess)
==68270== Warning: set address range perms: large range [0xcfa84b080, 0xd15661580) (undefined)
==68270== Warning: set address range perms: large range [0xc86935040, 0xca174b501) (undefined)
==68270== Warning: set address range perms: large range [0xc86935028, 0xca174b519) (noaccess)
==68270== Warning: set address range perms: large range [0xd3a3c7068, 0xd551dd558) (noaccess)
is outputted after we started iterating(and sending to device I believe) the data. My guess is that most of the preprocessing is done by python so there are a lot more python warning messages.
I will keep running the test...
JackCaoG
on 2 Aug 2020
@JackCaoG Are you still able to reproduce by simply iterating the dataset?
davidel
on 2 Aug 2020
@davidel yup, the single process segfault I posted above was by simply iterating the dataset. The test I am running right now(and yesterday) under Valgrind was also by simply iterating the dateset.
JackCaoG
on 2 Aug 2020
I do not see anything major in the log.
Most of the interesting stuff is at the end and very likely related to the test existing.
Can you print (and flush stdout/stderr) something when the test exits?
So the test is simply creating a PT DataLoader, wrapping it with a ParallelLoader, and iterating?
davidel
on 2 Aug 2020
I am not sure what
Reading pre-processed data=/home/taylanbil/debug/20200610-dlrm/geeta-data2//kaggleAdDisplayChallenge_processed.npz
Sparse fea = 26, Dense fea = 13
Defined train indices...
Randomized indices across days ...
Split data according to indices...
does but the major part of the code was just creating a PT DataLoader, wrapping it with a ParallelLoader, and iterating. I also tried removed the ParallelLoader and tried (so we don't send to the device) but did not see the segfault.
JackCaoG
on 2 Aug 2020
re: previous 2 comments:
the current code that leads to segfault does the following:
1- (python, numpy) load the data (the logs from the previous comment belong to this step)
2- (python/pytorch) create PT data loader
3- (python/torch_xla) create pl.MPDeviceLoader
4- (device) iterate on the data and print shapes of tensors on the device.
- These steps lead to segfault both on 1 core and 8 cores.
- removing step 3 from the equation (and thus 4 happens on cpu) does NOT lead to segfault.
- doing all 4 steps using
gdbdoes not lead to segfault (I tried 5 times, passed 5 times)
taylanbil
on 2 Aug 2020
Test also passed this time, I dump the valgrind log and test output in the same file so we can see when did those warning happen.
test8.log
I went through the log and the only interesting log I found was
SHAPE 74000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
==85478== Thread 64:
==85478== Invalid read of size 4
==85478== at 0x4E468C7: pthread_cond_broadcast@@GLIBC_2.3.2 (pthread_cond_broadcast.S:38)
==85478== by 0x178644EF: __gthread_cond_broadcast (gthr-default.h:866)
==85478== by 0x178644EF: std::condition_variable::notify_all() (condition_variable.cc:73)
==85478== by 0x26026A8E: std::_Function_handler<void (), xla::util::MultiWait::Completer(std::function<void ()>)::$_2>::_M_invoke(std::_Any_data const&) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/s\
ite-packages/torch_xla-1.6-py3.6-linux-x86_64.egg/torch_xla/lib/libxla_computation_client.so)
==85478== by 0x26029A60: std::thread::_State_impl<std::_Bind_simple<xla::env::(anonymous namespace)::ThreadPool::ThreadPool(unsigned long)::{lambda()#1} ()> >::_M_run() (in /anaconda3/envs/torch-xla-nightly\
/lib/python3.6/site-packages/torch_xla-1.6-py3.6-linux-x86_64.egg/torch_xla/lib/libxla_computation_client.so)
==85478== by 0x1786819C: execute_native_thread_routine (thread.cc:80)
==85478== by 0x4E404A3: start_thread (pthread_create.c:456)
==85478== Address 0xc70ef85e8 is on thread 98's stack
==85478== 1736 bytes below stack pointer
==85478==
==85478== Invalid read of size 8
==85478== at 0x4E46979: pthread_cond_broadcast@@GLIBC_2.3.2 (pthread_cond_broadcast.S:129)
==85478== by 0x178644EF: __gthread_cond_broadcast (gthr-default.h:866)
==85478== by 0x178644EF: std::condition_variable::notify_all() (condition_variable.cc:73)
==85478== by 0x26026A8E: std::_Function_handler<void (), xla::util::MultiWait::Completer(std::function<void ()>)::$_2>::_M_invoke(std::_Any_data const&) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/s\
ite-packages/torch_xla-1.6-py3.6-linux-x86_64.egg/torch_xla/lib/libxla_computation_client.so)
==85478== by 0x26029A60: std::thread::_State_impl<std::_Bind_simple<xla::env::(anonymous namespace)::ThreadPool::ThreadPool(unsigned long)::{lambda()#1} ()> >::_M_run() (in /anaconda3/envs/torch-xla-nightly\
/lib/python3.6/site-packages/torch_xla-1.6-py3.6-linux-x86_64.egg/torch_xla/lib/libxla_computation_client.so)
==85478== by 0x1786819C: execute_native_thread_routine (thread.cc:80)
==85478== by 0x4E404A3: start_thread (pthread_create.c:456)
==85478== Address 0xc70ef8608 is on thread 98's stack
==85478== 1704 bytes below stack pointer
==85478==
==85478== Invalid read of size 4
==85478== at 0x4E48F7E: __lll_lock_wait (lowlevellock.S:136)
==85478== by 0x4E4698F: pthread_cond_broadcast@@GLIBC_2.3.2 (pthread_cond_broadcast.S:133)
==85478== by 0x178644EF: __gthread_cond_broadcast (gthr-default.h:866)
==85478== by 0x178644EF: std::condition_variable::notify_all() (condition_variable.cc:73)
==85478== by 0x26026A8E: std::_Function_handler<void (), xla::util::MultiWait::Completer(std::function<void ()>)::$_2>::_M_invoke(std::_Any_data const&) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/s\
ite-packages/torch_xla-1.6-py3.6-linux-x86_64.egg/torch_xla/lib/libxla_computation_client.so)
==85478== by 0x26029A60: std::thread::_State_impl<std::_Bind_simple<xla::env::(anonymous namespace)::ThreadPool::ThreadPool(unsigned long)::{lambda()#1} ()> >::_M_run() (in /anaconda3/envs/torch-xla-nightly\
/lib/python3.6/site-packages/torch_xla-1.6-py3.6-linux-x86_64.egg/torch_xla/lib/libxla_computation_client.so)
==85478== by 0x1786819C: execute_native_thread_routine (thread.cc:80)
==85478== by 0x4E404A3: start_thread (pthread_create.c:456)
==85478== Address 0xc70ef85e8 is on thread 98's stack
==85478== 1736 bytes below stack pointer
==85478==
==85478== Syscall param futex(futex) points to unaddressable byte(s)
==85478== at 0x4E48F7C: __lll_lock_wait (lowlevellock.S:135)
==85478== by 0x4E4698F: pthread_cond_broadcast@@GLIBC_2.3.2 (pthread_cond_broadcast.S:133)
==85478== by 0x178644EF: __gthread_cond_broadcast (gthr-default.h:866)
==85478== by 0x178644EF: std::condition_variable::notify_all() (condition_variable.cc:73)
==85478== by 0x26026A8E: std::_Function_handler<void (), xla::util::MultiWait::Completer(std::function<void ()>)::$_2>::_M_invoke(std::_Any_data const&) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/s\
ite-packages/torch_xla-1.6-py3.6-linux-x86_64.egg/torch_xla/lib/libxla_computation_client.so)
==85478== by 0x26029A60: std::thread::_State_impl<std::_Bind_simple<xla::env::(anonymous namespace)::ThreadPool::ThreadPool(unsigned long)::{lambda()#1} ()> >::_M_run() (in /anaconda3/envs/torch-xla-nightly\
/lib/python3.6/site-packages/torch_xla-1.6-py3.6-linux-x86_64.egg/torch_xla/lib/libxla_computation_client.so)
==85478== by 0x1786819C: execute_native_thread_routine (thread.cc:80)
==85478== by 0x4E404A3: start_thread (pthread_create.c:456)
==85478== Address 0xc70ef85e8 is on thread 98's stack
==85478== 1736 bytes below stack pointer
==85478==
SHAPE 75000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
SHAPE 76000 torch.Size([128, 13]) torch.Size([128, 1]) Counter({torch.Size([128]): 26}) Counter({torch.Size([128]): 26})
This lock access seems fishy and happens when we iterating the data(between 74k-75 steps). Metric is printed at the end of the test, everything else seems to be related to the _PyObject_Free.
JackCaoG
on 3 Aug 2020
@JackCaoG I noticed that yesterday, and I thought it was related to the process getting killed due to crash.
If that happens in the middle, it might be an issue.
This is the transfer-to-server thread returning before its workers completed, which should not happen (unless that thread is explicitly killed).
davidel
on 3 Aug 2020
@davidel You mean in here? I can add some debug output in the beginning and in the end to check if all senders finishes properly. Do you have any theory why this might happen? Would it help if we add a check to TransferToServer and make sure results doesn't contain uninitialized DataPtr?
JackCaoG
on 3 Aug 2020
You can try https://github.com/pytorch/xla/pull/2393 but the warning comes from the very entry of notify_all() and that should not happen.
The caller thread won't exit until notified.
davidel
on 3 Aug 2020
The uninitialized DataPtr should not matter. That is not the issue here.
The issue (see "stack accessed below the stack pointer") here is that the thread calling Wait() leaves before the thread signaling the multi-wait completion, tearing apart the stack-local mwait, and triggering the warning (but also bad things can happen there, like corruption).
davidel
on 3 Aug 2020
After pulling the latest xla(with the https://github.com/pytorch/xla/pull/2393), I did not see
==85478== Invalid read of size 4
==85478== at 0x4E468C7: pthread_cond_broadcast@@GLIBC_2.3.2 (pthread_cond_broadcast.S:38)
==85478== by 0x178644EF: __gthread_cond_broadcast (gthr-default.h:866)
==85478== by 0x178644EF: std::condition_variable::notify_all() (condition_variable.cc:73)
==85478== by 0x26026A8E: std::_Function_handler<void (), xla::util::MultiWait::Completer(std::function<void ()>)::$_2>::_M_invoke(std::_Any_data const&) (in /anaconda3/envs/torch-xla-nightly/lib/python3.6/s\
ite-packages/torch_xla-1.6-py3.6-linux-x86_64.egg/torch_xla/lib/libxla_computation_client.so)
==85478== by 0x26029A60: std::thread::_State_impl<std::_Bind_simple<xla::env::(anonymous namespace)::ThreadPool::ThreadPool(unsigned long)::{lambda()#1} ()> >::_M_run() (in /anaconda3/envs/torch-xla-nightly\
/lib/python3.6/site-packages/torch_xla-1.6-py3.6-linux-x86_64.egg/torch_xla/lib/libxla_computation_client.so)
==85478== by 0x1786819C: execute_native_thread_routine (thread.cc:80)
==85478== by 0x4E404A3: start_thread (pthread_create.c:456)
==85478== Address 0xc70ef85e8 is on thread 98's stack
==85478== 1736 bytes below
stack pointer
warning anymore. Prior to this change the above warning was presented every-time. Other message in the log seems unrelated.
test10.log
I will check if I can repo the crash when only iterating over datas on 8 processes with this fix.
I still can't think of a way that completed_count_ > count_ through, but that seems to be what triggered the warning message above.
JackCaoG
on 4 Aug 2020
@JackCaoG It is not the completed_count_ > count_ check itself.
If you look at the XRT computation client code, the MultiWait objects are in the caller thread stack.
The workers threads gets a reference (another name for pointer for folks scared of C 😄 ) to those, via the & capture.
In the original code, we used take the lock, bump the completed-count, then release the lock, and notify (via notify_all() on the condition variable) the caller thread waiting on a Wait() call.
The reason we did not issue the notify_all() within the locked section was to avoid that such call would trigger a wakeup on the Wait() thread, which would rush to take the lock, which we would own.
The notify_all() would signal the Wait() thread, which would then exit the scope, and hence call the MultiWait destructor (and move the stack pointer up).
Depending on the implementation of notify_all(), that might trigger accesses to vanished object, if that code is accessing the condition variable memory after having issued a core scheduler wakeup.
That being sad, I am not sure this is actually the source of the crash being investigated.
davidel
on 4 Aug 2020
Ah I see, I did not know that notify_all() might try to access the condition variable after issuing a core scheduler wakeup.
I thought that change was meant to resolve the case where
completed_count_ == count_-> notify_all -> parent function returned and MultiWait object destructor called.- Somehow
completed_count_ > count_happened but condition variable(and mwait object itself) is already being pop out of the stack.
Now I think about it this doesn't really make any sense. Even your change prevent the case2 from accessing cv_ but completed_count_, mutex_ would also be below stack pointer.
I think the part that I am not clear is that if mWait object is being destroyed before all of the completer return, what's going to happen to those unfinished async tasks?
On a separate topic, I run the script to iterating over datas on 8 cores 5 times and all of them finished without error. It used to fail around 40% of the time. I will keep trying and maybe make it actually train with 8 cores(which used to fail 80% of the time).
JackCaoG
on 4 Aug 2020
The change from completed_count_ >= count_ is simply to make sure only one worker thread signal. In the current cases it does not really matter as completed_count_ never goes above count_.
It has nothing to do with the real fix.
The real fix is moving notify_all() within the locked section.
davidel
on 4 Aug 2020
With #2393 I run
3 times with single core and only iterating the data -> all passed
5 times with 8 cores and only iterating the data -> all passed
With https://github.com/pytorch/xla/pull/2397 I run
3 times with 8 cores and training -> all passed
I will keep trying one more day with 8 cores and training, but I think it is fair to say #2397 at least reduce the likelihood of segfault.
JackCaoG
on 5 Aug 2020
Thanks @JackCaoG !
It is possible that is the fix, according to the weird std::string error we saw.
We are running workers in thread pools and if a worker tries to access the stack after the caller is gone, it might affect the next closure such thread pool thread picks up.
davidel
on 5 Aug 2020
Davide, do you think it is worth it to backport this fix to the 1.6?
On Tue, Aug 4, 2020 at 11:20 PM Davide Libenzi notifications@github.com
wrote:
Thanks @JackCaoG https://github.com/JackCaoG !
It is possible that is the fix, according to the weird std::string error
we saw.
We are running workers in thread pools and if a worker tries to access the
stack after the caller is gone, it might affect the next closure such
thread pool thread picks up.—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/pytorch/xla/issues/2366#issuecomment-669004338, or
unsubscribe
https://github.com/notifications/unsubscribe-auth/AOCWEA4EEVK3BKGW7LVSXLLR7D24NANCNFSM4PEGP6JQ
.
JackCaoG
on 5 Aug 2020
I'd run a few more tests, and if this is really a fix, then I'd say it is worth to backport.
davidel
on 5 Aug 2020
Sounds good, I will keep running the test for another 1~2 days to be sure.
On Wed, Aug 5, 2020 at 12:08 AM Davide Libenzi notifications@github.com
wrote:
I'd run a few more tests, and if this is really a fix, then I'd say it is
worth to backport.—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/pytorch/xla/issues/2366#issuecomment-669021900, or
unsubscribe
https://github.com/notifications/unsubscribe-auth/AOCWEA6YVRT3REUZVUT26N3R7EANJANCNFSM4PEGP6JQ
.
JackCaoG
on 5 Aug 2020
Just trained 1 full epoch w/o crash. Marking this issue closed, will reopen if it occurs again. Thanks for your hard work!
taylanbil
on 6 Aug 2020
Related issues
patrickvonplaten
·
7Comments
ibeltagy
·
5Comments
butchland
·
7Comments
harpone
·
4Comments
butchland
·
7Comments