Re: freezing system for several second on high I/O [kernel 4.15]

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



On Wed, Feb 07, 2018 at 08:40:45AM +0500, mikhail wrote:
> On Tue, 2018-02-06 at 12:12 +0500, Mikhail Gavrilov wrote:
> > On 6 February 2018 at 11:08, Dave Chinner <david@xxxxxxxxxxxxx> wrote:
> Yet another hung:
> Trace report: https://dumps.sy24.ru/1/trace_report.txt.bz2 (9.4 MB)
> dmesg:
> [  369.374381] INFO: task TaskSchedulerFo:5624 blocked for more than 120 seconds.
> [  369.374391]       Not tainted 4.15.0-rc4-amd-vega+ #9
> [  369.374393] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [  369.374395] TaskSchedulerFo D11688  5624   3825 0x00000000
> [  369.374400] Call Trace:
> [  369.374407]  __schedule+0x2dc/0xba0
> [  369.374410]  ? __lock_acquire+0x2d4/0x1350
> [  369.374415]  ? __down+0x84/0x110
> [  369.374417]  schedule+0x33/0x90
> [  369.374419]  schedule_timeout+0x25a/0x5b0
> [  369.374423]  ? mark_held_locks+0x5f/0x90
> [  369.374425]  ? _raw_spin_unlock_irq+0x2c/0x40
> [  369.374426]  ? __down+0x84/0x110
> [  369.374429]  ? trace_hardirqs_on_caller+0xf4/0x190
> [  369.374431]  ? __down+0x84/0x110
> [  369.374433]  __down+0xac/0x110
> [  369.374466]  ? _xfs_buf_find+0x263/0xac0 [xfs]
> [  369.374470]  down+0x41/0x50
> [  369.374472]  ? down+0x41/0x50
> [  369.374490]  xfs_buf_lock+0x4e/0x270 [xfs]
> [  369.374507]  _xfs_buf_find+0x263/0xac0 [xfs]
> [  369.374528]  xfs_buf_get_map+0x29/0x490 [xfs]
> [  369.374545]  xfs_buf_read_map+0x2b/0x300 [xfs]
> [  369.374567]  xfs_trans_read_buf_map+0xc4/0x5d0 [xfs]
> [  369.374585]  xfs_read_agi+0xaa/0x200 [xfs]
> [  369.374605]  xfs_iunlink+0x4d/0x150 [xfs]
> [  369.374609]  ? current_time+0x32/0x70
> [  369.374629]  xfs_droplink+0x54/0x60 [xfs]
> [  369.374654]  xfs_rename+0xb15/0xd10 [xfs]
> [  369.374680]  xfs_vn_rename+0xd3/0x140 [xfs]
> [  369.374687]  vfs_rename+0x476/0x960
> [  369.374695]  SyS_rename+0x33f/0x390
> [  369.374704]  entry_SYSCALL_64_fastpath+0x1f/0x96

Again, this is waiting on a lock....

> [  369.374707] RIP: 0033:0x7f01cf705137
> [  369.374708] RSP: 002b:00007f01873e5608 EFLAGS: 00000202 ORIG_RAX: 0000000000000052
> [  369.374710] RAX: ffffffffffffffda RBX: 0000000000000119 RCX: 00007f01cf705137
> [  369.374711] RDX: 00007f01873e56dc RSI: 00003a5cd3540850 RDI: 00003a5cd7ea8000
> [  369.374713] RBP: 00007f01873e6340 R08: 0000000000000000 R09: 00007f01873e54e0
> [  369.374714] R10: 00007f01873e55f0 R11: 0000000000000202 R12: 00007f01873e6218
> [  369.374715] R13: 00007f01873e6358 R14: 0000000000000000 R15: 00003a5cd8416000
> [  369.374725] INFO: task disk_cache:0:3971 blocked for more than 120 seconds.
> [  369.374727]       Not tainted 4.15.0-rc4-amd-vega+ #9
> [  369.374729] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [  369.374731] disk_cache:0    D12432  3971   3903 0x00000000
> [  369.374735] Call Trace:
> [  369.374738]  __schedule+0x2dc/0xba0
> [  369.374743]  ? wait_for_completion+0x10e/0x1a0
> [  369.374745]  schedule+0x33/0x90
> [  369.374747]  schedule_timeout+0x25a/0x5b0
> [  369.374751]  ? mark_held_locks+0x5f/0x90
> [  369.374753]  ? _raw_spin_unlock_irq+0x2c/0x40
> [  369.374755]  ? wait_for_completion+0x10e/0x1a0
> [  369.374757]  ? trace_hardirqs_on_caller+0xf4/0x190
> [  369.374760]  ? wait_for_completion+0x10e/0x1a0
> [  369.374762]  wait_for_completion+0x136/0x1a0
> [  369.374765]  ? wake_up_q+0x80/0x80
> [  369.374782]  ? _xfs_buf_read+0x23/0x30 [xfs]
> [  369.374798]  xfs_buf_submit_wait+0xb2/0x530 [xfs]
> [  369.374814]  _xfs_buf_read+0x23/0x30 [xfs]
> [  369.374828]  xfs_buf_read_map+0x14b/0x300 [xfs]
> [  369.374847]  ? xfs_trans_read_buf_map+0xc4/0x5d0 [xfs]
> [  369.374867]  xfs_trans_read_buf_map+0xc4/0x5d0 [xfs]
> [  369.374883]  xfs_da_read_buf+0xca/0x110 [xfs]
> [  369.374901]  xfs_dir3_data_read+0x23/0x60 [xfs]
> [  369.374916]  xfs_dir2_leaf_addname+0x335/0x8b0 [xfs]
> [  369.374936]  xfs_dir_createname+0x17e/0x1d0 [xfs]
> [  369.374956]  xfs_create+0x6ad/0x840 [xfs]
> [  369.374981]  xfs_generic_create+0x1fa/0x2d0 [xfs]
> [  369.375000]  xfs_vn_mknod+0x14/0x20 [xfs]
> [  369.375016]  xfs_vn_create+0x13/0x20 [xfs]

That is held by this process, one it is waiting for IO completion.

There's nothing in the traces relating to this IO, because the trace
only starts at 270s after boot, and this process has been waiting
since submitting it's IO at 250s after boot. The traces tell me that
IO is still running, but it only takes on IO to go missing for
everything to have problems.

> [  369.378073] =============================================
> 
> Again false positive?

The lockdep false positive in the previous trace has nothing to do
with the IO completion/hung task issue here.

> If it not fs problem why process blocked for such time?

Lots of reasons, but the typical reason for Io completion not
occurring is that broken hardware.

And it looks like there's another different trace appended, and this
one is quite instructive:

> [  237.360627]   task                        PC stack   pid father
> [  237.360882] tracker-store   D12296  2481   1846 0x00000000
> [  237.360894] Call Trace:
> [  237.360901]  __schedule+0x2dc/0xba0
> [  237.360905]  ? _raw_spin_unlock_irq+0x2c/0x40
> [  237.360913]  schedule+0x33/0x90
> [  237.360918]  io_schedule+0x16/0x40
> [  237.360923]  generic_file_read_iter+0x3b8/0xe10
> [  237.360937]  ? page_cache_tree_insert+0x140/0x140
> [  237.360985]  xfs_file_buffered_aio_read+0x6e/0x1a0 [xfs]
> [  237.361018]  xfs_file_read_iter+0x68/0xc0 [xfs]
> [  237.361023]  __vfs_read+0xf1/0x160
> [  237.361035]  vfs_read+0xa3/0x150
> [  237.361042]  SyS_pread64+0x98/0xc0
> [  237.361048]  entry_SYSCALL_64_fastpath+0x1f/0x96

There are multiple processes stuck waiting for data read IO
completion. 

> [  237.361546] TaskSchedulerFo D12184  4005   3825 0x00000000
> [  237.361554] Call Trace:
> [  237.361560]  __schedule+0x2dc/0xba0
> [  237.361566]  ? _raw_spin_unlock_irq+0x2c/0x40
> [  237.361572]  schedule+0x33/0x90
> [  237.361577]  io_schedule+0x16/0x40
> [  237.361581]  wait_on_page_bit+0xd7/0x170
> [  237.361588]  ? page_cache_tree_insert+0x140/0x140
> [  237.361596]  truncate_inode_pages_range+0x702/0x9d0
> [  237.361606]  ? generic_write_end+0x98/0x100
> [  237.361617]  ? sched_clock+0x9/0x10
> [  237.361623]  ? unmap_mapping_range+0x76/0x130
> [  237.361632]  ? up_write+0x1f/0x40
> [  237.361636]  ? unmap_mapping_range+0x76/0x130
> [  237.361643]  truncate_pagecache+0x48/0x70
> [  237.361648]  truncate_setsize+0x32/0x40
> [  237.361677]  xfs_setattr_size+0xe3/0x340 [xfs]

And there's a truncate blocked waiting for data IO completion.

> [  237.361842]  wait_for_completion+0x136/0x1a0
> [  237.361846]  ? wake_up_q+0x80/0x80
> [  237.361872]  ? _xfs_buf_read+0x23/0x30 [xfs]
> [  237.361898]  xfs_buf_submit_wait+0xb2/0x530 [xfs]
> [  237.361935]  _xfs_buf_read+0x23/0x30 [xfs]
> [  237.361958]  xfs_buf_read_map+0x14b/0x300 [xfs]
> [  237.361981]  ? xfs_trans_read_buf_map+0xc4/0x5d0 [xfs]
> [  237.362003]  xfs_trans_read_buf_map+0xc4/0x5d0 [xfs]
> [  237.362005]  ? rcu_read_lock_sched_held+0x79/0x80
> [  237.362027]  xfs_imap_to_bp+0x67/0xe0 [xfs]
> [  237.362056]  xfs_iread+0x86/0x220 [xfs]
> [  237.362090]  xfs_iget+0x4c5/0x1070 [xfs]
> [  237.362094]  ? kfree+0xfe/0x2e0
> [  237.362132]  xfs_lookup+0x149/0x1e0 [xfs]
> [  237.362164]  xfs_vn_lookup+0x70/0xb0 [xfs]
> [  237.362172]  lookup_slow+0x132/0x220
> [  237.362192]  walk_component+0x1bd/0x340
> [  237.362202]  path_lookupat+0x84/0x1f0
> [  237.362212]  filename_lookup+0xb6/0x190
> [  237.362226]  ? __check_object_size+0xaf/0x1b0
> [  237.362233]  ? strncpy_from_user+0x4d/0x170
> [  237.362242]  user_path_at_empty+0x36/0x40
> [  237.362245]  ? user_path_at_empty+0x36/0x40
> [  237.362250]  vfs_statx+0x76/0xe0

and there's a stat() call blocked waiting for inode cluster read IO
completion.

> [  237.362321] TaskSchedulerFo D11576  5625   3825 0x00000000
> [  237.362328] Call Trace:
> [  237.362334]  __schedule+0x2dc/0xba0
> [  237.362339]  ? _raw_spin_unlock_irq+0x2c/0x40
> [  237.362346]  schedule+0x33/0x90
> [  237.362350]  io_schedule+0x16/0x40
> [  237.362355]  wait_on_page_bit_common+0x10a/0x1a0
> [  237.362362]  ? page_cache_tree_insert+0x140/0x140
> [  237.362371]  __filemap_fdatawait_range+0xfd/0x190
> [  237.362389]  filemap_write_and_wait_range+0x4b/0x90
> [  237.362412]  xfs_setattr_size+0x10b/0x340 [xfs]
> [  237.362433]  ? setattr_prepare+0x69/0x190
> [  237.362464]  xfs_vn_setattr_size+0x57/0x150 [xfs]
> [  237.362493]  xfs_vn_setattr+0x87/0xb0 [xfs]
> [  237.362502]  notify_change+0x300/0x420
> [  237.362512]  do_truncate+0x73/0xc0

Truncate explicitly waiting for data writeback completion.

> [  237.362586] Call Trace:
> [  237.362593]  __schedule+0x2dc/0xba0
> [  237.362622]  ? _xfs_log_force_lsn+0x2d4/0x360 [xfs]
> [  237.362634]  schedule+0x33/0x90
> [  237.362664]  _xfs_log_force_lsn+0x2d9/0x360 [xfs]
> [  237.362671]  ? wake_up_q+0x80/0x80
> [  237.362705]  xfs_file_fsync+0x10f/0x2b0 [xfs]
> [  237.362718]  vfs_fsync_range+0x4e/0xb0
> [  237.362726]  do_fsync+0x3d/0x70

fsync() waiting on log write IO completion.

> [  237.362804]  schedule_timeout+0x25a/0x5b0
> [  237.362811]  ? mark_held_locks+0x5f/0x90
> [  237.362815]  ? _raw_spin_unlock_irq+0x2c/0x40
> [  237.362818]  ? wait_for_completion+0x10e/0x1a0
> [  237.362823]  ? trace_hardirqs_on_caller+0xf4/0x190
> [  237.362829]  ? wait_for_completion+0x10e/0x1a0
> [  237.362833]  wait_for_completion+0x136/0x1a0
> [  237.362838]  ? wake_up_q+0x80/0x80
> [  237.362868]  ? _xfs_buf_read+0x23/0x30 [xfs]
> [  237.362897]  xfs_buf_submit_wait+0xb2/0x530 [xfs]
> [  237.362926]  _xfs_buf_read+0x23/0x30 [xfs]
> [  237.362952]  xfs_buf_read_map+0x14b/0x300 [xfs]
> [  237.362981]  ? xfs_trans_read_buf_map+0xc4/0x5d0 [xfs]
> [  237.363014]  xfs_trans_read_buf_map+0xc4/0x5d0 [xfs]
> [  237.363019]  ? rcu_read_lock_sched_held+0x79/0x80
> [  237.363048]  xfs_imap_to_bp+0x67/0xe0 [xfs]
> [  237.363081]  xfs_iread+0x86/0x220 [xfs]
> [  237.363116]  xfs_iget+0x4c5/0x1070 [xfs]
> [  237.363121]  ? kfree+0xfe/0x2e0
> [  237.363162]  xfs_lookup+0x149/0x1e0 [xfs]
> [  237.363195]  xfs_vn_lookup+0x70/0xb0 [xfs]
> [  237.363204]  lookup_open+0x2dc/0x7c0

open() waiting on inode read IO completion.

.....

And there's a lot more threads all waiting on IO completion, both
data or metadata, so I'm not going to bother commenting further
because filesystems don't hang like this by themselves.

i.e. This has all the hallmarks of something below the filesystem
dropping IO completions, such as the hardware being broken. The
filesystem is just the messenger....

Cheers,

Dave.
-- 
Dave Chinner
david@xxxxxxxxxxxxx

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@xxxxxxxxx.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@xxxxxxxxx";> email@xxxxxxxxx </a>



[Index of Archives]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Bugtraq]     [Linux OMAP]     [Linux MIPS]     [eCos]     [Asterisk Internet PBX]     [Linux API]

  Powered by Linux