samsk / log-malloc2 Goto Github PK

Applications that use cv::fastMalloc to call posix_memalign(&ptr, CV_MALLOC_ALIGN, size) fail during dl_init with:
MEMORY-ERROR: [20699]: GSlice: failed to allocate 1008 bytes (alignment: 1024): Cannot allocate memory

#include <opencv2/core/core.hpp>
int main(int argc, char* argv[]) {
// cv::fastMalloc(1024);
return 0;
}

Reference: https://github.com/opencv/opencv/blob/master/modules/core/src/alloc.cpp

$ LD_PRELOAD=/usr/local/lib/liblog-malloc2.so lldb-8 -- ./WS/build/test/OcvMatcherTest
*** log-malloc trace-fd = 1022 ***
*** log-malloc trace-fd = 1022 ***
*** log-malloc trace-fd = 1022 ***

(lldb) r
...
MEMORY-ERROR: [20871]: GSlice: failed to allocate 1008 bytes (alignment: 1024): Cannot allocate memory

Process 20871 stopped

• thread #1, name = 'OcvMatcherTest', stop reason = signal SIGABRT
  frame #0: 0x00007fffc25ca428 libc.so.6`__GI_raise(sig=6) at raise.c:54
  (lldb) bt
• thread #1, name = 'OcvMatcherTest', stop reason = signal SIGABRT
  • frame #0: 0x00007fffc25ca428 libc.so.6__GI_raise(sig=6) at raise.c:54 frame #1: 0x00007fffc25cc02a libc.so.6__GI_abort at abort.c:89
    frame #2: 0x00007fffbf84a961 libglib-2.0.so.0___lldb_unnamed_symbol277$$libglib-2.0.so.0 + 273 frame #3: 0x00007fffbf84b406 libglib-2.0.so.0___lldb_unnamed_symbol282$$libglib-2.0.so.0 + 518
    frame #4: 0x00007fffbf84bfba libglib-2.0.so.0g_slice_alloc + 1594 frame #5: 0x00007fffbf81d74e libglib-2.0.so.0g_hash_table_new_full + 30
    frame #6: 0x00007fffbf83e94b libglib-2.0.so.0___lldb_unnamed_symbol241$$libglib-2.0.so.0 + 75 frame #7: 0x00007ffff7de76ca ld-2.23.socall_init(l=, argc=1, argv=0x00007fffffffde78, env=0x00007fffffffde88) at dl-init.c:72
    frame #8: 0x00007ffff7de77db ld-2.23.so_dl_init at dl-init.c:30 frame #9: 0x00007ffff7de77c5 ld-2.23.so_dl_init(main_map=0x00007ffff7ffe168, argc=1, argv=0x00007fffffffde78, env=0x00007fffffffde88) at dl-init.c:120
    frame #10: 0x00007ffff7dd7c6a ld-2.23.so`_dl_start_user + 50

The problem could be related to dl_init of libopencv_core.so.3.4 (walking on thin ice here). For instance, running under G_SLICE=always-malloc, my application (or the reproducer) recurses to failure in cv::fastMalloc (OpenCV 3.4.5, gcc 5.4 and CUDA 8.0 on 16.04) OR (OpenCV 3.4.5, gcc 7.3 without CUDA on 18.04).

(lldb) thread backtrace -c 11 -s 17080

• thread #1, name = 'MidasATAdjust', stop reason = signal SIGSEGV: invalid address (fault address: 0x7fffff7feff8)
  frame #17080: 0x00007ffff6effb8a libopencv_core.so.3.4cv::fastMalloc(unsigned long) + 90 frame #17081: 0x00007ffff6e6de1d libopencv_core.so.3.4cv::String::allocate(unsigned long) + 29
  frame #17082: 0x00007ffff7021759 libopencv_core.so.3.4cv::format(char const*, ...) + 521 frame #17083: 0x00007ffff6effb8a libopencv_core.so.3.4cv::fastMalloc(unsigned long) + 90
  frame #17084: 0x00007ffff6efcb12 libopencv_core.so.3.4cvRegisterType + 434 frame #17085: 0x00007ffff6e36774 libopencv_core.so.3.4CvType::CvType(char const*, int ()(void const), void ()(void**), void ()(CvFileStorage, CvFileNode*), void ()(CvFileStorage, char const*, void const*, CvAttrList), void* ()(void const)) + 100
  frame #17086: 0x00007ffff6e367dd libopencv_core.so.3.4_GLOBAL__sub_I_persistence_types.cpp + 61 frame #17087: 0x00007ffff7de76ca ld-2.23.socall_init(l=, argc=7, argv=0x00007fffffffdcb8, env=0x00007fffffffdcf8) at dl-init.c:72
  frame #17088: 0x00007ffff7de77db ld-2.23.so_dl_init at dl-init.c:30 frame #17089: 0x00007ffff7de77c5 ld-2.23.so_dl_init(main_map=0x00007ffff7ffe168, argc=7, argv=0x00007fffffffdcb8, env=0x00007fffffffdcf8) at dl-init.c:120
  frame #17090: 0x00007ffff7dd7c6a ld-2.23.so`_dl_start_user + 50

I am trying to run log-malloc-2 on the CentOS 7 with my highly-multithreaded applications (runs tens of threads) and getting strange, invalid output in the log (executable name and most function names in stack traces are intentionally obfuscated):

+ malloc 24 0x1e65f40 [895997:990912] #84410 3015 2364 2746 0 34282 0
/lib64/libstdc++.so.6(_Znwm+0x1d)[0x7f54d1cde18d]
+ malloc 43 0x7f54c00008e0 [895973:990856] #84410 3015 2364 2746 0 34282 0
+ malloc 56 0x7f54c0000940 [896053:991000] #84410 3015 2364 2746 0 34282 0
+ malloc 31 0x7f54c00009a0 [896084:991072] #84410 3015 2364 2746 0 34282 0
+ malloc 31 0x7f54c00009f0 [896115:991144] #84410 3015 2364 2746 0 34282 0
+ malloc 37 0x7f54c0000a40 [896152:991216] #84410 3015 2364 2746 0 34282 0
+ free -31 0x7f54c00009f0 [896121:991144] #84410 3015 2364 2746 0 34282 0
+ malloc 49 0x7f54c0000a90 [896170:991232] #84410 3015 2364 2746 0 34282 0
+ free -37 0x7f54c0000a40 [896133:991160] #84410 3015 2364 2746 0 34282 0
+ free -31 0x7f54c00009a0 [896102:991088] #84410 3015 2364 2746 0 34282 0
+ free -49 0x7f54c0000a90 [896053:991000] #84410 3015 2364 2746 0 34282 0
+ malloc 376 0x7f54c0000af0 [896429:991408] #84410 3015 2364 2746 0 34282 0
+ malloc 40 0x7f54c00009a0 [896469:991480] #84410 3015 2364 2746 0 34282 0
./my_application(_myf2+0x33a)[0x68500a]
+ malloc 537 0x7f54c0000c90 [897006:992064] #84410 3015 2364 2746 0 34282 0
+ malloc 70 0x7f54c0000ee0 [897076:992168] #84410 3015 2364 2746 0 34282 0
+ free -70 0x7f54c0000ee0 [897006:992064] #84410 3015 2364 2746 0 34282 0
+ malloc 68 0x7f54c0000ee0 [897074:992168] #84410 3015 2364 2746 0 34282 0
+ free -68 0x7f54c0000ee0 [897006:992064] #84410 3015 2364 2746 0 34282 0
./my_application(_myf1+0xbf)[0x6858af]
./my_application(_myf00+0x59b)[0x6841fb]
./my_application(_myf000+0x33)[0x690ed3]
./my_application(_myf0000+0xb7)[0xac683b]
[0x0]

i.e. multiple malloc appear w/o stack trace at all, first malloc has only one frame of the stack trace and later on, more frames appear after free. It looks to me as output synchronization issue, but I've tried to look at log-malloc sources and seems like synchronization is present and properly done. So what could be the reason?

Configuration: log-malloc compiled with GCC 4.8.5 on CentOS 7. I have pthreads, libunwind but don't have "unwind details". Application under log-malloc compiled with GCC 7.3.1 (from the RedHat Devtoolset 7) on CentOS 7 and actively uses pthreads.

On Ubuntu 16.04 with gcc 5.4, log-malloc -o /tmp/log fails with:
symbol lookup error: /usr/local/lib/liblog-malloc2.so: undefined symbol: _Ux86_64_getcontext

git clone https://github.com/samsk/log-malloc2.git
cd log-malloc
.configure
make
sudo make install

ldd /usr/local/lib/liblog-malloc2.so linux-vdso.so.1 => (0x00007ffcf2ba6000)
libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007fd5d9f4d000)
libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007fd5d9d49000)
libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007fd5d997f000)
/lib64/ld-linux-x86-64.so.2 (0x00007fd5da16a000)

$ nm /usr/lib/x86_64-linux-gnu/libunwind.a | grep _Ux86_64_getcontext
U _Ux86_64_getcontext
U _Ux86_64_getcontext_trace
U _Ux86_64_getcontext
U _Ux86_64_getcontext
U _Ux86_64_getcontext
U _Ux86_64_getcontext
U _Ux86_64_getcontext
0000000000000000 T _Ux86_64_getcontext
0000000000000071 T _Ux86_64_getcontext_trace

I patched LDFLAGS as:
LDFLAGS="$LDFLAGS -lunwind-generic -lunwind"

$ ldd -v /usr/local/lib/liblog-malloc2.so
linux-vdso.so.1 => (0x00007ffe80496000)
libunwind.so.8 => /usr/lib/x86_64-linux-gnu/libunwind.so.8 (0x00007f4a910bc000)
libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007f4a90e9f000)
libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007f4a90c9b000)
libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f4a908d1000)
/lib64/ld-linux-x86-64.so.2 (0x00007f4a912d7000)
liblzma.so.5 => /lib/x86_64-linux-gnu/liblzma.so.5 (0x00007f4a906af000)

Now I go on to fail with:
MEMORY-ERROR: [25619]: GSlice: failed to allocate 1008 bytes (alignment: 1024): Cannot allocate memory