On Fri, Nov 29, 2019 at 03:41:01PM +0100, Andrea Vai wrote:
> Il giorno ven, 29/11/2019 alle 10.35 +0800, Ming Lei ha scritto:
> > On Fri, Nov 29, 2019 at 08:57:34AM +0800, Ming Lei wrote:
> >
> > > [...]
> >
> > > Andrea, can you collect the following log when running the test
> > > on current new(bad) kernel?
> > >
> > > /usr/share/bcc/tools/stackcount -K blk_mq_make_request
> >
> > Instead, please run the following trace, given insert may be
> > called from other paths, such as flush plug:
> >
> > /usr/share/bcc/tools/stackcount -K t:block:block_rq_insert
>
> Attached, for new (patched) bad kernel.
>
> Produced by: start the trace script (with the pendrive already
> plugged), wait some seconds, run the test (1 trial, 1 GB), wait for
> the test to finish, stop the trace.
>
> The copy took ~1700 seconds.
See the two path[1][2] of inserting request, and path[1] is triggered
4358 times, and the path[2] is triggered 5763 times.
The path[2] is expected behaviour. Not sure path [1] is correct, given
ext4_release_file() is supposed to be called when this inode is
released. That means the file is closed 4358 times during 1GB file
copying to usb storage.
Cc filesystem list.
[1] insert requests when returning to user mode from syscall
b'blk_mq_sched_request_inserted'
b'blk_mq_sched_request_inserted'
b'dd_insert_requests'
b'blk_mq_sched_insert_requests'
b'blk_mq_flush_plug_list'
b'blk_flush_plug_list'
b'io_schedule_prepare'
b'io_schedule'
b'rq_qos_wait'
b'wbt_wait'
b'__rq_qos_throttle'
b'blk_mq_make_request'
b'generic_make_request'
b'submit_bio'
b'ext4_io_submit'
b'ext4_writepages'
b'do_writepages'
b'__filemap_fdatawrite_range'
b'ext4_release_file'
b'__fput'
b'task_work_run'
b'exit_to_usermode_loop'
b'do_syscall_64'
b'entry_SYSCALL_64_after_hwframe'
4358
[2] insert requests from writeback wq context
b'blk_mq_sched_request_inserted'
b'blk_mq_sched_request_inserted'
b'dd_insert_requests'
b'blk_mq_sched_insert_requests'
b'blk_mq_flush_plug_list'
b'blk_flush_plug_list'
b'io_schedule_prepare'
b'io_schedule'
b'rq_qos_wait'
b'wbt_wait'
b'__rq_qos_throttle'
b'blk_mq_make_request'
b'generic_make_request'
b'submit_bio'
b'ext4_io_submit'
b'ext4_bio_write_page'
b'mpage_submit_page'
b'mpage_process_page_bufs'
b'mpage_prepare_extent_to_map'
b'ext4_writepages'
b'do_writepages'
b'__writeback_single_inode'
b'writeback_sb_inodes'
b'__writeback_inodes_wb'
b'wb_writeback'
b'wb_workfn'
b'process_one_work'
b'worker_thread'
b'kthread'
b'ret_from_fork'
5763
Thanks,
Ming
Il giorno mar, 03/12/2019 alle 10.23 +0800, Ming Lei ha scritto:
> On Fri, Nov 29, 2019 at 03:41:01PM +0100, Andrea Vai wrote:
> > Il giorno ven, 29/11/2019 alle 10.35 +0800, Ming Lei ha scritto:
> > > On Fri, Nov 29, 2019 at 08:57:34AM +0800, Ming Lei wrote:
> > >
> > > > [...]
> > >
> > > > Andrea, can you collect the following log when running the
> test
> > > > on current new(bad) kernel?
> > > >
> > > > /usr/share/bcc/tools/stackcount -K
> blk_mq_make_request
> > >
> > > Instead, please run the following trace, given insert may be
> > > called from other paths, such as flush plug:
> > >
> > > /usr/share/bcc/tools/stackcount -K t:block:block_rq_insert
> >
> > Attached, for new (patched) bad kernel.
> >
> > Produced by: start the trace script (with the pendrive already
> > plugged), wait some seconds, run the test (1 trial, 1 GB), wait
> for
> > the test to finish, stop the trace.
> >
> > The copy took ~1700 seconds.
>
> See the two path[1][2] of inserting request, and path[1] is
> triggered
> 4358 times, and the path[2] is triggered 5763 times.
>
> The path[2] is expected behaviour. Not sure path [1] is correct,
> given
> ext4_release_file() is supposed to be called when this inode is
> released. That means the file is closed 4358 times during 1GB file
> copying to usb storage.
>
> Cc filesystem list.
>
>
> [1] insert requests when returning to user mode from syscall
>
> b'blk_mq_sched_request_inserted'
> b'blk_mq_sched_request_inserted'
> b'dd_insert_requests'
> b'blk_mq_sched_insert_requests'
> b'blk_mq_flush_plug_list'
> b'blk_flush_plug_list'
> b'io_schedule_prepare'
> b'io_schedule'
> b'rq_qos_wait'
> b'wbt_wait'
> b'__rq_qos_throttle'
> b'blk_mq_make_request'
> b'generic_make_request'
> b'submit_bio'
> b'ext4_io_submit'
> b'ext4_writepages'
> b'do_writepages'
> b'__filemap_fdatawrite_range'
> b'ext4_release_file'
> b'__fput'
> b'task_work_run'
> b'exit_to_usermode_loop'
> b'do_syscall_64'
> b'entry_SYSCALL_64_after_hwframe'
> 4358
>
> [2] insert requests from writeback wq context
>
> b'blk_mq_sched_request_inserted'
> b'blk_mq_sched_request_inserted'
> b'dd_insert_requests'
> b'blk_mq_sched_insert_requests'
> b'blk_mq_flush_plug_list'
> b'blk_flush_plug_list'
> b'io_schedule_prepare'
> b'io_schedule'
> b'rq_qos_wait'
> b'wbt_wait'
> b'__rq_qos_throttle'
> b'blk_mq_make_request'
> b'generic_make_request'
> b'submit_bio'
> b'ext4_io_submit'
> b'ext4_bio_write_page'
> b'mpage_submit_page'
> b'mpage_process_page_bufs'
> b'mpage_prepare_extent_to_map'
> b'ext4_writepages'
> b'do_writepages'
> b'__writeback_single_inode'
> b'writeback_sb_inodes'
> b'__writeback_inodes_wb'
> b'wb_writeback'
> b'wb_workfn'
> b'process_one_work'
> b'worker_thread'
> b'kthread'
> b'ret_from_fork'
> 5763
>
> Thanks,
> Ming
>
Is there any update on this? Sorry if I am making noise, but I would
like to help to improve the kernel (or fix it) if I can help.
Otherwise, please let me know how to consider this case,
Thanks, and bye
Andrea