Re: [RFC][PATCH v2 0/5] Experiments with overlayfs filemap

[Amir Goldstein <amir73il@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 1070 bytes --]

On Thu, Jan 31, 2019 at 6:24 PM Miklos Szeredi <miklos@szeredi.hu> wrote:
>
> There's some progress: it makes it through xfstests without crashing
> or deadlocking.  There are still some regressing test cases, but
> things definitely look better.
>

They do!

kmemleak detected leaking ovl_readpage_work in ovl_readpage_work_fn()
and creator_cred in ovl_direct_IO().
I pushed your patch with the leak fixes to  ovl-aops-wip as a testing point.

> What remains is ctime/mtime support.
>
> Also fallocate/copyfile/reflink/etc will need some thought as we need
> to not only flush out dirty pages, but in some cases prevent new
> faults while the operation is in progress.

Well, generic/503 which exercises these corners hangs
(503.dmesg attached)

>
> And after that it needs to be optimized (->readpages() and
> ->writepages()), but I think that's the easy part.
>

And we also need to flush pages on non direct IO cases
of ->writepages() and then we can revert:
e8d4bfe3a715 ovl: Sync upper dirty data when syncing overlayfs
and swoop the grand prize :)

Thanks,
Amir.

[-- Attachment #2: 503.demg --]
[-- Type: application/octet-stream, Size: 4712 bytes --]

[ 2211.624509] INFO: task kworker/0:1:27923 blocked for more than 120 seconds.
[ 2211.629034]       Not tainted 5.0.0-rc1-xfstests-00012-g60d58209fbdd-dirty #4105
[ 2211.633470] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2211.637586] kworker/0:1     D    0 27923      2 0x80000000
[ 2211.638720] Workqueue: ovl_writeback ovl_readpage_work_fn
[ 2211.639654] Call Trace:
[ 2211.640095]  ? __schedule+0x939/0x9ae
[ 2211.640734]  ? rwsem_down_read_failed+0x121/0x196
[ 2211.641681]  schedule+0x6e/0x86
[ 2211.642462]  rwsem_down_read_failed+0x155/0x196
[ 2211.643533]  ? xfs_file_buffered_aio_read+0x10c/0x135
[ 2211.644704]  ? call_rwsem_down_read_failed+0x14/0x30
[ 2211.645541]  call_rwsem_down_read_failed+0x14/0x30
[ 2211.646475]  down_read_nested+0x79/0x9c
[ 2211.647808]  xfs_ilock+0x18b/0x208
[ 2211.648638]  xfs_file_buffered_aio_read+0x10c/0x135
[ 2211.649649]  xfs_file_read_iter+0x81/0xc8
[ 2211.650417]  do_iter_readv_writev+0x15a/0x191
[ 2211.651230]  do_iter_read+0x87/0xfb
[ 2211.651709]  ovl_do_readpage+0x8b/0x139
[ 2211.652235]  ovl_readpage_work_fn+0x16/0x29
[ 2211.652820]  process_one_work+0x2d3/0x4f5
[ 2211.653393]  ? worker_thread+0x23e/0x2b6
[ 2211.653947]  worker_thread+0x1e2/0x2b6
[ 2211.654685]  ? process_scheduled_works+0x2c/0x2c
[ 2211.655641]  kthread+0x124/0x12c
[ 2211.656331]  ? __kthread_create_on_node+0x196/0x196
[ 2211.657354]  ret_from_fork+0x3a/0x50
[ 2211.658113] INFO: task t_mmap_collisio:8210 blocked for more than 120 seconds.
[ 2211.659601]       Not tainted 5.0.0-rc1-xfstests-00012-g60d58209fbdd-dirty #4105
[ 2211.661051] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2211.662468] t_mmap_collisio D    0  8210   7956 0x00000000
[ 2211.663412] Call Trace:
[ 2211.663850]  ? __schedule+0x939/0x9ae
[ 2211.664528]  schedule+0x6e/0x86
[ 2211.665197]  io_schedule+0x12/0x33
[ 2211.665902]  __lock_page+0x186/0x20f
[ 2211.666539]  ? __add_to_page_cache_locked+0x264/0x264
[ 2211.667422]  truncate_inode_pages_range+0x51e/0x5d1
[ 2211.668311]  ? tlb_flush_mmu_free+0x15/0x42
[ 2211.669190]  ? arch_tlb_finish_mmu+0x8f/0xb2
[ 2211.670003]  ? tlb_finish_mmu+0x1e/0x2a
[ 2211.670752]  ? zap_page_range_single+0xbf/0xe3
[ 2211.671622]  ? kvm_clock_read+0x14/0x1c
[ 2211.672468]  ? kvm_sched_clock_read+0x5/0xd
[ 2211.673211]  ? uncore_event_cpu_offline+0x81/0x117
[ 2211.673880]  ? sched_clock_cpu+0x10/0xad
[ 2211.674641]  ? up_write+0x1c/0x79
[ 2211.675415]  ? unmap_mapping_pages+0x63/0x110
[ 2211.676325]  truncate_pagecache+0x3b/0x51
[ 2211.677162]  ovl_setattr+0x18c/0x1f9
[ 2211.677946]  notify_change+0x273/0x353
[ 2211.678742]  ? ovl_other_xattr_set+0x1e/0x1e
[ 2211.679628]  do_truncate+0x81/0xb4
[ 2211.680349]  ? rcu_read_lock_sched_held+0x5d/0x63
[ 2211.681361]  do_sys_ftruncate+0xcb/0x14b
[ 2211.682128]  do_syscall_64+0x57/0x14e
[ 2211.682869]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 2211.683884] RIP: 0033:0x7fe1ebf7cc87
[ 2211.684773] Code: Bad RIP value.
[ 2211.685534] RSP: 002b:00007fe1eb697f38 EFLAGS: 00000246 ORIG_RAX: 000000000000004d
[ 2211.687288] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fe1ebf7cc87
[ 2211.688724] RDX: 9837804094cc53b7 RSI: 0000000000000000 RDI: 0000000000000003
[ 2211.689734] RBP: 0000000010624dd3 R08: 00007fe1eb698700 R09: 00007fe1eb698700
[ 2211.690985] R10: 00007fe1eb6989d0 R11: 0000000000000246 R12: 0000000000000000
[ 2211.692491] R13: 00007ffdf0ead29f R14: 00007fe1eb698700 R15: 000055ff026a2240
[ 2211.693741] 
[ 2211.693741] Showing all locks held in the system:
[ 2211.694870] 1 lock held by khungtaskd/261:
[ 2211.695728]  #0: 0000000058dadfef (rcu_read_lock){....}, at: debug_show_all_locks+0x14/0x17b
[ 2211.697195] 3 locks held by kworker/0:1/27923:
[ 2211.697995]  #0: 00000000c1a41107 ((wq_completion)"ovl_writeback"){+.+.}, at: process_one_work+0x1af/0x4f5
[ 2211.699789]  #1: 000000009a0e6fe7 ((work_completion)(&ow->work)){+.+.}, at: process_one_work+0x1af/0x4f5
[ 2211.701457]  #2: 00000000f4e30bc0 (&sb->s_type->i_mutex_key#13){++++}, at: xfs_ilock+0x18b/0x208
[ 2211.702909] 1 lock held by t_mmap_collisio/8209:
[ 2211.703656]  #0: 0000000078d2625e (&inode->i_rwsem){++++}, at: xfs_ilock+0x18b/0x208
[ 2211.705398] 4 locks held by t_mmap_collisio/8210:
[ 2211.706454]  #0: 000000006b6c5f2a (sb_writers#11){.+.+}, at: do_sys_ftruncate+0xae/0x14b
[ 2211.708008]  #1: 000000005e6e3d55 (&ovl_i_mutex_key[depth]){+.+.}, at: do_truncate+0x72/0xb4
[ 2211.709460]  #2: 0000000070704028 (sb_writers#9){.+.+}, at: mnt_want_write+0x1d/0x42
[ 2211.710791]  #3: 00000000f4e30bc0 (&sb->s_type->i_mutex_key#13){++++}, at: ovl_setattr+0xfe/0x1f9
[ 2211.712530] 
[ 2211.712851] =============================================
[ 2211.712851]