Skip to contentSkip to conversation

: oops around sock_recvmsg

BUG 4.4-rc4 Holger Schurig 2 participants 5 messages Jan 7, 2016 – Jan 13, 2016

Subsystems (2)
lore
Share & tools
lore
#0 lore raw

Hi,

Background: Kernel was 4.4-rc4, machine was an arm-based i.MX6 one. System load was some artificial test bench where a Java program was doing heavy network and CAN code (network and CAN are both the i.MX6 built-in stuff). That test program manages to generate 11000 context switches per second, for example.

This oops with sock_recvmsg() inside it now happened 3 times, just not at my test box, only at one very remote from me. That's also the reason why the log is truncated, the people that grabbed it from Windows with Putty over the serial line just did give this to me ... :-(

BTW, are several places with "???" below. Is this just a "grabbing from Windows" artifact? Or an indication that the processor/memory of the system got completely insane?

[<c03e7964>] (wait_for_completion) from [<c005f9c8>] (__wait_rcu_gp+0xe0/0x108) [<c005f8e8>] (__wait_rcu_gp) from [<c0062510>] (synchronize_rcu+0x4c/0x5c) r10:00000000 r9:ee9d6c08 r8:ef100000 r7:00000020 r6:eea98444 r5:ef100000 r4:eea98400
[<c00624c4>] (synchronize_rcu) from [<c02cb234>] (evdev_release+0x84/0xe0) [<c02cb1b0>] (evdev_release) from [<c00c1218>] (__fput+0xe0/0x1b4) r8:ef3f0910 r7:ecc68660 r6:00000008 r5:ee1ec028 r4:ee9d6c00 r3:c02cb1b0 [<c00c1138>] (__fput) from [<c00c1350>] (____fput+0x10/0x14) r10:00000020 r9:ee9d4e38 r8:00000001 r7:ed9a9a58 r6:ee281540 r5:ed9b48ac r4:ed9b4440
[<c00c1340>] (____fput) from [<c00353a4>] (task_work_run+0xa4/0xbc) [<c0035300>] (task_work_run) from [<c001fc70>] (do_exit+0x370/0x810) r6:ed9b48bc r5:ee9d4e00 r4:ed9b4440 r3:000000d8
[<c001f900>] (do_exit) from [<c0012c28>] (die+0x2c0/0x404)
r7:ed9a9a93
[<c0012968>] (die) from [<c001b4d0>] (__do_kernel_fault.part.0+0x5c/0x1ec) r10:c0037790 r9:ee9d4e00 r8:80000007 r7:ed9a9bf8 r6:ee9d4e00 r5:80000007 r4:fffffffe
[<c001b474>] (__do_kernel_fault.part.0) from [<c0017438>] (do_page_fault+0x274/0x28c) r7:ed9a9bf8 r3:ed9a9bf8
[<c00171c4>] (do_page_fault) from [<c000934c>] (do_PrefetchAbort+0x3c/0xa0) r10:c0037790 r9:00000001 r8:00000001 r7:ed9a9bf8 r6:fffffffe r5:c055fbc4 r4:00000007
[<c0009310>] (do_PrefetchAbort) from [<c001354c>] (__pabt_svc+0x4c/0x80)

Exception stack(0xed9a9bf8 to 0xed9a9c40)

9be0:?????????????????????????????????????????????????????? ebaa3d18 00000001 9c00: 00000001 00000304 ee1c2c04 fffffff3 00000001 00000304 00000001 00000001 9c20: c0037790 ed9a9c74 ffffffff ed9a9c48 c004febc fffffffe 800100b3 ffffffff r7:ed9a9c2c r6:ffffffff r5:800100b3 r4:fffffffe
[<c004fe68>] (__wake_up_common) from [<c00504ac>] (__wake_up_sync_key+0x4c/0x60) r10:00000000 r9:00000010 r8:00000304 r7:00000001 r6:00000001 r5:a0010013 r4:ee1c2c00 r3:00000001
[<c0050460>] (__wake_up_sync_key) from [<c03cf9d0>] (unix_write_space+0x60/0x90) r8:ed9a9df4 r7:eb9decc0 r6:ed95d5e4 r5:ed95f02c r4:ed95ef80
[<c03cf970>] (unix_write_space) from [<c0347674>] (sock_wfree+0x4c/0x84) r4:ed95ef80 r3:c03cf970
[<c0347628>] (sock_wfree) from [<c03cf2b8>] (unix_destruct_scm+0x6c/0x74) r5:00000000 r4:eb9decc0
[<c03cf24c>] (unix_destruct_scm) from [<c0348768>] (skb_release_head_state+0x70/0xb0) r4:eb9decc0
[<c03486f8>] (skb_release_head_state) from [<c034b280>] (skb_release_all+0x14/0x2c) r4:eb9decc0 r3:00000001
[<c034b26c>] (skb_release_all) from [<c034b2ac>] (__kfree_skb+0x14/0x94) r4:eb9decc0 r3:00000001
[<c034b298>] (__kfree_skb) from [<c034b610>] (consume_skb+0x58/0x5c) r4:ed95d400 r3:00000001
[<c034b5b8>] (consume_skb) from [<c03d050c>] (unix_stream_read_generic+0x5ec/0x750) [<c03cff20>] (unix_stream_read_generic) from [<c03d0754>] (unix_stream_recvmsg+0x50/0x5c) r10:ecc13800 r9:ed9a9e88 r8:bee12988 r7:00000040 r6:ecc13800 r5:ed9a9f4c r4:00001000
[<c03d0704>] (unix_stream_recvmsg) from [<c0341250>] (sock_recvmsg+0x18/0x1c) r7:bee1296c r6:00000040 r5:00000000 r4:ed9a9f4c
[<c0341238>] (sock_recvmsg) from [<c0342fa0>] (___sys_recvmsg+0x98/0x170) [<c0342f08>] (___sys_recvmsg) from [<c0343d34>] (__sys_recvmsg+0x44/0x68) r10:00000000 r9:ed9a8000 r8:c000f1e4 r7:00000129 r6:bee1296c r5:00000000 r4:ecc13800
[<c0343cf0>] (__sys_recvmsg) from [<c0343d68>] (SyS_recvmsg+0x10/0x14) r6:b6f7df10 r5:81196c08 r4:bee12988
[<c0343d58>] (SyS_recvmsg) from [<c000f020>] (ret_fast_syscall+0x0/0x3c) Xorg??????????? D c03e6c58???? 0?? 368??? 367 0x00000004

Backtrace:
[<c03e68a0>] (__schedule) from [<c03e6e94>] (schedule+0xb0/0xcc)
r10:c0064090 r9:00000000 r8:ed9a8000 r7:00000002 r6:ed9a99a4 r5:7fffffff
r4:ed9a8000 r3:00000001
[<c03e6de4>] (schedule) from [<c03e9804>] (schedule_timeout+0x20/0x180)
r4:7fffffff r3:00000004
[<c03e97e4>] (schedule_timeout) from [<c03e7924>] (wait_for_common+0x118/0x158)
r8:ed9a8000 r7:00000002 r6:ed9a99a4 r5:7fffffff r4:ed9a99a0
[<c03e780c>] (wait_for_common) from [<c03e797c>] (wait_for_completion+0x18/0x1c)
r9:00000000 r8:00000001 r7:ed9a9994 r6:ed9a99a0 r5:c0064050 r4:00000000
[<c03e7964>] (wait_for_completion) from [<c005f9c8>] (__wait_rcu_gp+0xe0/0x108)
[<c005f8e8>] (__wait_rcu_gp) from [<c0062510>] (synchronize_rcu+0x4c/0x5c)
r10:00000000 r9:ee9d6c08 r8:ef100000 r7:00000020 r6:eea98444 r5:ef100000

r4:eea98400
[<c00624c4>] (synchronize_rcu) from [<c02cb234>] (evdev_release+0x84/0xe0) [<c02cb1b0>] (evdev_release) from [<c00c1218>] (__fput+0xe0/0x1b4) r8:ef3f0910 r7:ecc68660 r6:00000008 r5:ee1ec028 r4:ee9d6c00 r3:c02cb1b0

#1 lore raw
Quoted 4 lines · Holger Schurig

This oops with sock_recvmsg() inside it now happened 3 times, just not at my test box, only at one very remote from me. That's also the reason why the log is truncated, the people that grabbed it from Windows with Putty over the serial line just did give this to me ... :-(

It's a little incomplete, but luckily we have some useful information buried in it.

Quoted 3 lines

BTW, are several places with "???" below. Is this just a "grabbing from Windows" artifact? Or an indication that the processor/memory of the system got completely insane?

No idea, sorry.

...

Quoted 8 lines

[<c00171c4>] (do_page_fault) from [<c000934c>] (do_PrefetchAbort+0x3c/0xa0) r10:c0037790 r9:00000001 r8:00000001 r7:ed9a9bf8 r6:fffffffe r5:c055fbc4 r4:00000007
[<c0009310>] (do_PrefetchAbort) from [<c001354c>] (__pabt_svc+0x4c/0x80)

Exception stack(0xed9a9bf8 to 0xed9a9c40)

9be0:?????????????????????????????????????????????????????? ebaa3d18 00000001 9c00: 00000001 00000304 ee1c2c04 fffffff3 00000001 00000304 00000001 00000001 9c20: c0037790 ed9a9c74 ffffffff ed9a9c48 c004febc fffffffe 800100b3 ffffffff

These are the registers - r0 to pc, cpsr and "orig_r0". The PC value triggering the prefetch abort was 0xfffffffe, and the link register was 0xc004febc - this should be the instruction after the call.

To do any diagnosis, I'd need the disassembly around the link register - it may be best if you can send me the vmlinux file itself by private mail in case I need to reference other functions too.

I've left the remainder of the trace in place - please retain it when you reply with the disassembly so I can refer directly to it in my next reply without having to find the previous email. Thanks.

Quoted 31 lines

r7:ed9a9c2c r6:ffffffff r5:800100b3 r4:fffffffe
[<c004fe68>] (__wake_up_common) from [<c00504ac>] (__wake_up_sync_key+0x4c/0x60) r10:00000000 r9:00000010 r8:00000304 r7:00000001 r6:00000001 r5:a0010013 r4:ee1c2c00 r3:00000001
[<c0050460>] (__wake_up_sync_key) from [<c03cf9d0>] (unix_write_space+0x60/0x90) r8:ed9a9df4 r7:eb9decc0 r6:ed95d5e4 r5:ed95f02c r4:ed95ef80
[<c03cf970>] (unix_write_space) from [<c0347674>] (sock_wfree+0x4c/0x84) r4:ed95ef80 r3:c03cf970
[<c0347628>] (sock_wfree) from [<c03cf2b8>] (unix_destruct_scm+0x6c/0x74) r5:00000000 r4:eb9decc0
[<c03cf24c>] (unix_destruct_scm) from [<c0348768>] (skb_release_head_state+0x70/0xb0) r4:eb9decc0
[<c03486f8>] (skb_release_head_state) from [<c034b280>] (skb_release_all+0x14/0x2c) r4:eb9decc0 r3:00000001
[<c034b26c>] (skb_release_all) from [<c034b2ac>] (__kfree_skb+0x14/0x94) r4:eb9decc0 r3:00000001
[<c034b298>] (__kfree_skb) from [<c034b610>] (consume_skb+0x58/0x5c) r4:ed95d400 r3:00000001
[<c034b5b8>] (consume_skb) from [<c03d050c>] (unix_stream_read_generic+0x5ec/0x750) [<c03cff20>] (unix_stream_read_generic) from [<c03d0754>] (unix_stream_recvmsg+0x50/0x5c) r10:ecc13800 r9:ed9a9e88 r8:bee12988 r7:00000040 r6:ecc13800 r5:ed9a9f4c r4:00001000
[<c03d0704>] (unix_stream_recvmsg) from [<c0341250>] (sock_recvmsg+0x18/0x1c) r7:bee1296c r6:00000040 r5:00000000 r4:ed9a9f4c
[<c0341238>] (sock_recvmsg) from [<c0342fa0>] (___sys_recvmsg+0x98/0x170) [<c0342f08>] (___sys_recvmsg) from [<c0343d34>] (__sys_recvmsg+0x44/0x68) r10:00000000 r9:ed9a8000 r8:c000f1e4 r7:00000129 r6:bee1296c r5:00000000 r4:ecc13800
[<c0343cf0>] (__sys_recvmsg) from [<c0343d68>] (SyS_recvmsg+0x10/0x14) r6:b6f7df10 r5:81196c08 r4:bee12988
[<c0343d58>] (SyS_recvmsg) from [<c000f020>] (ret_fast_syscall+0x0/0x3c)

Signature · 3 lines
RMK's Patch system: http://www.arm.linux.org.uk/developer/patches/
FTTC broadband for 0.8mile line: currently at 9.6Mbps down 400kbps up
according to speedtest.net.
#2 lore raw

Hi,

Russell, as asked I've sent the kernel via private mail to you.

For the mailing list:

As I "lost" the vmlinux (I continued working on the kernel) and scripts/extract-vmlinux didn't liked the vmlinux file, I reverted my changes and recompiled the kernel. The resulting System.map is identical to the one on the device, so I'm pretty sure that worked out. I just note it here as a potential caveat.

I then did run

gcc-linaro-arm-linux-gnueabihf-4.8-2014.04_linux/arm-linux-gnueabihf/bin/objdump -D -S --show-raw-insn --prefix-addresses --line-numbers linux/vmlinux >o

and got this around 0xc004febc:

__wake_up_common():

c004fe68 <__wake_up_common> e1a0c00d    mov     ip, sp
c004fe6c <__wake_up_common+0x4> e92ddff8        push    {r3, r4, r5, r6, r7, r8, r9, sl, fp, ip, lr, pc}
c004fe70 <__wake_up_common+0x8> e24cb004        sub     fp, ip, #4
c004fe74 <__wake_up_common+0xc> e1a04000        mov     r4, r0
c004fe78 <__wake_up_common+0x10> e1a09003       mov     r9, r3
c004fe7c <__wake_up_common+0x14> e1a08001       mov     r8, r1
c004fe80 <__wake_up_common+0x18> e5b43004       ldr     r3, [r4, #4]!
c004fe84 <__wake_up_common+0x1c> e1a06002       mov     r6, r2
c004fe88 <__wake_up_common+0x20> e59b7004       ldr     r7, [fp, #4]
c004fe8c <__wake_up_common+0x24> e5935000       ldr     r5, [r3]
c004fe90 <__wake_up_common+0x28> e243000c       sub     r0, r3, #12
c004fe94 <__wake_up_common+0x2c> e245500c       sub     r5, r5, #12
c004fe98 <__wake_up_common+0x30> e280300c       add     r3, r0, #12
c004fe9c <__wake_up_common+0x34> e1530004       cmp     r3, r4
c004fea0 <__wake_up_common+0x38> 0a00000f       beq     c004fee4 <__wake_up_common+0x7c>
c004fea4 <__wake_up_common+0x3c> e590c008       ldr     ip, [r0, #8]
c004fea8 <__wake_up_common+0x40> e1a01008       mov     r1, r8
c004feac <__wake_up_common+0x44> e1a02009       mov     r2, r9
c004feb0 <__wake_up_common+0x48> e1a03007       mov     r3, r7
c004feb4 <__wake_up_common+0x4c> e590a000       ldr     sl, [r0]
c004feb8 <__wake_up_common+0x50> e12fff3c       blx     ip
c004febc <__wake_up_common+0x54> e3500000       cmp     r0, #0
c004fec0 <__wake_up_common+0x58> 0a000003       beq     c004fed4 <__wake_up_common+0x6c>
c004fec4 <__wake_up_common+0x5c> e31a0001       tst     sl, #1
c004fec8 <__wake_up_common+0x60> 0a000001       beq     c004fed4 <__wake_up_common+0x6c>
c004fecc <__wake_up_common+0x64> e2566001       subs    r6, r6, #1
c004fed0 <__wake_up_common+0x68> 089daff8       ldmeq   sp, {r3, r4, r5, r6, r7, r8, r9, sl, fp, sp, pc}
c004fed4 <__wake_up_common+0x6c> e595300c       ldr     r3, [r5, #12]
c004fed8 <__wake_up_common+0x70> e1a00005       mov     r0, r5
c004fedc <__wake_up_common+0x74> e243500c       sub     r5, r3, #12
c004fee0 <__wake_up_common+0x78> eaffffec       b       c004fe98 <__wake_up_common+0x30>
c004fee4 <__wake_up_common+0x7c> e89daff8       ldm     sp, {r3, r4, r5, r6, r7, r8, r9, sl, fp, sp, pc}
Quoted 52 lines
Quoted 8 lines

[<c00171c4>] (do_page_fault) from [<c000934c>] (do_PrefetchAbort+0x3c/0xa0) r10:c0037790 r9:00000001 r8:00000001 r7:ed9a9bf8 r6:fffffffe r5:c055fbc4 r4:00000007
[<c0009310>] (do_PrefetchAbort) from [<c001354c>] (__pabt_svc+0x4c/0x80)

Exception stack(0xed9a9bf8 to 0xed9a9c40)

9be0:?????????????????????????????????????????????????????? ebaa3d18 00000001 9c00: 00000001 00000304 ee1c2c04 fffffff3 00000001 00000304 00000001 00000001 9c20: c0037790 ed9a9c74 ffffffff ed9a9c48 c004febc fffffffe 800100b3 ffffffff

These are the registers - r0 to pc, cpsr and "orig_r0". The PC value triggering the prefetch abort was 0xfffffffe, and the link register was 0xc004febc - this should be the instruction after the call.

To do any diagnosis, I'd need the disassembly around the link register - it may be best if you can send me the vmlinux file itself by private mail in case I need to reference other functions too.

I've left the remainder of the trace in place - please retain it when you reply with the disassembly so I can refer directly to it in my next reply without having to find the previous email. Thanks.

Quoted 31 lines

r7:ed9a9c2c r6:ffffffff r5:800100b3 r4:fffffffe
[<c004fe68>] (__wake_up_common) from [<c00504ac>] (__wake_up_sync_key+0x4c/0x60) r10:00000000 r9:00000010 r8:00000304 r7:00000001 r6:00000001 r5:a0010013 r4:ee1c2c00 r3:00000001
[<c0050460>] (__wake_up_sync_key) from [<c03cf9d0>] (unix_write_space+0x60/0x90) r8:ed9a9df4 r7:eb9decc0 r6:ed95d5e4 r5:ed95f02c r4:ed95ef80
[<c03cf970>] (unix_write_space) from [<c0347674>] (sock_wfree+0x4c/0x84) r4:ed95ef80 r3:c03cf970
[<c0347628>] (sock_wfree) from [<c03cf2b8>] (unix_destruct_scm+0x6c/0x74) r5:00000000 r4:eb9decc0
[<c03cf24c>] (unix_destruct_scm) from [<c0348768>] (skb_release_head_state+0x70/0xb0) r4:eb9decc0
[<c03486f8>] (skb_release_head_state) from [<c034b280>] (skb_release_all+0x14/0x2c) r4:eb9decc0 r3:00000001
[<c034b26c>] (skb_release_all) from [<c034b2ac>] (__kfree_skb+0x14/0x94) r4:eb9decc0 r3:00000001
[<c034b298>] (__kfree_skb) from [<c034b610>] (consume_skb+0x58/0x5c) r4:ed95d400 r3:00000001
[<c034b5b8>] (consume_skb) from [<c03d050c>] (unix_stream_read_generic+0x5ec/0x750) [<c03cff20>] (unix_stream_read_generic) from [<c03d0754>] (unix_stream_recvmsg+0x50/0x5c) r10:ecc13800 r9:ed9a9e88 r8:bee12988 r7:00000040 r6:ecc13800 r5:ed9a9f4c r4:00001000
[<c03d0704>] (unix_stream_recvmsg) from [<c0341250>] (sock_recvmsg+0x18/0x1c) r7:bee1296c r6:00000040 r5:00000000 r4:ed9a9f4c
[<c0341238>] (sock_recvmsg) from [<c0342fa0>] (___sys_recvmsg+0x98/0x170) [<c0342f08>] (___sys_recvmsg) from [<c0343d34>] (__sys_recvmsg+0x44/0x68) r10:00000000 r9:ed9a8000 r8:c000f1e4 r7:00000129 r6:bee1296c r5:00000000 r4:ecc13800
[<c0343cf0>] (__sys_recvmsg) from [<c0343d68>] (SyS_recvmsg+0x10/0x14) r6:b6f7df10 r5:81196c08 r4:bee12988
[<c0343d58>] (SyS_recvmsg) from [<c000f020>] (ret_fast_syscall+0x0/0x3c)

#3 lore raw
Quoted 1 line · Holger Schurig

scripts/extract-vmlinux didn't liked the vmlinux file, I reverted my

I meant "didn't liked the vmlinu*Z* file" (with a z) ...