************************* hanginfo ************************* /exports/testreports/47154/testresults/racer-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg231-client-timeout-core (3.10.0-7.9-debug) *** UNINTERRUPTIBLE threads, classified *** ================== Waiting in io_schedule ================== ... 82 pids. Youngest,oldest: 26456, 5894 Ran ms ago: 227284, 911872 printing 10 out of 82 sorted by ran_ago, youngest first [26456, 8807, 1210, 13273, 12281, <72 skipped>, 11901, 11635, 5387, 5386, 5894] ================= Waiting on inode mutexes ================= -- /mnt/lustre2/racer0 -- lustre_inode_cache Owner: pid=8320 cmd=mrename ... 30 pids. Youngest,oldest: 12850, 8347 Ran ms ago: 811200, 884075 printing 10 out of 30 sorted by ran_ago, youngest first [12850, 12803, 12773, 12763, 12841, <20 skipped>, 8394, 8406, 8380, 8370, 8347] ==================== Waiting on mutexes ==================== -- lustre_inode_cache Owner: pid=12235 cmd=truncate ... 1 pids. Youngest,oldest: 12231, 12231 Ran ms ago: 910362, 910362 sorted by ran_ago, youngest first [12231] -- lustre_inode_cache Owner: pid=26332 cmd=rm ... 17 pids. Youngest,oldest: 6826, 27515 Ran ms ago: 759737, 869008 printing 10 out of 17 sorted by ran_ago, youngest first [6826, 1635, 30350, 30233, 29524, <7 skipped>, 28279, 28295, 27995, 27531, 27515] -- lustre_inode_cache Owner: pid=7517 cmd=cp ... 11 pids. Youngest,oldest: 10974, 7387 Ran ms ago: 881815, 884535 printing 10 out of 11 sorted by ran_ago, youngest first [10974, 11418, 10084, 9683, 9744, <1 skipped>, 9307, 8708, 8699, 8387, 7387] -- lustre_inode_cache Owner: pid=14496 cmd=dd ... 1 pids. Youngest,oldest: 15402, 15402 Ran ms ago: 907662, 907662 sorted by ran_ago, youngest first [15402] -- lustre_inode_cache Owner: pid=12674 cmd=truncate ... 6 pids. Youngest,oldest: 13796, 12546 Ran ms ago: 908674, 909834 sorted by ran_ago, youngest first [13796, 13826, 13404, 13156, 12844, 12546] -- lustre_inode_cache Owner: pid=10421 cmd=dir_create.sh ... 4 pids. Youngest,oldest: 20556, 14323 Ran ms ago: 901505, 908028 sorted by ran_ago, youngest first [20556, 20947, 21089, 14323] -- lustre_inode_cache Owner: pid=6110 cmd=rm ... 8 pids. Youngest,oldest: 8292, 5468 Ran ms ago: 883499, 885501 sorted by ran_ago, youngest first [8292, 8320, 7628, 7118, 7299, 7140, 6537, 5468] -- lustre_inode_cache Owner: pid=13297 cmd=truncate ... 2 pids. Youngest,oldest: 13938, 13729 Ran ms ago: 908578, 908602 sorted by ran_ago, youngest first [13938, 13729] -- lustre_inode_cache Owner: pid=13805 cmd=cp ... 3 pids. Youngest,oldest: 14615, 13998 Ran ms ago: 907904, 908711 sorted by ran_ago, youngest first [14615, 14303, 13998] -- lustre_inode_cache Owner: pid=7517 cmd=cp ... 2 pids. Youngest,oldest: 11240, 7355 Ran ms ago: 881841, 884293 sorted by ran_ago, youngest first [11240, 7355] -- lustre_inode_cache Owner: pid=30319 cmd=dd ... 3 pids. Youngest,oldest: 30483, 30516 Ran ms ago: 892717, 892881 sorted by ran_ago, youngest first [30483, 30654, 30516] -- lustre_inode_cache Owner: pid=14496 cmd=dd ... 1 pids. Youngest,oldest: 20299, 20299 Ran ms ago: 902501, 902501 sorted by ran_ago, youngest first [20299] -- kmalloc-2048 Owner: pid=8292 cmd=mrename ... 6 pids. Youngest,oldest: 13045, 8282 Ran ms ago: 880547, 884037 sorted by ran_ago, youngest first [13045, 12848, 11658, 9102, 9105, 8282] ******** Non-classified UN Threads ********** 4 in total ------- 1 stacks like that: ---------- #0 __schedule #1 schedule #2 __wait_on_freeing_inode #3 find_inode #4 ilookup5_nowait #5 ilookup5 #6 iget5_locked #7 ll_iget #8 ll_prep_inode #9 ll_lookup_it_finish #10 ll_lookup_it.constprop.42 #11 ll_atomic_open #12 do_last #13 path_openat #14 do_filp_open #15 do_sys_open #16 sys_open #17 system_call_fastpath ........................ dir_create.sh 1 times ... PIDs ... 10275 ------- 1 stacks like that: ---------- #0 __schedule #1 schedule #2 vvp_io_setattr_start #3 cl_io_start #4 cl_io_loop #5 ll_fallocate #6 vfs_fallocate #7 sys_fallocate #8 system_call_fastpath ........................ fallocate 1 times ... PIDs ... 8626 ------- 2 stacks like that: ---------- #0 __schedule #1 schedule #2 __wait_on_freeing_inode #3 find_inode #4 ilookup5_nowait #5 ilookup5 #6 iget5_locked #7 ll_iget #8 ll_prep_inode #9 ll_lookup_it_finish #10 ll_lookup_it.constprop.42 #11 ll_lookup_nd #12 lookup_real #13 __lookup_hash #14 do_unlinkat #15 sys_unlinkat #16 system_call_fastpath ........................ rm 2 times ... PIDs ... 6110 26332 *** Threads that own resources the other threads are waiting on *** PID=8320 CPU=3 CMD=mrename #0 __schedule+0x2e2 #1 schedule_preempt_disabled+0x39 #2 __mutex_lock_slowpath+0x13a #3 mutex_lock+0x2d #4 vfs_rename+0x41d #5 SYSC_renameat2+0x4d3 #6 sys_renameat2+0xe #7 sys_rename+0x1e #8 system_call_fastpath+0x1f, 477 bytes of data {8321, 8385, 12803, 8391, 8394, 14026, 8398, 8336, 8146, 8405, 8406, 8347, 12763, 8156, 8479, 12832, 8545, 8357, 8421, 12773, 8423, 12841, 8426, 8107, 8367, 8370, 12850, 8373, 8565, 8380} PID=14496 CPU=2 CMD=dd #0 __schedule+0x2e2 #1 schedule+0x29 #2 schedule_timeout+0x209 #3 io_schedule_timeout+0xad #4 io_schedule+0x18 #5 bit_wait_io+0x11 #6 __wait_on_bit_lock+0x5f #7 __lock_page+0x74 #8 truncate_inode_pages_range+0x79a #9 truncate_pagecache+0x47 #10 vvp_io_setattr_end+0xa4 #11 cl_io_end+0x5c #12 cl_io_loop+0xad #13 cl_setattr_ost+0x2af #14 ll_setattr_raw+0x1430 #15 ll_setattr+0x56 #16 notify_change+0x309 #17 do_truncate+0x75 #18 do_last+0x5f6 #19 path_openat+0xcd #20 do_filp_open+0x4d #21 do_sys_open+0x124 #22 sys_open+0x1e #23 system_call_fastpath+0x1f, 477 bytes of data {15402, 20299} PID=12674 CPU=1 CMD=truncate #0 __schedule+0x2e2 #1 schedule+0x29 #2 schedule_timeout+0x209 #3 io_schedule_timeout+0xad #4 io_schedule+0x18 #5 bit_wait_io+0x11 #6 __wait_on_bit_lock+0x5f #7 __lock_page+0x74 #8 truncate_inode_pages_range+0x79a #9 truncate_pagecache+0x47 #10 vvp_io_setattr_end+0xa4 #11 cl_io_end+0x5c #12 cl_io_loop+0xad #13 cl_setattr_ost+0x2af #14 ll_setattr_raw+0x1430 #15 ll_setattr+0x56 #16 notify_change+0x309 #17 do_truncate+0x75 #18 vfs_truncate+0x171 #19 do_sys_truncate+0x8c #20 sys_truncate+0xe #21 system_call_fastpath+0x1f, 477 bytes of data {12546, 13826, 13156, 13796, 12844, 13404} PID=8292 CPU=1 CMD=mrename #0 __schedule+0x2e2 #1 schedule_preempt_disabled+0x39 #2 __mutex_lock_slowpath+0x13a #3 mutex_lock+0x2d #4 lock_rename+0xc9 #5 SYSC_renameat2+0x22f #6 sys_renameat2+0xe #7 sys_rename+0x1e #8 system_call_fastpath+0x1f, 477 bytes of data {12848, 9105, 13045, 8282, 11658, 9102} PID=12235 CPU=2 CMD=truncate #0 __schedule+0x2e2 #1 schedule+0x29 #2 schedule_timeout+0x209 #3 io_schedule_timeout+0xad #4 io_schedule+0x18 #5 bit_wait_io+0x11 #6 __wait_on_bit_lock+0x5f #7 __lock_page+0x74 #8 __find_lock_page+0x66 #9 find_lock_page+0xe #10 truncate_inode_pages_range+0x5cd #11 truncate_pagecache+0x47 #12 vvp_io_setattr_end+0xa4 #13 cl_io_end+0x5c #14 cl_io_loop+0xad #15 cl_setattr_ost+0x2af #16 ll_setattr_raw+0x1430 #17 ll_setattr+0x56 #18 notify_change+0x309 #19 do_truncate+0x75 #20 vfs_truncate+0x171 #21 do_sys_truncate+0x8c #22 sys_truncate+0xe #23 system_call_fastpath+0x1f, 477 bytes of data {12231} PID=13805 CPU=1 CMD=cp #0 __schedule+0x2e2 #1 schedule+0x29 #2 schedule_timeout+0x209 #3 io_schedule_timeout+0xad #4 io_schedule+0x18 #5 bit_wait_io+0x11 #6 __wait_on_bit_lock+0x5f #7 __lock_page+0x74 #8 truncate_inode_pages_range+0x79a #9 truncate_pagecache+0x47 #10 vvp_io_setattr_end+0xa4 #11 cl_io_end+0x5c #12 cl_io_loop+0xad #13 cl_setattr_ost+0x2af #14 ll_setattr_raw+0x1430 #15 ll_setattr+0x56 #16 notify_change+0x309 #17 do_truncate+0x75 #18 do_last+0x5f6 #19 path_openat+0x457 #20 do_filp_open+0x4d #21 do_sys_open+0x124 #22 sys_open+0x1e #23 system_call_fastpath+0x1f, 477 bytes of data {14615, 13998, 14303} PID=30319 CPU=2 CMD=dd #0 __schedule+0x2e2 #1 schedule+0x29 #2 schedule_timeout+0x209 #3 io_schedule_timeout+0xad #4 io_schedule+0x18 #5 bit_wait_io+0x11 #6 __wait_on_bit_lock+0x5f #7 __lock_page+0x74 #8 truncate_inode_pages_range+0x79a #9 truncate_pagecache+0x47 #10 vvp_io_setattr_end+0xa4 #11 cl_io_end+0x5c #12 cl_io_loop+0xad #13 cl_setattr_ost+0x2af #14 ll_setattr_raw+0x1430 #15 ll_setattr+0x56 #16 notify_change+0x309 #17 do_truncate+0x75 #18 do_last+0x5f6 #19 path_openat+0xcd #20 do_filp_open+0x4d #21 do_sys_open+0x124 #22 sys_open+0x1e #23 system_call_fastpath+0x1f, 477 bytes of data {30483, 30516, 30654} PID=13297 CPU=1 CMD=truncate #0 __schedule+0x2e2 #1 schedule+0x29 #2 schedule_timeout+0x209 #3 io_schedule_timeout+0xad #4 io_schedule+0x18 #5 bit_wait_io+0x11 #6 __wait_on_bit_lock+0x5f #7 __lock_page+0x74 #8 __find_lock_page+0x66 #9 find_lock_page+0xe #10 truncate_inode_pages_range+0x5cd #11 truncate_pagecache+0x47 #12 vvp_io_setattr_end+0xa4 #13 cl_io_end+0x5c #14 cl_io_loop+0xad #15 cl_setattr_ost+0x2af #16 ll_setattr_raw+0x1430 #17 ll_setattr+0x56 #18 notify_change+0x309 #19 do_truncate+0x75 #20 vfs_truncate+0x171 #21 do_sys_truncate+0x8c #22 sys_truncate+0xe #23 system_call_fastpath+0x1f, 477 bytes of data {13729, 13938} PID=10421 CPU=3 CMD=dir_create.sh #0 __schedule+0x2e2 #1 schedule+0x29 #2 schedule_timeout+0x209 #3 io_schedule_timeout+0xad #4 io_schedule+0x18 #5 bit_wait_io+0x11 #6 __wait_on_bit_lock+0x5f #7 __lock_page+0x74 #8 truncate_inode_pages_range+0x79a #9 truncate_pagecache+0x47 #10 vvp_io_setattr_end+0xa4 #11 cl_io_end+0x5c #12 cl_io_loop+0xad #13 cl_setattr_ost+0x2af #14 ll_setattr_raw+0x1430 #15 ll_setattr+0x56 #16 notify_change+0x309 #17 do_truncate+0x75 #18 do_last+0x5f6 #19 path_openat+0xcd #20 do_filp_open+0x4d #21 do_sys_open+0x124 #22 sys_open+0x1e #23 system_call_fastpath+0x1f, 477 bytes of data {21089, 14323, 20556, 20947} PID=26332 CPU=3 CMD=rm #0 __schedule+0x2e2 #1 schedule+0x29 #2 __wait_on_freeing_inode+0xa9 #3 find_inode+0x99 #4 ilookup5_nowait+0x71 #5 ilookup5+0x2f #6 iget5_locked+0x2e #7 ll_iget+0x56 #8 ll_prep_inode+0x225 #9 ll_lookup_it_finish+0xc2 #10 ll_lookup_it.constprop.42+0x890 #11 ll_lookup_nd+0x110 #12 lookup_real+0x1d #13 __lookup_hash+0x42 #14 do_unlinkat+0x14c #15 sys_unlinkat+0x1b #16 system_call_fastpath+0x1f, 477 bytes of data {29312, 28295, 28487, 27531, 27339, 30350, 29011, 29524, 27773, 30233, 27995, 1635, 29287, 6826, 28279, 27515, 29181} PID=7517 CPU=1 CMD=cp #0 __schedule+0x2e2 #1 schedule+0x29 #2 schedule_timeout+0x209 #3 io_schedule_timeout+0xad #4 io_schedule+0x18 #5 bit_wait_io+0x11 #6 __wait_on_bit_lock+0x5f #7 __lock_page+0x74 #8 truncate_inode_pages_range+0x79a #9 truncate_pagecache+0x47 #10 vvp_io_setattr_end+0xa4 #11 cl_io_end+0x5c #12 cl_io_loop+0xad #13 cl_setattr_ost+0x2af #14 ll_setattr_raw+0x1430 #15 ll_setattr+0x56 #16 notify_change+0x309 #17 do_truncate+0x75 #18 do_last+0x5f6 #19 path_openat+0xcd #20 do_filp_open+0x4d #21 do_sys_open+0x124 #22 sys_open+0x1e #23 system_call_fastpath+0x1f, 477 bytes of data {8387, 8708, 10084, 11240, 7355, 7387, 9744, 9683, 9300, 8699, 11418, 9307, 10974} PID=6110 CPU=2 CMD=rm #0 __schedule+0x2e2 #1 schedule+0x29 #2 __wait_on_freeing_inode+0xa9 #3 find_inode+0x99 #4 ilookup5_nowait+0x71 #5 ilookup5+0x2f #6 iget5_locked+0x2e #7 ll_iget+0x56 #8 ll_prep_inode+0x225 #9 ll_lookup_it_finish+0xc2 #10 ll_lookup_it.constprop.42+0x890 #11 ll_lookup_nd+0x110 #12 lookup_real+0x1d #13 __lookup_hash+0x42 #14 do_unlinkat+0x14c #15 sys_unlinkat+0x1b #16 system_call_fastpath+0x1f, 477 bytes of data {8320, 7299, 7140, 8292, 6537, 7628, 7118, 5468} *** System activities other threads are waiting for *** --- Doing io_schedule --- {10499, 5894, 10760, 12808, 5386, 5387, 12817, 16401, 7956, 24344, 10265, 16672, 16930, 16163, 24869, 20774, 16428, 27436, 29742, 12337, 12095, 17728, 2631, 26456, 29016, 16218, 12893, 7517, 11359, 29794, 10340, 8807, 31337, 20841, 30319, 16497, 7282, 11635, 13947, 11901, 26497, 12674, 14210, 13197, 13709, 11923, 16788, 15257, 16028, 21150, 14496, 12704, 10926, 17586, 10421, 24757, 24504, 1210, 4798, 12225, 12235, 22223, 29904, 20179, 11731, 10453, 15573, 18133, 13273, 16608, 10218, 14315, 13805, 13297, 29426, 3828, 12533, 10228, 12281, 14076, 14590, 11007} +++WARNING+++ Possible hang ****************************************************************************** ************************ A Summary Of Problems Found ************************* ****************************************************************************** -------------------- A list of all +++WARNING+++ messages -------------------- Possible hang ------------------------------------------------------------------------------ ** Execution took 5.92s (real) 4.06s (CPU), Child processes: 1.85s