Interpreting call trace

Interpreting call trace

[Daniel Baluta]

Hello,

I have the following stack trace:

[3992.172/0] BUG: soft lockup - CPU#0 stuck for 61s! [events/0:39]
[ 3992.215/0] Pid: 39, comm: events/0 Tainted: P        W  2.6.32 #1 X8DTT-H
[ 3992.222/0] RIP: 0010:[<ffffffff8115f989>]  [<ffffffff8115f989>]
__write_lock_failed+0x9/0x20
[ 3992.231/0] RSP: 0018:ffff880028203908  EFLAGS: 00000287
[ 3992.236/0] RAX: ffff88063ce0bfd8 RBX: ffff880028203920 RCX: ffffffff814e1b00
[ 3992.243/0] RDX: ffff8800282144e0 RSI: ffff880028203abc RDI: ffffffff814e1b04
[ 3992.250/0] RBP: ffffffff8100c6f3 R08: 0000000000000004 R09: ffff880028203ab0
[ 3992.257/0] R10: ffff88061851fa08 R11: 0000000000000000 R12: ffff880028203880
[ 3992.264/0] R13: ffff88060404f800 R14: ffffffff814e1b04 R15: ffffffff8101fd88
[ 3992.272/0] FS:  0000000000000000(0000) GS:ffff880028200000(0000)
knlGS:0000000000000000
[ 3992.280/0] CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
[ 3992.286/0] CR2: 00007f9cc9fb9000 CR3: 0000000001001000 CR4: 00000000000006f0
[ 3992.293/0] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 3992.300/0] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 3992.307/0] Call Trace:
[ 3992.309/0]  <IRQ>  [<ffffffff81374e12>] ? _write_lock_bh+0x22/0x30
[ 3992.316/0]  [<ffffffff81297751>] ? neigh_create+0x2f1/0x6b0
[ 3992.321/0]  [<ffffffff81374f00>] ? _read_unlock_bh+0x10/0x20
[ 3992.327/0]  [<ffffffff81296401>] ? neigh_lookup+0xd1/0xf0
[ 3992.333/0]  [<ffffffff81297b96>] ? neigh_event_ns+0x86/0xc0
[ 3992.338/0]  [<ffffffff812f2cdb>] ? arp_process+0x9fb/0xbf0
[ 3992.344/0]  [<ffffffff812f2ffc>] ? arp_rcv+0x11c/0x130

How could one interpret this?

For example having:
[ 3992.316/0]  [<ffffffff81297751>] ? neigh_create+0x2f1/0x6b0
[ 3992.321/0]  [<ffffffff81374f00>] ? _read_unlock_bh+0x10/0x20

means that _read_unlock_bh has been called & finished ? Or it has been
interrupted by
next function in trace (neigh_create).

Any other info about interpreting call traces are welcomed.


thanks,
Daniel.

Interpreting call trace

[Michael Blizek]

Hi!

On 15:56 Wed 06 Apr     , Daniel Baluta wrote:
...
> For example having:
> [ 3992.316/0]  [<ffffffff81297751>] ? neigh_create+0x2f1/0x6b0
> [ 3992.321/0]  [<ffffffff81374f00>] ? _read_unlock_bh+0x10/0x20
> 
> means that _read_unlock_bh has been called & finished ? Or it has been
> interrupted by
> next function in trace (neigh_create).
> 
> Any other info about interpreting call traces are welcomed.

Usually this means that _read_unlock_bh has called neigh_create. However, this
looks very unlikely to me. So maybe there was a buffer overflow on the stack
or any other form of memory corruption.

	-Michi
-- 
programing a layer 3+4 network protocol for mesh networks
see http://michaelblizek.twilightparadox.com

Interpreting call trace

[Mulyadi Santosa]

Hi Daniel...



On Wed, Apr 6, 2011 at 19:56, Daniel Baluta <daniel.baluta@gmail.com> wrote:
> Hello,
>
> I have the following stack trace:
>
> [3992.172/0] BUG: soft lockup - CPU#0 stuck for 61s! [events/0:39]

alright, so we see soft lockup here.... so that means your machine is
not entirely frozen, right?

If that's true, then I think this entire call trace try to show that
there is lock contention somewhere along the trace...very likely
something grab a lock too long in fast path...


-- 
regards,

Mulyadi Santosa
Freelance Linux trainer and consultant

blog: the-hydra.blogspot.com
training: mulyaditraining.blogspot.com

Interpreting call trace

[Kaustubh Ashtekar]

Hi Daniel,

On Wed, Apr 6, 2011 at 6:26 PM, Daniel Baluta <daniel.baluta@gmail.com> wrote:
> Hello,
>
> I have the following stack trace:

<snip>

> How could one interpret this?
>
> For example having:
> [ 3992.316/0] ?[<ffffffff81297751>] ? neigh_create+0x2f1/0x6b0
> [ 3992.321/0] ?[<ffffffff81374f00>] ? _read_unlock_bh+0x10/0x20
>
> means that _read_unlock_bh has been called & finished ? Or it has been
> interrupted by
> next function in trace (neigh_create).

This means that  _read_unlock_bh called neigh_create. The instruction
at (_read_unlock_bh+0x10) will be executed next when the CPU returns
from the function
neigh_create.

For better understanding you can do
> gdb vmlinux
and then run
gdb> disassemble _read_unlock_bh

Then look at offset 0x10.

Kaustubh

Interpreting call trace

[Daniel Baluta]

> For better understanding you can do
>> gdb vmlinux
> and then run
> gdb> disassemble _read_unlock_bh
>
> Then look at offset 0x10.

Did that. Is there any way to show disassembled
output interleaved with source code?


thank you all for your answers.

Daniel.

Interpreting call trace

[nilesh]

Hi Daniel,

On Thu, 2011-04-07 at 11:26 +0300, Daniel Baluta wrote:
> > For better understanding you can do
> >> gdb vmlinux
> > and then run
> > gdb> disassemble _read_unlock_bh
> >
> > Then look at offset 0x10.
> 
> Did that. Is there any way to show disassembled
> output interleaved with source code?
> 
May be you can try taking the 'objdump' of vmlinux (FYI, it will be
quite big in size). Otherwise try taking objdump of specific binary
only.

#objdump -r -D -l -S <binary>
> 
> thank you all for your answers.
> 
> Daniel.

-- 
Thanks,
Nilesh

Interpreting call trace

[Sowmya Sridharan]

> Did that. Is there any way to show disassembled
> output interleaved with source code?
> 
> 
objdump is the tool you should be looking for.
If you have the tool, then take an "objdump" of your entire 
vmlinux(uncompressed version). Options -d, and -S will intermix source 
with disassembly.
With the output, you can analyze the call trace with the functions' base 
addresses and offsets.

Thanks,
Sowmya
=====-----=====-----=====
Notice: The information contained in this e-mail
message and/or attachments to it may contain 
confidential or privileged information. If you are 
not the intended recipient, any dissemination, use, 
review, distribution, printing or copying of the 
information contained in this e-mail message 
and/or attachments to it are strictly prohibited. If 
you have received this communication in error, 
please notify us by reply e-mail or telephone and 
immediately and permanently delete the message 
and any attachments. Thank you


-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20110407/985d1f64/attachment.html 

Interpreting call trace

[Manish Katiyar]

On Thu, Apr 7, 2011 at 1:26 AM, Daniel Baluta <daniel.baluta@gmail.com> wrote:
>> For better understanding you can do
>>> gdb vmlinux
>> and then run
>> gdb> disassemble _read_unlock_bh
>>
>> Then look at offset 0x10.
>
> Did that. Is there any way to show disassembled
> output interleaved with source code?
>

Have a look at http://kerneltrap.org/mailarchive/linux-kernel-newbies/2009/9/2/6373273/thread


>
> thank you all for your answers.
>
> Daniel.
>
> _______________________________________________
> Kernelnewbies mailing list
> Kernelnewbies at kernelnewbies.org
> http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
>



-- 
Thanks -
Manish