Deciphering a stack trace and addr2line

[Phil Endecott]

Dear All,

In the absence of a functioning gdb on my system, I'm trying to debug
a crash using the stack trace in the logcat output.

Based on previous posts here, my understanding is that the addresses
in the stack trace are virtual addresses but running addr2line on
a .so file requires an offset into the library; I've allowed for that
by printing the address of a symbol on startup and finding the same
symbol in the nm output; the offset is 0x81800000, which looks
reasonable.

However, the addresses in the stack trace still don't make any sense;
it looks like the crash is not in my code. Can someone help me
understand what the stack trace means? Here's most of it:

I/DEBUG ( 4763): *** *** *** *** *** *** *** *** *** *** *** *** ***
*** *** ***
I/DEBUG ( 4763): Build fingerprint: 'samsung/GT-P1000/GT-P1000/GT-
P1000:2.2/FROYO/XWJJ3:user/release-keys'
I/DEBUG ( 4763): pid: 8601, tid: 8608 >>> my_app_name_here <<<
I/DEBUG ( 4763): signal 11 (SIGSEGV), fault addr 0000000b

Seg fault, null pointer; I can believe that.

I/DEBUG ( 4763): r0 00000000 r1 4862e038 r2 00000007 r3 4862e030
I/DEBUG ( 4763): r4 00000000 r5 00000000 r6 400d3688 r7 4862e010
I/DEBUG ( 4763): r8 80916fc0 r9 00238d90 10 430c5ec8 fp 4bb41b60
I/DEBUG ( 4763): ip 400d3674 sp 4bb41818 lr 4862e034 pc
8094102c cpsr 20000030
I/DEBUG ( 4763): d0 6472656767756265 d1 0000000000000000
I/DEBUG ( 4763): d2 bf80000000000000 d3 0000000000000000
I/DEBUG ( 4763): d4 0000008e00000000 d5 0000000000000090
I/DEBUG ( 4763): d6 0000000000000000 d7 000000000000334c
I/DEBUG ( 4763): d8 0000000000000000 d9 0000000000000000
I/DEBUG ( 4763): d10 0000000000000000 d11 0000000000000000
I/DEBUG ( 4763): d12 0000000000000000 d13 0000000000000000
I/DEBUG ( 4763): d14 0000000000000000 d15 0000000000000000
I/DEBUG ( 4763): d16 00000000400d3b98 d17 3fd34413509f6000
I/DEBUG ( 4763): d18 bfb01590036c65da d19 bfa06b3496b2f2d2
I/DEBUG ( 4763): d20 0000000000000000 d21 3fd9999a95ec9df7
I/DEBUG ( 4763): d22 3fd24925629b88ce d23 3fcc71c67954861f
I/DEBUG ( 4763): d24 3fc74665e6db4bfa d25 3fc39a09d078c69f
I/DEBUG ( 4763): d26 3f31203b52979784 d27 3f43be6e726a7f4d
I/DEBUG ( 4763): d28 3f1409fa0fec906e d29 3f138c77a2fd6705
I/DEBUG ( 4763): d30 3efb2a7074bf7ad4 d31 0000000000000000
I/DEBUG ( 4763): scr 20000012

That's a register dump, presumably; there seem to be more registers
that I was expecting though!

I/DEBUG ( 4763):
I/DEBUG ( 4763): #00 pc 0004102c /system/lib/libdvm.so
I/DEBUG ( 4763): #01 pc 000642b4 /system/lib/libdvm.so
I/DEBUG ( 4763): #02 pc 0001bd58 /system/lib/libdvm.so
I/DEBUG ( 4763): #03 pc 00022754 /system/lib/libdvm.so
I/DEBUG ( 4763): #04 pc 000215f4 /system/lib/libdvm.so
I/DEBUG ( 4763): #05 pc 0005c584 /system/lib/libdvm.so
I/DEBUG ( 4763): #06 pc 0005c7b4 /system/lib/libdvm.so
I/DEBUG ( 4763): #07 pc 000418e2 /system/lib/libdvm.so
I/DEBUG ( 4763): #08 pc 000416a0 /system/lib/libdvm.so
I/DEBUG ( 4763): #09 pc 00041768 /system/lib/libdvm.so
I/DEBUG ( 4763): #10 pc 00044474 /system/lib/libdvm.so
I/DEBUG ( 4763): #11 pc 0001bf78 /system/lib/libdvm.so
I/DEBUG ( 4763): #12 pc 00022754 /system/lib/libdvm.so
I/DEBUG ( 4763): #13 pc 000215f4 /system/lib/libdvm.so
I/DEBUG ( 4763): #14 pc 0005c584 /system/lib/libdvm.so
I/DEBUG ( 4763): #15 pc 0005c7b4 /system/lib/libdvm.so
I/DEBUG ( 4763): #16 pc 0004fa88 /system/lib/libdvm.so
I/DEBUG ( 4763): #17 pc 000111b0 /system/lib/libc.so
I/DEBUG ( 4763): #18 pc 00010ca0 /system/lib/libc.so

OK, so that looks like a stack trace. But none of those addresses
look like they're in my code, and they all look quite small; are they
in fact offsets?

I guess libdvm is the "dalvik virtual machine". Is there a copy of
that that I can use to decode the symbols somewhere?

I/DEBUG ( 4763):
I/DEBUG ( 4763): code around pc:
I/DEBUG ( 4763): 8094100c 46039f01 b1da9a00 e0196015 2c0cf856
I/DEBUG ( 4763): 8094101c 0c14f1a6 469eb18a 2b04f84e 0104f10e
I/DEBUG ( 4763): 8094102c f4146854 bf187f80 d105605d 400cf8dc
I/DEBUG ( 4763): 8094103c 1aa66a12 605a1072 f8dc460b e0006000
I/DEBUG ( 4763): 8094104c 2e002500 9901d1e2 f00db131 4601fa21
I/DEBUG ( 4763):
I/DEBUG ( 4763): code around lr:
I/DEBUG ( 4763): 4862e014 00000000 00000006 00000000 432f2310
I/DEBUG ( 4763): 4862e024 00000230 430c6000 00000000 00000007
I/DEBUG ( 4763): 4862e034 00000000 00000001 0000009b 4000f398
I/DEBUG ( 4763): 4862e044 00000000 00000020 00000000 0000001a
I/DEBUG ( 4763): 4862e054 0000001b 00000008 00000005 00000009
I/DEBUG ( 4763):
I/DEBUG ( 4763): stack:
I/DEBUG ( 4763): 4bb417d8 809a6018
I/DEBUG ( 4763): 4bb417dc 4000f398 /dev/ashmem/mspace/dalvik-
heap/zygote/0 (deleted)
I/DEBUG ( 4763): 4bb417e0 00000004
I/DEBUG ( 4763): 4bb417e4 80965cc9 /system/lib/libdvm.so
I/DEBUG ( 4763): 4bb417e8 00000000
I/DEBUG ( 4763): 4bb417ec 00000000
I/DEBUG ( 4763): 4bb417f0 00000006
I/DEBUG ( 4763): 4bb417f4 00000000
I/DEBUG ( 4763): 4bb417f8 00000002
I/DEBUG ( 4763): 4bb417fc 00000001
I/DEBUG ( 4763): 4bb41800 4bb4180c
I/DEBUG ( 4763): 4bb41804 00000000
I/DEBUG ( 4763): 4bb41808 00000003
I/DEBUG ( 4763): 4bb4180c 430c5f6c
I/DEBUG ( 4763): 4bb41810 df002777
I/DEBUG ( 4763): 4bb41814 e3a070ad
I/DEBUG ( 4763): #00 4bb41818 00000000
I/DEBUG ( 4763): 4bb4181c 00000001
I/DEBUG ( 4763): 4bb41820 00000000
I/DEBUG ( 4763): 4bb41824 4bb41890
I/DEBUG ( 4763): 4bb41828 430c5ef0
I/DEBUG ( 4763): 4bb4182c 4bb41888
I/DEBUG ( 4763): 4bb41830 40009a98 /dev/ashmem/mspace/dalvik-
heap/zygote/0 (deleted)
I/DEBUG ( 4763): 4bb41834 809642b9 /system/lib/libdvm.so
I/DEBUG ( 4763): #01 4bb41838 436930b0 /system/framework/core.odex
I/DEBUG ( 4763): 4bb4183c 8091bd5c /system/lib/libdvm.so

So this says it's the stack; presumably this is every word of the
stack, rather than just the return addresses shown in the stack trace
above, and the lines marked #00 and #01 are the saved PCs, right? But
they have peculiar values 00000000 and 436930b0, which don't match the
values in the earlier listing. So what are they? Does the (deleted)
annotation tell me anything?

This looks like a crash in libdvm with no involvement from my native
code. If my Java code (what little there is) had misbehaved, I would
not expect this sort of crash. It would not surprise me to see a
segfault inside an OpenGL driver since I pass lots of data to OpenGL
that could go wrong in some way, but that doesn't seem to be the case
here.

Also I get this afterwards:

I/dalvikvm( 2489): Wrote stack traces to '/data/anr/traces.txt'
I/dalvikvm( 2572): threadid=3: reacting to signal 3
I/dalvikvm( 2572): Wrote stack traces to '/data/anr/traces.txt'
I/dalvikvm( 2577): threadid=3: reacting to signal 3
I/dalvikvm( 2577): Wrote stack traces to '/data/anr/traces.txt'
I/dalvikvm( 2580): threadid=3: reacting to signal 3
I/dalvikvm( 2580): Wrote stack traces to '/data/anr/traces.txt'
I/dalvikvm( 2582): threadid=3: reacting to signal 3
D/dalvikvm( 2489): GC_FOR_MALLOC freed 63 objects / 230216 bytes in
100ms
I/GpsLocationProvider( 2489): requestRefLocation: gsm_cell =
[32083,6312907]
I/GpsLocationProvider( 2489): requestRefLocation: mcc = 234 mnc = 10
I/dalvikvm( 2582): Wrote stack traces to '/data/anr/traces.txt'
I/dalvikvm( 2588): threadid=3: reacting to signal 3
I/dalvikvm( 2588): Wrote stack traces to '/data/anr/traces.txt'
I/dalvikvm( 2618): threadid=3: reacting to signal 3
I/dalvikvm( 2839): threadid=3: reacting to signal 3
I/dalvikvm( 2618): Wrote stack traces to '/data/anr/traces.txt'
I/dalvikvm( 2903): threadid=3: reacting to signal 3
I/dalvikvm( 2903): Wrote stack traces to '/data/anr/traces.txt'
I/dalvikvm( 3012): threadid=3: reacting to signal 3
E/dalvikvm( 2839): Failed to write stack traces to /data/anr/
traces.txt (3241 of 4146): No such file or directory
I/dalvikvm( 3012): Wrote stack traces to '/data/anr/traces.txt'
I/dalvikvm( 3021): threadid=3: reacting to signal 3

and more of the same. What is that telling me? What is the
significance of the many repititions?

The referenced /data/anr/traces.txt says:

----- pid 5214 at 2011-01-04 23:11:33 -----
Cmd line: com.android.MtpApplication

DALVIK THREADS:
"main" prio=5 tid=1 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x4001d8b0 self=0xcd28
| sysTid=5214 nice=0 sched=0/0 cgrp=bg_non_interactive
handle=-1345017808
at java.lang.Object.wait(Native Method)
- waiting on <0x48180f30> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:110)
at android.app.ActivityThread.main(ActivityThread.java:4627)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:521)
at com.android.internal.os.ZygoteInit
$MethodAndArgsCaller.run(ZygoteInit.java:871)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:629)
at dalvik.system.NativeStart.main(Native Method)

"Binder Thread #2" prio=5 tid=6 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x48183308 self=0x12d440
| sysTid=5219 nice=0 sched=0/0 cgrp=default handle=1202432
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #1" prio=5 tid=5 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x481810a8 self=0x13cd60
| sysTid=5218 nice=0 sched=0/0 cgrp=default handle=1297616
at dalvik.system.NativeStart.run(Native Method)

"Compiler" daemon prio=5 tid=4 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x4817a2a0 self=0x1332a8
| sysTid=5217 nice=0 sched=0/0 cgrp=bg_non_interactive
handle=1258088
at dalvik.system.NativeStart.run(Native Method)

"Signal Catcher" daemon prio=5 tid=3 RUNNABLE
| group="system" sCount=0 dsCount=0 s=N obj=0x4817a1e8 self=0x13b878
| sysTid=5216 nice=0 sched=0/0 cgrp=bg_non_interactive
handle=1292344
at dalvik.system.NativeStart.run(Native Method)

"HeapWorker" daemon prio=5 tid=2 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x4551e240 self=0x13b610
| sysTid=5215 nice=0 sched=0/0 cgrp=bg_non_interactive
handle=1301528
at dalvik.system.NativeStart.run(Native Method)

----- end 5214 -----

None of that means anything to me - does it mean anything to anyone
else? (Or, please tell me if there are any docs describing this!)

Many thanks, Phil.

[alan]

the pc values have been translated into offsets in the specified
library for you. the values in the stack haven't been translated which
is why they are different. libdvm is the dalvik runtime, you may have
discovered a bug in dalvik but it is more likely that there is a bug
in your jni code somewhere, try running your code with check jni
turned on as this may display a warning

On Jan 5, 10:29 pm, Phil Endecott <spam_from_goo...@chezphil.org>
wrote:

[iblues]

Hi Phil,

You need to run the addr2line against the so present in \mydroid\out
\target\product\passion\symbols\system\lib path as only these
libraries actually have the symbol information mentioned in the
stack.

the address mentioned below should be the start of your crash :
#00 pc 0004102c /system/lib/libdvm.so

I use addr2line all the times to debug the stack crashes.

The other dalvik errors 'Wrote stack traces to '/data/anr/traces.txt'
' is because key dispatch to each of the running processes has failing
and let to ANR error.

Regards,
Syed
On Jan 6, 3:29 am, Phil Endecott <spam_from_goo...@chezphil.org>
wrote:

>   at...
>
> read more »

[Phil Endecott]

Thanks Alan -

On Jan 6, 9:32 am, alan <a...@birtles.org.uk> wrote:
> try running your code with check jni
> turned on as this may display a warning

This is "setprop dalvik.vm.checkjni true", right?

BTW I saw your other post saying that gdb doesn't work for threads.
That's rather useless. Do you know how these stack traces will behave
if there are multiple threads? It looks like it's not trying to dump
stack traces for any other threads. Can I be sure that this is the
thread that actually crashed?

[Phil Endecott]

On Jan 6, 10:03 am, iblues <iblues....@gmail.com> wrote:
> You need to run the addr2line against the so present in \mydroid\out
> \target\product\passion\symbols\system\lib path as only these
> libraries actually have the symbol information mentioned in the
> stack.

Hmm, that path doesn't mean much to me. It doesn't look like part of
the ndk or sdk distribution. Can someone give me a clue where to find
it?

[Olivier Guilyardi]

On 01/05/2011 11:29 PM, Phil Endecott wrote:

> I/DEBUG ( 4763): #00 pc 0004102c /system/lib/libdvm.so

[...]

> OK, so that looks like a stack trace. But none of those addresses
> look like they're in my code, and they all look quite small; are they
> in fact offsets?
>
> I guess libdvm is the "dalvik virtual machine". Is there a copy of
> that that I can use to decode the symbols somewhere?

You could retrieve the library used on the device with:

adb pull /system/lib/libdvm.so .

Then run addr2line on that, and if you get a function name, look for in in the
dalvik sources at http://android.git.kernel.org/?p=platform/dalvik.git;a=tree

I've never tried it but it could work

--
Olivier

[Phil Endecott]

Thanks Olivier -

On Jan 6, 5:40 pm, Olivier Guilyardi <l...@samalyse.com> wrote:
> You could retrieve the library used on the device with:
>
> adb pull /system/lib/libdvm.so .

Right, so I get function names as follows:

dvmFillInStackTraceInternal
dvmFreeDexOrJar
dvmJitToInterpNoChain
dvmMterpStd
dvmInterpret
dvmCallMethodV
dvmCallMethod
dvmThrowChainedExceptionWithClassMessage
dvmThrowChainedExceptionByClass
dvmThrowChainedException
dvmThrowException
dvmMterpCommonExceptionThrown
dvmMterpStd
dvmInterpret
dvmCallMethodV
dvmCallMethod
dvmDetachCurrentThread

The last line suggests that this is a secondary thread; I don't
explicitly create any threads in Java, so perhaps it's the OpenGL
rendering thread.

Then a few lines up it says "ThrowException", which presumably
indicates a Java exception. I don't think I have any try-catch in the
Java code, so I would expect that to kill the process with some
mention of an uncaught exception in the log.

Any thoughts anyone?

[Olivier Guilyardi]

Yes, but I think that something crashes while in the process of throwing the
exception. Apparently, this is related to the stack trace. Here's the Froyo
source for dvmFillInStackTraceInternal:
http://android.git.kernel.org/?p=platform/dalvik.git;a=blob;f=vm/Exception.c;h=13b051e50af02a0d51f0f10b94559200c0bdde75;hb=1daf86bdb630efa96147220019e1a97c853ed3d2#l982

I'm not sure that's been fixed according to the history:
http://android.git.kernel.org/?p=platform/dalvik.git;a=history;f=vm/Exception.c;h=3a73420dbe838efbbc25c0cc59537a673dde6220;hb=HEAD

Looks like a bug in Dalvik.

By the way, although they're pretty rare, I randomly get similar crashes, and I
do use OpenSL too.

--
Olivier

[Olivier Guilyardi]

On 01/06/2011 08:44 PM, Olivier Guilyardi wrote:

> Looks like a bug in Dalvik.
>
> By the way, although they're pretty rare, I randomly get similar crashes, and I
> do use OpenSL too.

s/OpenSL/OpenGL/

--
Olivier

[Phil Endecott]

Thanks Olivier -

On Jan 6, 7:44 pm, Olivier Guilyardi <l...@samalyse.com> wrote:
> Yes, but I think that something crashes while in the process of throwing the
> exception. Apparently, this is related to the stack trace. Here's the Froyo

> source for dvmFillInStackTraceInternal:http://android.git.kernel.org/?p=platform/dalvik.git;a=blob;f=vm/Exce...

I've looked at the disassembly, and the segfault corresponds to the
"if (dvmIsNativeMethod(method)) {" on line 1074 of Exception.c.
dvmIsNativeMethod() expands to "method->accessFlags & ACC_NATIVE",
which I can see as:

4102c: 6854 ldr r4, [r2, #4]
4102e: f414 7f80 tst.w r4, #256 ; 0x100

It is that load that segfaults.

What does this tell me? Presumably the stack is not as it expected it
to be, but why? This is really not easy to debug; it would be hard
enough if I had a debugger....

Perhaps there is a way to find out what the underlying exception is,
somehow. If I put a try-catch in the right place, can I avoid running
this problematic code?


Thanks, Phil.

[Olivier Guilyardi]

Just an thought, but are you calling Java from C? If so, do you properly handle
exceptions as explained in:
http://java.sun.com/docs/books/jni/html/exceptions.html#26074

Because "Calling most JNI functions with a pending exception [...] may lead to
unexpected results.".

Make sure that you look at ExceptionCheck().

--
Olivier

[Phil Endecott]

On Jan 9, 8:17 pm, Olivier Guilyardi <l...@samalyse.com> wrote:
> Just an thought, but are you calling Java from C? If so, do you properly handle
> exceptions as explained in:http://java.sun.com/docs/books/jni/html/exceptions.html#26074
>
> Because "Calling most JNI functions with a pending exception [...] may lead to
> unexpected results.".
>
> Make sure that you look at ExceptionCheck().

Thanks for the hint. I think that I probably only ever make one JNI
call at a time, so I don't think there's a way that I can call
something new with an old exception pending. But I'll do some more
research.

But, having changed some other things, the crashes are now less
frequent. So it's more difficult to debug again...

[Olivier Guilyardi]

On 01/10/2011 03:22 PM, Phil Endecott wrote:

> Thanks for the hint. I think that I probably only ever make one JNI
> call at a time, so I don't think there's a way that I can call
> something new with an old exception pending. But I'll do some more
> research.

You may already know this, but it depends what you mean by "one JNI call". For
instance, calling a single Java method usually involves several JNI calls, for
example: FindClass(), GetMethodID(), and Call*Method(). If FindClass() fails
(returns NULL) then a exception is pending, and you should not call
GetMethodID(), etc.. You need to do a lot of checking. Very few JNI calls are
safe when an exception is pending:
http://java.sun.com/docs/books/jni/html/design.html#2193

--
Olivier