[LU-435] unknow error in page fault when running sanity test_30c

• Type: Bug
• Resolution: Fixed
• Priority: Blocker
• Fix Version/s: Lustre 2.1.0
• Environment: lustre-master build #176/RHEL6/x86_64
• Severity: 3
• Assignee: Zhenyu Xu
• Reporter: Sarah Liu

Description

got following error when running sanity test on the latest master build RHEL6/x86_64

Lustre: DEBUG MARKER: == sanity test 30b: execute binary from Lustre as non-root ============= 14:52:31 (1308606751)
Lustre: DEBUG MARKER: == sanity test 30c: execute binary from Lustre without read perms ====== 14:52:32 (1308606752)
Lustre: DEBUG MARKER: cancel_lru_locks mdc start
Lustre: DEBUG MARKER: cancel_lru_locks mdc stop
Lustre: DEBUG MARKER: cancel_lru_locks osc start
LustreError: 29727:0:(ldlm_request.c:1169:ldlm_cli_cancel_req()) Got rc -11 from cancel RPC: canceling anyway
LustreError: 29727:0:(ldlm_request.c:1796:ldlm_cli_cancel_list()) ldlm_cli_cancel_list: -11
Lustre: DEBUG MARKER: cancel_lru_locks osc stop
LustreError: 2232:0:(vvp_io.c:673:vvp_io_kernel_fault()) unknow error in page fault!
ls invoked oom-killer: gfp_mask=0x0, order=0, oom_adj=0
ls cpuset=/ mems_allowed=0
Pid: 2232, comm: ls Tainted: G ---------------- T 2.6.32-131.2.1.el6.x86_64 #1
Call Trace:
[<ffffffff810c0061>] ? cpuset_print_task_mems_allowed+0x91/0xb0
[<ffffffff811101fb>] ? oom_kill_process+0xcb/0x2e0
[<ffffffff811107c0>] ? select_bad_process+0xd0/0x110
[<ffffffff81110858>] ? __out_of_memory+0x58/0xc0
[<ffffffff81110b1d>] ? pagefault_out_of_memory+0x4d/0x90
[<ffffffff8104110e>] ? mm_fault_error+0x4e/0x100
[<ffffffff810416e6>] ? __do_page_fault+0x336/0x480
[<ffffffff8112dbc0>] ? vma_prio_tree_insert+0x30/0x50
[<ffffffff8113ac8c>] ? __vma_link_file+0x4c/0x80
[<ffffffff8113b45b>] ? vma_link+0x9b/0xf0
[<ffffffff8113d9e9>] ? mmap_region+0x269/0x590
[<ffffffff814e017e>] ? do_page_fault+0x3e/0xa0
[<ffffffff814dd525>] ? page_fault+0x25/0x30
[<ffffffff8126e4af>] ? __clear_user+0x3f/0x70
[<ffffffff8126e491>] ? __clear_user+0x21/0x70
[<ffffffff8126e518>] ? clear_user+0x38/0x40
[<ffffffff811c4e4d>] ? padzero+0x2d/0x40
[<ffffffff811c6e6e>] ? load_elf_binary+0x88e/0x1b10
[<ffffffff811330f1>] ? follow_page+0x321/0x460
[<ffffffff8113839f>] ? __get_user_pages+0x10f/0x420
[<ffffffff811c390c>] ? load_misc_binary+0xac/0x3e0
[<ffffffff81179f5b>] ? search_binary_handler+0x10b/0x350
[<ffffffff8117b0e9>] ? do_execve+0x239/0x310
[<ffffffff8126e5ca>] ? strncpy_from_user+0x4a/0x90
[<ffffffff810095ca>] ? sys_execve+0x4a/0x80
[<ffffffff8100b5ca>] ? stub_execve+0x6a/0xc0
Mem-Info:
Node 0 DMA per-cpu:
CPU 0: hi: 0, btch: 1 usd: 0
CPU 1: hi: 0, btch: 1 usd: 0
CPU 2: hi: 0, btch: 1 usd: 0
CPU 3: hi: 0, btch: 1 usd: 0
Node 0 DMA32 per-cpu:
CPU 0: hi: 186, btch: 31 usd: 156
CPU 1: hi: 186, btch: 31 usd: 0
CPU 2: hi: 186, btch: 31 usd: 29
CPU 3: hi: 186, btch: 31 usd: 0
Node 0 Normal per-cpu:
CPU 0: hi: 186, btch: 31 usd: 38
CPU 1: hi: 186, btch: 31 usd: 132
CPU 2: hi: 186, btch: 31 usd: 137
CPU 3: hi: 186, btch: 31 usd: 157
active_anon:6036 inactive_anon:16 isolated_anon:0
active_file:18077 inactive_file:80830 isolated_file:0
unevictable:0 dirty:42 writeback:0 unstable:0
free:2796991 slab_reclaimable:10069 slab_unreclaimable:64088
mapped:4093 shmem:62 pagetables:1015 bounce:0
Node 0 DMA free:15564kB min:80kB low:100kB high:120kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15156kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 2991 12081 12081
Node 0 DMA32 free:2734832kB min:16712kB low:20888kB high:25068kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3063392kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 0 9090 9090
Node 0 Normal free:8437568kB min:50784kB low:63480kB high:76176kB active_anon:24144kB inactive_anon:64kB active_file:72308kB inactive_file:323320kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:9308160kB mlocked:0kB dirty:168kB writeback:0kB mapped:16372kB shmem:248kB slab_reclaimable:40276kB slab_unreclaimable:256352kB kernel_stack:2168kB pagetables:4060kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 0 0 0
Node 0 DMA: 1*4kB 1*8kB 0*16kB 2*32kB 0*64kB 1*128kB 0*256kB 0*512kB 1*1024kB 1*2048kB 3*4096kB = 15564kB
Node 0 DMA32: 6*4kB 29*8kB 3*16kB 6*32kB 6*64kB 5*128kB 7*256kB 7*512kB 8*1024kB 6*2048kB 661*4096kB = 2734832kB
Node 0 Normal: 820*4kB 344*8kB 204*16kB 84*32kB 42*64kB 18*128kB 12*256kB 7*512kB 9*1024kB 4*2048kB 2050*4096kB = 8437840kB
98938 total pagecache pages
0 pages in swap cache
Swap cache stats: add 0, delete 0, find 0/0
Free swap = 14417912kB
Total swap = 14417912kB
3145712 pages RAM
98606 pages reserved
62563 pages shared
136399 pages non-shared
Out of memory: kill process 28271 (console-kit-dae) score 32533 or a child
Killed process 28271 (console-kit-dae) vsz:2082156kB, anon-rss:1268kB, file-rss:1940kB
Lustre: 28779:0:(import.c:529:import_select_connection()) lustre-OST0004-osc-ffff88030c0db000: tried all connections, increasing latency to 6s
Lustre: lustre-OST0004-osc-ffff88030c0db000: Connection restored to service lustre-OST0004 using nid 192.168.4.131@o2ib.
INFO: task ls:2232 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
ls D 0000000000000000 0 2232 2119 0x00000080
ffff8803023f3b08 0000000000000082 0000000000000000 0000000000000001
0000000000000188 0000000000000000 ffff8803027f1d88 0000000100336aa9
ffff88031ccd0638 ffff8803023f3fd8 000000000000f598 ffff88031ccd0638
Call Trace:
[<ffffffff814dcc95>] rwsem_down_failed_common+0x95/0x1d0
[<ffffffff814dcdf3>] rwsem_down_write_failed+0x23/0x30
[<ffffffff8126e1d3>] call_rwsem_down_write_failed+0x13/0x20
[<ffffffff814dc2f2>] ? down_write+0x32/0x40
[<ffffffff811c53fc>] elf_map+0x9c/0x170
[<ffffffff811c7e94>] load_elf_binary+0x18b4/0x1b10
[<ffffffff811330f1>] ? follow_page+0x321/0x460
[<ffffffff8113839f>] ? __get_user_pages+0x10f/0x420
[<ffffffff81179f5b>] search_binary_handler+0x10b/0x350
[<ffffffff8117b0e9>] do_execve+0x239/0x310
[<ffffffff8126e5ca>] ? strncpy_from_user+0x4a/0x90
[<ffffffff810095ca>] sys_execve+0x4a/0x80
[<ffffffff8100b5ca>] stub_execve+0x6a/0xc0
INFO: task ls:2232 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
ls D 0000000000000000 0 2232 2119 0x00000080
ffff8803023f3b08 0000000000000082 0000000000000000 0000000000000001
0000000000000188 0000000000000000 ffff8803027f1d88 0000000100336aa9
ffff88031ccd0638 ffff8803023f3fd8 000000000000f598 ffff88031ccd0638
Call Trace:
[<ffffffff814dcc95>] rwsem_down_failed_common+0x95/0x1d0
[<ffffffff814dcdf3>] rwsem_down_write_failed+0x23/0x30
[<ffffffff8126e1d3>] call_rwsem_down_write_failed+0x13/0x20
[<ffffffff814dc2f2>] ? down_write+0x32/0x40
[<ffffffff811c53fc>] elf_map+0x9c/0x170
[<ffffffff811c7e94>] load_elf_binary+0x18b4/0x1b10
[<ffffffff811330f1>] ? follow_page+0x321/0x460
[<ffffffff8113839f>] ? __get_user_pages+0x10f/0x420
[<ffffffff81179f5b>] search_binary_handler+0x10b/0x350
[<ffffffff8117b0e9>] do_execve+0x239/0x310
[<ffffffff8126e5ca>] ? strncpy_from_user+0x4a/0x90
[<ffffffff810095ca>] sys_execve+0x4a/0x80
[<ffffffff8100b5ca>] stub_execve+0x6a/0xc0
INFO: task ls:2232 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
ls D 0000000000000000 0 2232 2119 0x00000080
ffff8803023f3b08 0000000000000082 0000000000000000 0000000000000001
0000000000000188 0000000000000000 ffff8803027f1d88 0000000100336aa9
ffff88031ccd0638 ffff8803023f3fd8 000000000000f598 ffff88031ccd0638
Call Trace:
[<ffffffff814dcc95>] rwsem_down_failed_common+0x95/0x1d0
[<ffffffff814dcdf3>] rwsem_down_write_failed+0x23/0x30
[<ffffffff8126e1d3>] call_rwsem_down_write_failed+0x13/0x20
[<ffffffff814dc2f2>] ? down_write+0x32/0x40
[<ffffffff811c53fc>] elf_map+0x9c/0x170
[<ffffffff811c7e94>] load_elf_binary+0x18b4/0x1b10
[<ffffffff811330f1>] ? follow_page+0x321/0x460
[<ffffffff8113839f>] ? __get_user_pages+0x10f/0x420
[<ffffffff81179f5b>] search_binary_handler+0x10b/0x350
[<ffffffff8117b0e9>] do_execve+0x239/0x310
[<ffffffff8126e5ca>] ? strncpy_from_user+0x4a/0x90
[<ffffffff810095ca>] sys_execve+0x4a/0x80
[<ffffffff8100b5ca>] stub_execve+0x6a/0xc0
INFO: task ls:2232 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
ls D 0000000000000000 0 2232 2119 0x00000080
ffff8803023f3b08 0000000000000082 0000000000000000 0000000000000001
0000000000000188 0000000000000000 ffff8803027f1d88 0000000100336aa9
ffff88031ccd0638 ffff8803023f3fd8 000000000000f598 ffff88031ccd0638
Call Trace:
[<ffffffff814dcc95>] rwsem_down_failed_common+0x95/0x1d0
[<ffffffff814dcdf3>] rwsem_down_write_failed+0x23/0x30
[<ffffffff8126e1d3>] call_rwsem_down_write_failed+0x13/0x20
[<ffffffff814dc2f2>] ? down_write+0x32/0x40
[<ffffffff811c53fc>] elf_map+0x9c/0x170
[<ffffffff811c7e94>] load_elf_binary+0x18b4/0x1b10
[<ffffffff811330f1>] ? follow_page+0x321/0x460
[<ffffffff8113839f>] ? __get_user_pages+0x10f/0x420
[<ffffffff81179f5b>] search_binary_handler+0x10b/0x350
[<ffffffff8117b0e9>] do_execve+0x239/0x310
[<ffffffff8126e5ca>] ? strncpy_from_user+0x4a/0x90
[<ffffffff810095ca>] sys_execve+0x4a/0x80
[<ffffffff8100b5ca>] stub_execve+0x6a/0xc0