MUSCL + MIPS + threads + debugging/stack traces

MUSCL + MIPS + threads + debugging/stack traces

[Ward Willats]

Hello.

We're working on a consumer product using an OpenWRT-based MIPS Linux platform and linking our C++11 std::thread (really pthread) app to MUSL.

When we try to get a backtrace with the toolchain gdb/gdbserver (or the latest one we cross compiled ourselves from source) we get these kind of pathetic, truncated stack traces. 

Here, for example, is a sample:

(gdb) thread apply all backtrace

Thread 4 (Thread 8009.9567):
#0  0x77fcb904 in __cp_end () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
#1  0x77fc6f38 in __syscall_cp_c () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
#2  0x00000000 in ?? ()
Backtrace stopped: frame did not save the PC

Thread 3 (Thread 8009.9566):
#0  0x77fcb904 in __cp_end () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
#1  0x77fc6f38 in __syscall_cp_c () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
#2  0x00000000 in ?? ()
Backtrace stopped: frame did not save the PC

Thread 2 (Thread 8009.9565):
#0  0x77fcb904 in __cp_end () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
#1  0x77fc6f38 in __syscall_cp_c () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
warning: GDB can't find the start of the function at 0x77b8da46.

    GDB is unable to find the start of the function at 0x77b8da46
and thus can't determine the size of that function's stack frame.
This means that GDB may be unable to access that stack frame, or
the frames below it.
    This problem is most likely caused by an invalid program counter or
stack pointer.
    However, if you think GDB should simply search farther back
from 0x77b8da46 for code which looks like the beginning of a
function, you can increase the range of the search using the `set
heuristic-fence-post' command.
#2  0x77b8da48 in ?? ()

Thread 1 (Thread 8009.8009):
#0  0x005c4be0 in sqlite3_open_v2@plt ()
#1  0x0055606c in SqliteDatabase::open (this=0x9d69c0) at /Users/wardw/fp/fsp/fsp/src/portable/FPActivityStore/DB/SqliteDatabase.cpp:183
#2  0x0053e658 in Nova::ValueStore::ValueStoreDatabase::open (this=0x9d69c0) at /Users/wardw/fp/fsp/fsp/src/util/ValueStore.cpp:146
#3  0x0053e494 in Nova::ValueStore::VolatileDBOpener::openOrCreateDb (this=0x7ffc16d8, strName=..., strThreadName=...) at /Users/wardw/fp/fsp/fsp/src/util/ValueStore.cpp:114
... etc ... this is the tread with the breakpoint and the trace was good all the way to main()


The other threads (4,3,2) are blocked in select() calls and what-not, but you'd never know it from this. We also can't decode core dumps, and attempts to do stack traces in code with libbacktrace have yielded mixed to poor results.

SO....today we went and linked our app to uLibc just to see what would happen, and lo, and behold! It works great! (Note: Similar/redundant thread info below removed and indicated by ellipses)

gdb) thread apply all bt

Thread 11 (Thread 1278.1506):
#0  0x77bb542c in __pthread_cond_wait (cond=0x7f954a68, mutex=0x7f954a98)
    at libpthread/nptl/sysdeps/pthread/pthread_cond_wait.c:152
#1  0x77cde4fc in std::condition_variable::wait(std::unique_lock<std::mutex>&) ()
   from /Volumes/uClibFSP/scripts/../staging_dir/target-mipsel_24kec+dsp_uClibc-0.9.33.2/root-UberFSP/usr/lib/libstdc++.so.6
#2  0x0042b440 in wait<Nova::Mailbox::awaitMail(uint32_t)::__lambda2> (__p=..., __lock=..., this=0x7f954a68)
    at /Volumes/uClibFSP/staging_dir/toolchain-mipsel_24kec+dsp_gcc-4.8-linaro_uClibc-0.9.33.2/mipsel-openwrt-linux-uclibc/include/c++/4.8.3/condition_variable:93
#3  Nova::Mailbox::awaitMail (this=this@entry=0x7f954a40, timeout_ms=timeout_ms@entry=0)
    at /Users/xxxxx/Desktop/RontundaTrunk/Foundation_0.1.42-20160116/fsp/src/framework/Mailbox.cpp:140
#4  0x0042cdb8 in awaitMail (timeout_ms=0, this=0x7f954a20)
    at /Users/xxxxx/Desktop/RontundaTrunk/Foundation_0.1.42-20160116/fsp/src/framework/Task.cpp:220
#5  Nova::Task::run (this=0x7f954a20)
    at /Users/xxxxx/Desktop/RontundaTrunk/Foundation_0.1.42-20160116/fsp/src/framework/Task.cpp:66
#6  0x0042ca34 in Nova::Task::_run (this=0x7f954a20)
    at /Users/xxxxx/Desktop/RontundaTrunk/Foundation_0.1.42-20160116/fsp/src/framework/Task.cpp:87
#7  0x77ce2f38 in execute_native_thread_routine ()
   from /Volumes/uClibFSP/scripts/../staging_dir/target-mipsel_24kec+dsp_uClibc-0.9.33.2/root-UberFSP/usr/lib/libstdc++.so.6
#8  0x77bc0ce0 in start_thread (arg=0x76a6b520) at libpthread/nptl/pthread_create.c:297
#9  0x77bad154 in __thread_start () at ./libc/sysdeps/linux/mips/clone.S:146
Backtrace stopped: frame did not save the PC

...

Thread 8 (Thread 1278.1459):
#0  0x77af1b0c in __syscall_select (n=26, readfds=0x76e6adec, writefds=0x0, exceptfds=0x0, timeout=0x76e6ae80)
    at libc/sysdeps/linux/common/select.c:74
#1  0x77af1c64 in __libc_select (n=26, readfds=0x76e6adec, writefds=0x0, exceptfds=0x0, timeout=0x76e6ae80)
    at libc/sysdeps/linux/common/select.c:85
#2  0x00443ef0 in Nova::FlanInterfaceTask::run (this=0x7f955eb8)
    at /Users/tylerrider/Desktop/RontundaTrunk/Foundation_0.1.42-20160116/fsp/src/tasks/FlanInterfaceTask.cpp:157
#3  0x0042ca34 in Nova::Task::_run (this=0x7f955eb8)
    at /Users/tylerrider/Desktop/RontundaTrunk/Foundation_0.1.42-20160116/fsp/src/framework/Task.cpp:87
#4  0x77ce2f38 in execute_native_thread_routine ()
   from /Volumes/uClibFSP/scripts/../staging_dir/target-mipsel_24kec+dsp_uClibc-0.9.33.2/root-UberFSP/usr/lib/libstdc++.so.6
#5  0x77bc0ce0 in start_thread (arg=0x76e6b520) at libpthread/nptl/pthread_create.c:297
#6  0x77bad154 in __thread_start () at ./libc/sysdeps/linux/mips/clone.S:146
Backtrace stopped: frame did not save the PC

... 

Thread 2 (Thread 1278.1453):
#0  0x77bb4790 in __pthread_cond_timedwait (cond=0xe852d8, mutex=0xe852bc, abstime=0x77a6ae90)
    at libpthread/nptl/sysdeps/pthread/pthread_cond_timedwait.c:158
#1  0x0042e07c in __gthread_cond_timedwait (__abs_timeout=0x77a6ae90, __mutex=<optimized out>, __cond=0xe852d8)
    at /Volumes/uClibFSP/staging_dir/toolchain-mipsel_24kec+dsp_gcc-4.8-linaro_uClibc-0.9.33.2/mipsel-openwrt-linux-uclibc/include/c++/4.8.3/mipsel-openwrt-linux-uclibc/bits/gthr-default.h:871
#2  __wait_until_impl<std::chrono::duration<long long, std::ratio<1ll, 1000000000ll> > > (
    __atime=<synthetic pointer>, __lock=..., this=0xe852d8)
    at /Volumes/uClibFSP/staging_dir/toolchain-mipsel_24kec+dsp_gcc-4.8-linaro_uClibc-0.9.33.2/mipsel-openwrt-linux-uclibc/include/c++/4.8.3/condition_variable:160
#3  wait_until<std::chrono::_V2::steady_clock, std::chrono::duration<long long, std::ratio<1ll, 1000000000ll> > > (
    __atime=<synthetic pointer>, __lock=..., this=0xe852d8)
    at /Volumes/uClibFSP/staging_dir/toolchain-mipsel_24kec+dsp_gcc-4.8-linaro_uClibc-0.9.33.2/mipsel-openwrt-linux-uclibc/include/c++/4.8.3/condition_variable:113
#4  Nova::Timer::run (this=0xe85278)
    at /Users/xxxxx/Desktop/RontundaTrunk/Foundation_0.1.42-20160116/fsp/src/framework/Timer.cpp:110
#5  0x77ce2f38 in execute_native_thread_routine ()
   from /Volumes/uClibFSP/scripts/../staging_dir/target-mipsel_24kec+dsp_uClibc-0.9.33.2/root-UberFSP/usr/lib/libstdc++.so.6
#6  0x77bc0ce0 in start_thread (arg=0x77a6b520) at libpthread/nptl/pthread_create.c:297
#7  0x77bad154 in __thread_start () at ./libc/sysdeps/linux/mips/clone.S:146
Backtrace stopped: frame did not save the PC

Thread 1 (Thread 1278.1278):
#0  0x77aef294 in __syscall_nanosleep (req=0x7f920aa0, rem=0x0) at libc/sysdeps/linux/common/nanosleep.c:21
#1  0x77aef3b8 in __libc_nanosleep (req=0x7f920aa0, rem=0x0) at libc/sysdeps/linux/common/nanosleep.c:33
#2  0x77b85e38 in usleep (usec=100000) at libc/unistd/usleep.c:21
#3  0x004287cc in main (argc=<optimized out>, argv=<optimized out>)
    at /Users/xxxxx/Desktop/RontundaTrunk/Foundation_0.1.42-20160116/fsp/src/main.cpp:500


Now, I realize MIPS is a bit of a ghetto, and backtracing on the architecture is a heuristic-filled nightmare, and also that backtracing is not part of the "core" features you provide since "most people just use GDB" -- but gee-whiz, it sure doesn't work on MIPS and we can't be the first people to run into this. Hopefully there is something simple and stupid we are doing wrong and you folks can set us straight.  

We'd like to keep using MUSL since it is modern, clean, and "preferred" -- but with customer deadlines and money on the line we can't keep working blind like this and struggling with "debugging by printf()" -- so we're going to have to switch to uLiibC real soon unless there is some kind of way to make MUSL and GDB be more helpful.

Thanks!

-- Ward

Re: MUSCL + MIPS + threads + debugging/stack traces

[Rich Felker]

On Mon, Jan 18, 2016 at 05:34:27PM -0800, Ward Willats wrote:
> Hello.
> 
> We're working on a consumer product using an OpenWRT-based MIPS
> Linux platform and linking our C++11 std::thread (really pthread)
> app to MUSL.
> 
> When we try to get a backtrace with the toolchain gdb/gdbserver (or
> the latest one we cross compiled ourselves from source) we get these
> kind of pathetic, truncated stack traces.
> 
> Here, for example, is a sample:
> 
> (gdb) thread apply all backtrace
> 
> Thread 4 (Thread 8009.9567):
> #0  0x77fcb904 in __cp_end () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
> #1  0x77fc6f38 in __syscall_cp_c () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
> #2  0x00000000 in ?? ()
> Backtrace stopped: frame did not save the PC
> 
> Thread 3 (Thread 8009.9566):
> #0  0x77fcb904 in __cp_end () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
> #1  0x77fc6f38 in __syscall_cp_c () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
> #2  0x00000000 in ?? ()
> Backtrace stopped: frame did not save the PC
> 
> Thread 2 (Thread 8009.9565):
> #0  0x77fcb904 in __cp_end () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
> #1  0x77fc6f38 in __syscall_cp_c () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
> warning: GDB can't find the start of the function at 0x77b8da46.
> 
>     GDB is unable to find the start of the function at 0x77b8da46
> and thus can't determine the size of that function's stack frame.
> This means that GDB may be unable to access that stack frame, or
> the frames below it.
>     This problem is most likely caused by an invalid program counter or
> stack pointer.
>     However, if you think GDB should simply search farther back
> from 0x77b8da46 for code which looks like the beginning of a
> function, you can increase the range of the search using the `set
> heuristic-fence-post' command.
> #2  0x77b8da48 in ?? ()

It looks like your libc build lacks debug info and thus gdb is
attempting to use heuristics to make sense of the call stack. Do you
know if this is the case, and if so, whether there's a way to get
OpenWRT to build libc with -g? It's also possible that missing CFI in
our asm files it the cause. I'll ask and see if anyone else familiar
with MIPS has run into this and has ideas.

Rich

Re: MUSCL + MIPS + threads + debugging/stack traces

[Felix Fietkau]

On 2016-01-19 05:19, Rich Felker wrote:
> On Mon, Jan 18, 2016 at 05:34:27PM -0800, Ward Willats wrote:
>> Hello.
>> 
>> We're working on a consumer product using an OpenWRT-based MIPS
>> Linux platform and linking our C++11 std::thread (really pthread)
>> app to MUSL.
>> 
>> When we try to get a backtrace with the toolchain gdb/gdbserver (or
>> the latest one we cross compiled ourselves from source) we get these
>> kind of pathetic, truncated stack traces.
>> 
>> Here, for example, is a sample:
>> 
>> (gdb) thread apply all backtrace
>> 
>> Thread 4 (Thread 8009.9567):
>> #0  0x77fcb904 in __cp_end () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
>> #1  0x77fc6f38 in __syscall_cp_c () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
>> #2  0x00000000 in ?? ()
>> Backtrace stopped: frame did not save the PC
>> 
>> Thread 3 (Thread 8009.9566):
>> #0  0x77fcb904 in __cp_end () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
>> #1  0x77fc6f38 in __syscall_cp_c () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
>> #2  0x00000000 in ?? ()
>> Backtrace stopped: frame did not save the PC
>> 
>> Thread 2 (Thread 8009.9565):
>> #0  0x77fcb904 in __cp_end () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
>> #1  0x77fc6f38 in __syscall_cp_c () from /Volumes/OpenWrt/fsp-openwrt/staging_dir/target-mipsel_24kec+dsp_musl-1.1.11/root-UberFSP/lib/ld-musl-mipsel-sf.so.1
>> warning: GDB can't find the start of the function at 0x77b8da46.
>> 
>>     GDB is unable to find the start of the function at 0x77b8da46
>> and thus can't determine the size of that function's stack frame.
>> This means that GDB may be unable to access that stack frame, or
>> the frames below it.
>>     This problem is most likely caused by an invalid program counter or
>> stack pointer.
>>     However, if you think GDB should simply search farther back
>> from 0x77b8da46 for code which looks like the beginning of a
>> function, you can increase the range of the search using the `set
>> heuristic-fence-post' command.
>> #2  0x77b8da48 in ?? ()
> 
> It looks like your libc build lacks debug info and thus gdb is
> attempting to use heuristics to make sense of the call stack. Do you
> know if this is the case, and if so, whether there's a way to get
> OpenWRT to build libc with -g? It's also possible that missing CFI in
> our asm files it the cause. I'll ask and see if anyone else familiar
> with MIPS has run into this and has ideas.
Seems that I forgot to put in --enable-debug in the Makefile. This is
fixed in r48363 now.

- Felix

Re: MUSCL + MIPS + threads + debugging/stack traces

[Ward Willats]

> On Jan 19, 2016, at 4:45 AM, Felix Fietkau <nbd@openwrt.org> wrote:
> On 2016-01-19 05:19, Rich Felker wrote:
>> On Mon, Jan 18, 2016 at 05:34:27PM -0800, Ward Willats wrote:
>>> When we try to get a backtrace with the toolchain gdb/gdbserver (or
>>> the latest one we cross compiled ourselves from source) we get these
>>> kind of pathetic, truncated stack traces.
>> 
>> It looks like your libc build lacks debug info and thus gdb is
>> attempting to use heuristics to make sense of the call stack.
> Seems that I forgot to put in --enable-debug in the Makefile. This is
> fixed in r48363 now.
> 

Ha! Turning debug on makes things great. Core dumps too. (At least as far as our quick checks this morning go.)

And boy, do we feel like idiots for not figuring this out straight away! Seems so obvious in retrospect.

Thank you all.

-- Ward