search

ddio / gperftools

Automatically exported from code.google.com/p/gperftools
BSD 3-Clause "New" or "Revised" License
0 stars 0 forks source link

libunwind causes deadlock with heap-checker #222

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
What steps will reproduce the problem?
In order to generate, you need my software, but i can't provide it.
I just did "pprof --gv p2.hprof.0001.heap"

What is the expected output? What do you see instead?
open the pprof.ps : arrows are all with zeros

What version of the product are you using? On what operating system?
google-perftools 1.5, libunwind 0.99 hardware : 64bits , ubuntu 9.10 up to 
date.

Original issue reported on code.google.com by laurent....@gmail.com on 11 Mar 2010 at 5:18

Attachments:

GoogleCodeExporter commented 9 years ago

Original comment by `` on 18 Jan 2012 at 9:48

GoogleCodeExporter commented 9 years ago 
i forgot the postscript :s

Original comment by laurent....@gmail.com on 11 Mar 2010 at 5:19

Attachments:

GoogleCodeExporter commented 9 years ago 
Hmm, the profile seems pretty good actually, except for the fact all the edges 
are 0.  
But indeed, that's what the profile is showing -- lots of backtraces with 
almost 0 
memory used.  Is it possible your application just doesn't use that much memory?

Did the program only output foo.0001.heap -- that is, there's no 00002.heap or 
anything else?  That's another indication that the heap-profiler, at least, 
thinks 
the application isn't using much memory.

If you are using a lot of memory, maybe you're using it in a way that tcmalloc 
doesn't hook into.  Do you acquire memory via malloc or free?  Or do you use 
mmap or 
something else?

Also, if you can provide the output of pprof --raw p2.hprof.00001.heap, that 
may help 
figure out what's going on (I can run pprof on the resulting raw profile, 
without 
needing your binary).

Original comment by csilv...@gmail.com on 11 Mar 2010 at 9:44

GoogleCodeExporter commented 9 years ago 
Hello,
you're right, there is no 00002.heap, although my software was working right, 
doing 
lots of malloc and free. (pprof --raw is attached to this message).

In fact, i had a lot of difficulties to run heap-profile. It deadlocks 9 times 
out of 
10 at startup, and it looks like issue 208 :
http://code.google.com/p/google-perftools/issues/detail?id=208 . (My 
p2.hprof.0001.heap is from the luckily 1 out of 10). Indeed my soft uses Mysql. 
I 
tried to play with the linker : e.g -lpthread -lmysqlclient_r -ltcmalloc , and 
changing the order unsuccessfully :/

Here is the backtrace of the threads (2 threads at that time) of my software 
when it 
is deadlocked :
#0  0x00007fe393cceb1e in sys_futex (this=0x7fe393f07160) at 
./src/base/linux_syscall_support.h:2271
#1  SpinLockWait (this=0x7fe393f07160) at ./src/base/spinlock_linux-inl.h:72
#2  SpinLock::SlowLock (this=0x7fe393f07160) at src/base/spinlock.cc:117
#3  0x00007fe393ccb671 in SpinLock::Lock (ptr=0x10d0000, size=<value optimized 
out>) 
at src/base/spinlock.h:74
#4  SpinLockHolder (ptr=0x10d0000, size=<value optimized out>) at 
src/base/spinlock.h:148
#5  RecordAlloc (ptr=0x10d0000, size=<value optimized out>) at src/heap-
profiler.cc:336
#6  NewHook (ptr=0x10d0000, size=<value optimized out>) at 
src/heap-profiler.cc:358
#7  0x00007fe393cd1ecf in MallocHook::InvokeNewHook (size=56) at 
src/malloc_hook-
inl.h:98
#8  tc_malloc (size=56) at src/tcmalloc.cc:1309
#9  0x00007fe3947b5d45 in _dl_map_object_deps (map=<value optimized out>, 
preloads=0x80, npreloads=<value optimized out>, trace_mode=<value optimized 
out>, 
    open_mode=<value optimized out>) at dl-deps.c:506
#10 0x00007fe3947bbda3 in dl_open_worker (a=<value optimized out>) at 
dl-open.c:326
#11 0x00007fe3947b7386 in _dl_catch_error (objname=<value optimized out>, 
errstring=<value optimized out>, mallocedp=<value optimized out>, 
    operate=<value optimized out>, args=<value optimized out>) at dl-error.c:178
#12 0x00007fe3947bb6c7 in _dl_open (file=0x7fe39431a6af "libgcc_s.so.1", mode=-
2147483647, caller_dlopen=0x0, nsid=-2, argc=4, argv=0xca, env=0x10c9000)
    at dl-open.c:615
#13 0x00007fe393a4ec00 in do_dlopen (ptr=0x7fe392a27010) at dl-libc.c:86
#14 0x00007fe3947b7386 in _dl_catch_error (objname=<value optimized out>, 
errstring=<value optimized out>, mallocedp=<value optimized out>, 
    operate=<value optimized out>, args=<value optimized out>) at dl-error.c:178
#15 0x00007fe393a4ed57 in dlerror_run (name=<value optimized out>, mode=<value 
optimized out>) at dl-libc.c:47
#16 *__GI___libc_dlopen_mode (name=<value optimized out>, mode=<value optimized 
out>) 
at dl-libc.c:160
#17 0x00007fe39431888c in pthread_cancel_init () at 
../nptl/sysdeps/pthread/unwind-
forcedunwind.c:53
#18 0x00007fe3943189ec in _Unwind_ForcedUnwind (exc=<value optimized out>, 
stop=<value optimized out>, stop_argument=<value optimized out>)
    at ../nptl/sysdeps/pthread/unwind-forcedunwind.c:126
#19 0x00007fe394316850 in __pthread_unwind (buf=0x4ecfe095) at unwind.c:130
#20 0x00007fe394310b75 in __do_cancel (value=<value optimized out>) at 
pthreadP.h:265
#21 __pthread_exit (value=<value optimized out>) at pthread_exit.c:30
#22 0x00007fe393f638fb in ?? () from /usr/lib/libmysqlclient_r.so.15
#23 0x00007fe39430fa04 in start_thread (arg=<value optimized out>) at 
pthread_create.c:300
#24 0x00007fe393a1180d in clone () at 
../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#25 0x0000000000000000 in ?? ()

and 

#0  __lll_lock_wait () at 
../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
#1  0x00007fe3943122b0 in _L_lock_1022 () from /lib/libpthread.so.0
#2  0x00007fe394312111 in __pthread_mutex_lock (mutex=0x7fe3949c84c8) at 
pthread_mutex_lock.c:82
#3  0x00007fe393a4e5bb in *__GI___dl_iterate_phdr (callback=0x7fe3930b5410 
<callback>, data=0x80) at dl-iteratephdr.c:42
#4  0x00007fe3930b4943 in _ULx86_64_dwarf_find_proc_info (as=<value optimized 
out>, 
ip=140615416689766, pi=0x7fff604b5e48, need_unwind_info=1, arg=0x7fff604b5d70)
    at dwarf/Gfind_proc_info-lsb.c:732
#5  0x00007fe3930b31b4 in fetch_proc_info (c=0x7fff604b5d70, 
ip=140615416689766, 
need_unwind_info=1) at dwarf/Gparser.c:397
#6  0x00007fe3930b41bc in _ULx86_64_dwarf_find_save_locs (c=0x7fff604b5d70) at 
dwarf/Gparser.c:825
#7  0x00007fe3930b46c9 in _ULx86_64_dwarf_step (c=0x7fe3949c84c8) at 
dwarf/Gstep.c:35
#8  0x00007fe3930b6ab5 in _ULx86_64_step (cursor=0x7fe3949c84c8) at 
x86_64/Gstep.c:42
#9  0x00007fe393cd1276 in GetStackTrace (result=0x7fff604b6570, max_depth=42, 
skip_count=0) at src/stacktrace_libunwind-inl.h:81
#10 0x00007fe393cc6bf8 in MallocHook_GetCallerStackTrace 
(result=0x7fff604b6700, 
max_depth=32, skip_count=<value optimized out>) at src/malloc_hook.cc:324
#11 0x00007fe393cc9f14 in MallocHook::GetCallerStackTrace (this=0x7fe39498f040, 
ptr=0x10cf000, bytes=168, skip_count=-1) at ./src/google/malloc_hook.h:192
#12 HeapProfileTable::RecordAlloc (this=0x7fe39498f040, ptr=0x10cf000, 
bytes=168, 
skip_count=-1) at src/heap-profile-table.cc:196
#13 0x00007fe393ccb696 in RecordAlloc (ptr=0x10cf000, size=<value optimized 
out>) at 
src/heap-profiler.cc:338
#14 NewHook (ptr=0x10cf000, size=<value optimized out>) at 
src/heap-profiler.cc:358
#15 0x00007fe393cd1b1a in MallocHook::InvokeNewHook (n=<value optimized out>, 
elem_size=<value optimized out>) at src/malloc_hook-inl.h:98
#16 tc_calloc (n=<value optimized out>, elem_size=<value optimized out>) at 
src/tcmalloc.cc:1321
#17 0x00007fe393f63467 in my_thread_init () from /usr/lib/libmysqlclient_r.so.15
#18 0x00007fe393f63847 in my_thread_global_init () from 
/usr/lib/libmysqlclient_r.so.15
#19 0x00007fe393f5e805 in my_init () from /usr/lib/libmysqlclient_r.so.15
#20 0x00007fe393f5d1d6 in mysql_server_init () from 
/usr/lib/libmysqlclient_r.so.15
#21 0x0000000000419474 in db_connect () at ../db/db_insert.c:542
#22 0x000000000041956b in db_init () at ../db/db_insert.c:565
#23 0x000000000040968a in main (argc=4, argv=0x7fff604b6b18) at ../main.c:623

In #21 0x0000000000419474 in db_connect () at ../db/db_insert.c:542 , it is in 
my 
code :
    mysql_library_init(0, NULL, NULL)

I can see some "malloc_hook" :) ... in the bt.

Anyway thank you for you work

Original comment by laurent....@gmail.com on 12 Mar 2010 at 11:03

Attachments:

GoogleCodeExporter commented 9 years ago 
My bad, it's not as issue 208, here it deadlock at startup.

Original comment by laurent....@gmail.com on 12 Mar 2010 at 11:05

GoogleCodeExporter commented 9 years ago 
Hello again,

here is a 10 line source code, that create a deadlock on my computer.

gcc -I/usr/include/mysql/  -lpthread -lmysqlclient_r -ltcmalloc

no need to setup a database, it deadlocks before. The backtrace :

#0  0x00007f734a524b1e in sys_futex (this=0x7f734a75d160) at 
./src/base/linux_syscall_support.h:2271
#1  SpinLockWait (this=0x7f734a75d160) at ./src/base/spinlock_linux-inl.h:72
#2  SpinLock::SlowLock (this=0x7f734a75d160) at src/base/spinlock.cc:117
#3  0x00007f734a521671 in SpinLock::Lock (ptr=0x23f4000, size=<value optimized 
out>) 
at src/base/spinlock.h:74
#4  SpinLockHolder (ptr=0x23f4000, size=<value optimized out>) at 
src/base/spinlock.h:148
#5  RecordAlloc (ptr=0x23f4000, size=<value optimized out>) at src/heap-
profiler.cc:336
#6  NewHook (ptr=0x23f4000, size=<value optimized out>) at 
src/heap-profiler.cc:358
#7  0x00007f734a527ecf in MallocHook::InvokeNewHook (size=56) at 
src/malloc_hook-
inl.h:98
#8  tc_malloc (size=56) at src/tcmalloc.cc:1309
#9  0x00007f734ad87d45 in _dl_map_object_deps (map=<value optimized out>, 
preloads=0x80, npreloads=<value optimized out>, trace_mode=<value optimized 
out>, 
    open_mode=<value optimized out>) at dl-deps.c:506
#10 0x00007f734ad8dda3 in dl_open_worker (a=<value optimized out>) at 
dl-open.c:326
#11 0x00007f734ad89386 in _dl_catch_error (objname=<value optimized out>, 
errstring=<value optimized out>, mallocedp=<value optimized out>, 
    operate=<value optimized out>, args=<value optimized out>) at dl-error.c:178
#12 0x00007f734ad8d6c7 in _dl_open (file=0x7f734ab706af "libgcc_s.so.1", mode=-
2147483647, caller_dlopen=0x0, nsid=-2, argc=1, argv=0xca, env=0x23ed000)
    at dl-open.c:615
#13 0x00007f734a2a4c00 in do_dlopen (ptr=0x7f7348ff9010) at dl-libc.c:86
#14 0x00007f734ad89386 in _dl_catch_error (objname=<value optimized out>, 
errstring=<value optimized out>, mallocedp=<value optimized out>, 
    operate=<value optimized out>, args=<value optimized out>) at dl-error.c:178
#15 0x00007f734a2a4d57 in dlerror_run (name=<value optimized out>, mode=<value 
optimized out>) at dl-libc.c:47
#16 *__GI___libc_dlopen_mode (name=<value optimized out>, mode=<value optimized 
out>) 
at dl-libc.c:160
#17 0x00007f734ab6e88c in pthread_cancel_init () at 
../nptl/sysdeps/pthread/unwind-
forcedunwind.c:53
#18 0x00007f734ab6e9ec in _Unwind_ForcedUnwind (exc=<value optimized out>, 
stop=<value optimized out>, stop_argument=<value optimized out>)
    at ../nptl/sysdeps/pthread/unwind-forcedunwind.c:126
#19 0x00007f734ab6c850 in __pthread_unwind (buf=0xffffffffa38c9811) at 
unwind.c:130
#20 0x00007f734ab66b75 in __do_cancel (value=<value optimized out>) at 
pthreadP.h:265
#21 __pthread_exit (value=<value optimized out>) at pthread_exit.c:30
#22 0x00007f734a7b98fb in ?? () from /usr/lib/libmysqlclient_r.so.15
#23 0x00007f734ab65a04 in start_thread (arg=<value optimized out>) at 
pthread_create.c:300
#24 0x00007f734a26780d in clone () at 
../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#25 0x0000000000000000 in ?? ()

and 

#0  __lll_lock_wait () at 
../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
#1  0x00007f734ab682b0 in _L_lock_1022 () from /lib/libpthread.so.0
#2  0x00007f734ab68111 in __pthread_mutex_lock (mutex=0x7f734af9a4c8) at 
pthread_mutex_lock.c:82
#3  0x00007f734a2a45bb in *__GI___dl_iterate_phdr (callback=0x7f7349687410 
<callback>, data=0x80) at dl-iteratephdr.c:42
#4  0x00007f7349686943 in _ULx86_64_dwarf_find_proc_info (as=<value optimized 
out>, 
ip=140133147579494, pi=0x7fff7d9021a8, need_unwind_info=1, arg=0x7fff7d9020d0)
    at dwarf/Gfind_proc_info-lsb.c:732
#5  0x00007f73496851b4 in fetch_proc_info (c=0x7fff7d9020d0, 
ip=140133147579494, 
need_unwind_info=1) at dwarf/Gparser.c:397
#6  0x00007f73496861bc in _ULx86_64_dwarf_find_save_locs (c=0x7fff7d9020d0) at 
dwarf/Gparser.c:825
#7  0x00007f73496866c9 in _ULx86_64_dwarf_step (c=0x7f734af9a4c8) at 
dwarf/Gstep.c:35
#8  0x00007f7349688ab5 in _ULx86_64_step (cursor=0x7f734af9a4c8) at 
x86_64/Gstep.c:42
#9  0x00007f734a527276 in GetStackTrace (result=0x7fff7d9028d0, max_depth=42, 
skip_count=0) at src/stacktrace_libunwind-inl.h:81
#10 0x00007f734a51cbf8 in MallocHook_GetCallerStackTrace 
(result=0x7fff7d902a60, 
max_depth=32, skip_count=<value optimized out>) at src/malloc_hook.cc:324
#11 0x00007f734a51ff14 in MallocHook::GetCallerStackTrace (this=0x7f734af61040, 
ptr=0x23f3000, bytes=168, skip_count=-1) at ./src/google/malloc_hook.h:192
#12 HeapProfileTable::RecordAlloc (this=0x7f734af61040, ptr=0x23f3000, 
bytes=168, 
skip_count=-1) at src/heap-profile-table.cc:196
#13 0x00007f734a521696 in RecordAlloc (ptr=0x23f3000, size=<value optimized 
out>) at 
src/heap-profiler.cc:338
#14 NewHook (ptr=0x23f3000, size=<value optimized out>) at 
src/heap-profiler.cc:358
#15 0x00007f734a527b1a in MallocHook::InvokeNewHook (n=<value optimized out>, 
elem_size=<value optimized out>) at src/malloc_hook-inl.h:98
#16 tc_calloc (n=<value optimized out>, elem_size=<value optimized out>) at 
src/tcmalloc.cc:1321
#17 0x00007f734a7b9467 in my_thread_init () from /usr/lib/libmysqlclient_r.so.15
#18 0x00007f734a7b9847 in my_thread_global_init () from 
/usr/lib/libmysqlclient_r.so.15
#19 0x00007f734a7b4805 in my_init () from /usr/lib/libmysqlclient_r.so.15
#20 0x00007f734a7b31d6 in mysql_server_init () from 
/usr/lib/libmysqlclient_r.so.15
#21 0x00000000004009dc in main () at ../src/test.c:16

Original comment by laurent....@gmail.com on 12 Mar 2010 at 12:20

Attachments:

GoogleCodeExporter commented 9 years ago 
Ah, this is a classic libunwind issue, as described in the README (under 
"64-bit 
issues").  The only solution right now is to compile libunwind with 
--enable-frame-
pointers.  This should get you a heap profile, though you may not have 
visibility 
into libraries that lack debug info, such as libcstdc++ and libmysql.  That may 
be 
sufficient for your needs.  (Note the tcmalloc allocator ought not to be 
affected by 
this bug, just the heap- and cpu-profilers.)

I don't see a bug report describing this libunwind issue, so I'll leave this 
open and 
change the summary line.  But I don't expect a fix anytime soon: it depends on 
the 
libc folks and the libunwind folks working out some locking issues.  There's 
unfortunately not much we ourselves can do.

Original comment by csilv...@gmail.com on 12 Mar 2010 at 6:33

GoogleCodeExporter commented 9 years ago 
Building libunwind AND tcmalloc with frame-pointers made it work !

Thank you for your work.

Original comment by laurent....@gmail.com on 15 Mar 2010 at 10:12

GoogleCodeExporter commented 9 years ago 
Ah, there *is* a bug report for libunwind.  I'll merge this with that.

Original comment by csilv...@gmail.com on 17 Mar 2010 at 11:06