Subject: [arm64] OOPS when using /proc/kcore to disassemble the kernel symbols in "perf top"

From: [email-masked] (Tan Xiaojun)
Date: Wed, 19 Apr 2017 16:01:41 +0800

On 2017/4/19 12:14, Pratyush Anand wrote:
> Hi tan,
> 
> On Saturday 15 April 2017 02:18 PM, Tan Xiaojun wrote:
>> Hi,
>>
>> My test server is Hisilicon D03/D05 (arm64).
>> Kernel source code is 4.11-rc6 (up to date) and config (as an attachment in the end) is generated by defconfig.
>> (Old version does not seem to have this problem. Linux-4.1 is fine and other versions I have not tested yet.)
> 
> I tested with mustang(ARM64) and 4.11-rc6 and could not reproduce it.
> 

This is important. Thanks a lot.

>>
>> When I do "perf top" and annotate a random kernel symbol (like vsnprintf or others), the system report an OOPS below:
>> (The probability of occurrence is very high, almost every time.)
>>
>> $ perf top
>>
>> Annotate vsnprintf               ---- choose it
>> Zoom into perf(7066) thread
>> Zoom into the Kernel DSO
>> Browse map details
>> Run scripts for samples of thread [perf]
>> Run scripts for samples of symbol [vsnprintf]
>> Run scripts for all samples
>> Exit
>>
>> log:
>> Apr 17 05:03:59 EulerOS kernel: [  339.913498] Unable to handle kernel paging request at virtual address ffffdb16aa14028c
>> Apr 17 05:03:59 EulerOS kernel: [  339.913502] pgd = ffff803f70b29000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913506] [ffffdb16aa14028c] *pgd=0000000000000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913511] Internal error: Oops: 96000004 [#1] PREEMPT SMP
>> Apr 17 05:03:59 EulerOS kernel: [  339.913514] Modules linked in:
>> Apr 17 05:03:59 EulerOS kernel: [  339.913520] CPU: 6 PID: 9703 Comm: perf Not tainted 4.11.0-rc6-00029-gb9b3322 #3
>> Apr 17 05:03:59 EulerOS kernel: [  339.913523] Hardware name: Huawei Taishan 2180 /BC11SPCC, BIOS 1.31 06/23/2016
>> Apr 17 05:03:59 EulerOS kernel: [  339.913526] task: ffff803f6ff99a00 task.stack: ffff803f4c104000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913531] PC is at __memcpy+0x38/0x180
>> Apr 17 05:03:59 EulerOS kernel: [  339.913535] LR is at vread+0x148/0x284
>> Apr 17 05:03:59 EulerOS kernel: [  339.913538] pc : [<ffff0000083926b8>] lr : [<ffff0000081ba2a0>] pstate: 00000145
>> Apr 17 05:03:59 EulerOS kernel: [  339.913540] sp : ffff803f4c107c70
>> Apr 17 05:03:59 EulerOS kernel: [  339.913542] x29: ffff803f4c107c70 x28: ffff803f5ef73000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913548] x27: 000000000000032c x26: ffff803f6ff99a00
>> Apr 17 05:03:59 EulerOS kernel: [  339.913552] x25: ffff00000839d28c x24: ffff803f7f801380
>> Apr 17 05:03:59 EulerOS kernel: [  339.913557] x23: 000000000000032c x22: ffff803f5ef73000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913561] x21: 000000000000028c x20: ffff00000839d28c
>> Apr 17 05:03:59 EulerOS kernel: [  339.913565] x19: 000000000000032c x18: 0000ffffaa6cc2d0
>> Apr 17 05:03:59 EulerOS kernel: [  339.913569] x17: 0000ffffab9dc350 x16: ffff0000081f5f04
>> Apr 17 05:03:59 EulerOS kernel: [  339.913573] x15: 0000317ba8000000 x14: 001c19d1d0000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913577] x13: 00000003e8000000 x12: 0000000000000006
>> Apr 17 05:03:59 EulerOS kernel: [  339.913581] x11: 0000000000000007 x10: 0000000000000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913586] x9 : 0000000000000000 x8 : ffff000008e6d3d8
>> Apr 17 05:03:59 EulerOS kernel: [  339.913590] x7 : 00005b16aa140000 x6 : ffff803f5ef73000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913594] x5 : 0000000000000d74 x4 : 0000000000000004
>> Apr 17 05:03:59 EulerOS kernel: [  339.913598] x3 : 0000000000000000 x2 : 0000000000000328
>> Apr 17 05:03:59 EulerOS kernel: [  339.913602] x1 : ffffdb16aa14028c x0 : ffff803f5ef73000
> 
> So, source pointer for the memcpy(2nd arg) seems wrong. (Unable to handle kernel paging request at virtual address ffffdb16aa14028c, and x1 is ffffdb16aa14028c).
> 
> I tried to look into code around source pointer,and they seem to be correct.
> 
> in read_kcore(): start is source pointer.
>         start = kc_offset_to_vaddr(*fpos - elf_buflen);
>     vread(buf, (char *)start, tsz);
> 
> in vread() -> aligned_vread(): addr is source pointer.
> offset = offset_in_page(addr);
> p = vmalloc_to_page(addr);
> *map = kmap_atomic(p);
> memcpy(buf, map + offset, length);
> 
> They all look fine and should work. Since, it always works with 4.1 on your platform, can you please try a git bisect to see which commit is causing trouble for you.
> 
> ~Pratyush
> 

Yes, Pratyush, you are right. I am working on it now.

Thank you for your reply.

Xiaojun.

>> Apr 17 05:03:59 EulerOS kernel: [  339.913606]
>> Apr 17 05:03:59 EulerOS kernel: [  339.913609] Process perf (pid: 9703, stack limit = 0xffff803f4c104000)
>> Apr 17 05:03:59 EulerOS kernel: [  339.913612] Stack: (0xffff803f4c107c70 to 0xffff803f4c108000)
>> Apr 17 05:03:59 EulerOS kernel: [  339.913615] 7c60:                                   ffff803f4c107d00 ffff000008267a18
>> Apr 17 05:03:59 EulerOS kernel: [  339.913619] 7c80: 000000000000032c 0000000036dd9c10 ffff000008f75160 ffff803f4c107eb8
>> Apr 17 05:03:59 EulerOS kernel: [  339.913622] 7ca0: 0000000000000000 ffff803f6ff99a00 ffff803f5ef73000 ffff000008e6d3d8
>> Apr 17 05:03:59 EulerOS kernel: [  339.913625] 7cc0: ffff00000839d28c 000000000000032c 0000000000000024 ffff803f5ef73000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913629] 7ce0: 000000000000032c 000000000000032c ffff803f6ff99a00 ffff000008e684a0
>> Apr 17 05:03:59 EulerOS kernel: [  339.913632] 7d00: ffff803f4c107d90 ffff000008259d00 ffff803f720c3d00 fffffffffffffffb
>> Apr 17 05:03:59 EulerOS kernel: [  339.913635] 7d20: 0000000036dd9c10 ffff803f4c107eb8 0000000080000000 0000000000000015
>> Apr 17 05:03:59 EulerOS kernel: [  339.913638] 7d40: 0000000000000124 000000000000003f ffff000008942000 ffff803f6ff99a00
>> Apr 17 05:03:59 EulerOS kernel: [  339.913641] 7d60: ffff803f6ff08310 ffff803f6ff99a00 ffff803f6ff99a00 ffff803f6ff99a00
>> Apr 17 05:03:59 EulerOS kernel: [  339.913644] 7d80: 0000000d00000124 0000000000002000 ffff803f4c107db0 ffff0000081f3810
>> Apr 17 05:03:59 EulerOS kernel: [  339.913647] 7da0: ffff803f6ff08300 ffff803f4c107eb8 ffff803f4c107e30 ffff0000081f4ab0
>> Apr 17 05:03:59 EulerOS kernel: [  339.913650] 7dc0: 000000000000032c ffff803f6ff08300 0000000000000000 0000000000000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913653] 7de0: ffff803f4c107e10 ffff0000081f49ac ffff803f6ff08300 0000000000000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913656] 7e00: 0000000036dd9c10 ffff803f4c107eb8 ffff803f4c107e30 ffff0000081f4a8c
>> Apr 17 05:03:59 EulerOS kernel: [  339.913659] 7e20: 000000000000032c ffff803f6ff08300 ffff803f4c107e70 ffff0000081f5f48
>> Apr 17 05:03:59 EulerOS kernel: [  339.913662] 7e40: ffff803f6ff08303 ffff803f6ff08300 ffffffffffffffff 0000ffffab9dc37c
>> Apr 17 05:03:59 EulerOS kernel: [  339.913664] 7e60: 0000000000000200 0000ffffab9dcbdc 0000000000000000 ffff000008082f8c
>> Apr 17 05:03:59 EulerOS kernel: [  339.913667] 7e80: 0000000000000200 0000803ff70f9000 ffffffffffffffff ffff000008082f5c
>> Apr 17 05:03:59 EulerOS kernel: [  339.913670] 7ea0: 0000000036dd9c10 000000000000032c ffffffffffffffff 000000000839f28c
>> Apr 17 05:03:59 EulerOS kernel: [  339.913673] 7ec0: 000000000000002a 0000000036dd9c10 000000000000032c 0000ffffaa6d42c8
>> Apr 17 05:03:59 EulerOS kernel: [  339.913676] 7ee0: 0000ffffaa6cc49c 0000ffffaa6d41c0 0000ffffaa6d48b0 0000000000000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913679] 7f00: 000000000000003f 0000000000000003 0000000000000020 0000000000000007
>> Apr 17 05:03:59 EulerOS kernel: [  339.913682] 7f20: 0000000000000006 00000003e8000000 001c19d1d0000000 0000317ba8000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913685] 7f40: 0000000000000000 0000ffffab9dc350 0000ffffaa6cc2d0 0000000000622000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913688] 7f60: 0000000000001000 0000000036dd9c10 000000000000032c 00000000006f1038
>> Apr 17 05:03:59 EulerOS kernel: [  339.913691] 7f80: 000000000000002b 000000000000002a 000000000839f28c 0000000000000001
>> Apr 17 05:03:59 EulerOS kernel: [  339.913694] 7fa0: 0000ffffaa6d3990 0000ffffaa6cc4e0 0000ffffab9dc368 0000ffffaa6cc4a0
>> Apr 17 05:03:59 EulerOS kernel: [  339.913697] 7fc0: 0000ffffab9dc37c 0000000080000000 000000000000002a 000000000000003f
>> Apr 17 05:03:59 EulerOS kernel: [  339.913700] 7fe0: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913702] Call trace:
>> Apr 17 05:03:59 EulerOS kernel: [  339.913705] Exception stack(0xffff803f4c107aa0 to 0xffff803f4c107bd0)
>> Apr 17 05:03:59 EulerOS kernel: [  339.913708] 7aa0: 000000000000032c 0001000000000000 ffff803f4c107c70 ffff0000083926b8
>> Apr 17 05:03:59 EulerOS kernel: [  339.913712] 7ac0: 00000000014200ca 0000000000000000 ffff803f71b1ec38 0000000000000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913715] 7ae0: ffff803f6ff99a00 0000000036dda000 0000000000000000 0000000000000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913718] 7b00: 000000000000000c ffff000008f6c610 ffff803f4c107b60 ffff0000082c0ae0
>> Apr 17 05:03:59 EulerOS kernel: [  339.913721] 7b20: ffff803f7047a030 ffff000008f76000 0000000000000000 ffff803f7200a800
>> Apr 17 05:03:59 EulerOS kernel: [  339.913724] 7b40: ffff803f5ef73000 ffffdb16aa14028c 0000000000000328 0000000000000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913727] 7b60: 0000000000000004 0000000000000d74 ffff803f5ef73000 00005b16aa140000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913729] 7b80: ffff000008e6d3d8 0000000000000000 0000000000000000 0000000000000007
>> Apr 17 05:03:59 EulerOS kernel: [  339.913732] 7ba0: 0000000000000006 00000003e8000000 001c19d1d0000000 0000317ba8000000
>> Apr 17 05:03:59 EulerOS kernel: [  339.913735] 7bc0: ffff0000081f5f04 0000ffffab9dc350
>> Apr 17 05:03:59 EulerOS kernel: [  339.913739] [<ffff0000083926b8>] __memcpy+0x38/0x180
>> Apr 17 05:03:59 EulerOS kernel: [  339.913743] [<ffff000008267a18>] read_kcore+0x230/0x3b0
>> Apr 17 05:03:59 EulerOS kernel: [  339.913747] [<ffff000008259d00>] proc_reg_read+0x64/0x90
>> Apr 17 05:03:59 EulerOS kernel: [  339.913751] [<ffff0000081f3810>] __vfs_read+0x28/0x108
>> Apr 17 05:03:59 EulerOS kernel: [  339.913754] [<ffff0000081f4ab0>] vfs_read+0x80/0x13c
>> Apr 17 05:03:59 EulerOS kernel: [  339.913757] [<ffff0000081f5f48>] SyS_read+0x44/0xa0
>> Apr 17 05:03:59 EulerOS kernel: [  339.913761] [<ffff000008082f8c>] __sys_trace_return+0x0/0x4
>> Apr 17 05:03:59 EulerOS kernel: [  339.913765] Code: 36080064 78402423 780024c3 36100064 (b8404423)
>> Apr 17 05:03:59 EulerOS kernel: [  339.913768] ---[ end trace 6710f03ffe50aedc ]---
>> Apr 17 05:03:59 EulerOS kernel: [  339.913772] note: perf[9703] exited with preempt_count 2
>>
>> Call relationship:
>> read_kcore -> vread -> aligned_vread -> memcpy -> __memcpy
>>
>> Maybe you can give me some ideas.
>>
>> Thanks a lot.
>>
>> Xiaojun.
>>
>>
>>
>>
> 
> .
>