writeback: Tracing support V2
Subsystems (5)
cover writeback: Tracing support V2
Hi Jens,
This series is an update of the writeback tracing that I'd previously posted against mainline. This version is based on the block/for-2.6.36 branch.
The tracing provides visibility into the behaviour of the writeback path and is sufficient to understand questions such as what process is writing data, what process is blocking on congestion, etc. It also allows view the differences in behaviour for different sync modes and calling contexts.
This series is based on the block/for-2.6.36 branch.
Output (slighty trimmed) for a background flush of a clean bdi is as follows:
flush-8:0-[...]: wbc_writeback_start: bdi 8:0: towrt=1024 skip=0 mode=0 kupd=1 bgrd=0 reclm=0 cyclic=1 more=0 older=0xffff5d8e start=0x0 end=0x0 flush-8:0-[...]: wbc_writeback_written: bdi 8:0: towrt=1024 skip=0 mode=0 kupd=1 bgrd=0 reclm=0 cyclic=1 more=0 older=0xffff5d8e start=0x0 end=0x0 flush-8:0-[...]: writeback_pages_written: 0
Here we see that we are doing writeback for kupdate in cyclic mode with inodes that are older than 0xffff5d8e. The filesystem is clean, so there is nothing to write...
Output (slighty trimmed) for a sync(1) based flush of a clean bdi is as follows:
sync-[...]: wb_sched_queue: bdi 8:0: sb_dev 0:0 nr_pages=0 sync_mode=0 kupdate=0 range_cyclic=0 background=0
sync-[...]: wb_sched_task: bdi 8:0: sb_dev 0:0 nr_pages=0 sync_mode=0 kupdate=0 range_cyclic=0 background=0
flush-8:0-[...]: wb_sched_exec: bdi 8:0: sb_dev 0:0 nr_pages=0 sync_mode=0 kupdate=0 range_cyclic=0 background=0
flush-8:0-[...]: writeback_pages_written: 0
sync-[...]: wb_sched_queue: bdi 8:0: sb_dev 8:1 nr_pages=7712 sync_mode=0 kupdate=0 range_cyclic=0 background=0
sync-[...]: wb_sched_task: bdi 8:0: sb_dev 8:1 nr_pages=7712 sync_mode=0 kupdate=0 range_cyclic=0 background=0flush-8:0-[...]: wb_sched_exec: bdi 8:0: sb_dev 8:1 nr_pages=7712 sync_mode=0 kupdate=0 range_cyclic=0 background=0 flush-8:0-[...]: wbc_writeback_start: bdi 8:0: towrt=1024 skip=0 mode=0 kupd=0 bgrd=0 reclm=0 cyclic=0 more=0 older=0x0 start=0x0 end=0x7fffffffffffffff flush-8:0-[...]: wbc_writeback_written: bdi 8:0: towrt=1024 skip=0 mode=0 kupd=0 bgrd=0 reclm=0 cyclic=0 more=0 older=0x0 start=0x0 end=0x7fffffffffffffff flush-8:0-[...]: writeback_pages_written: 0
sync-[...]: wb_sched_queue: bdi 8:0: sb_dev 8:1 nr_pages=9223372036854775807 sync_mode=1 kupdate=0 range_cyclic=0 background=0
sync-[...]: wb_sched_task: bdi 8:0: sb_dev 8:1 nr_pages=9223372036854775807 sync_mode=1 kupdate=0 range_cyclic=0 background=0flush-8:0-[...]: wb_sched_exec: bdi 8:0: sb_dev 8:1 nr_pages=9223372036854775807 sync_mode=1 kupdate=0 range_cyclic=0 background=0 flush-8:0-[...]: wbc_writeback_start: bdi 8:0: wbc=ffff88011cb4bd20 towrt=1024 skip=0 mode=1 kupd=0 bgrd=0 reclm=0 cyclic=0 more=0 older=0x0 start=0x0 end=0x7fffffffffffffff flush-8:0-[...]: wbc_writeback_written: bdi 8:0: wbc=ffff88011cb4bd20 towrt=1024 skip=0 mode=1 kupd=0 bgrd=0 reclm=0 cyclic=0 more=0 older=0x0 start=0x0 end=0x7fffffffffffffff flush-8:0-[...]: writeback_pages_written: 0
What we can see here is that:
- sync queued an async flush to the entire bdi
- the bdi flusher thread wrote no pages (i.e. clean)
- sync has issued an async flush of superblock 8:1 for 7712 pages
- the bdi flush ran writeback on the superblock, wrote no pages
- sync queued a synchronous flush of the superblock
- the bdi flush ran writeback on the superblock, wrote no pages
---
Version 2:
- rewrite of initial patch from previous 2.6.34 based code to match new bdi scheduling code as part of rebasing onto the block/for-2.6.36 tree.
- removed work structure address from output as it was mostly redundant and took up lots of space in the output.
- removed writeback control structure address from output as it was mostly redundant and took up lots of space in the output.
PATCH 1/3 writeback: Initial tracing support
Trace queue/sched/exec parts of the writeback loop. This provides insight into when and why flusher threads are scheduled to run. e.g a sync invocation leaves traces like:
sync-[...]: wb_sched_queue: bdi 8:0: sb_dev 8:1 nr_pages=7712 sync_mode=0 kupdate=0 range_cyclic=0 background=0
sync-[...]: wb_sched_task: bdi 8:0: sb_dev 8:1 nr_pages=7712 sync_mode=0 kupdate=0 range_cyclic=0 background=0flush-8:0-[...]: wb_sched_exec: bdi 8:0: sb_dev 8:1 nr_pages=7712 sync_mode=0 kupdate=0 range_cyclic=0 background=0
This also lays the foundation for adding more writeback tracing to provide deeper insight into the whole writeback path.
The original tracing code is from Jens Axboe, though this version is a rewrite as a result of the code being traced changing significantly.
--- fs/fs-writeback.c | 43 ++++++++++++++---- include/trace/events/writeback.h | 93 ++++++++++++++++++++++++++++++++++++++ mm/backing-dev.c | 3 + 3 files changed, 130 insertions(+), 9 deletions(-) create mode 100644 include/trace/events/writeback.h
fs/fs-writeback.c +34 -9
@@ -26,15 +26,9 @@#include <linux/blkdev.h> #include <linux/backing-dev.h> #include <linux/buffer_head.h> +#include <linux/tracepoint.h> #include "internal.h" -#define inode_to_bdi (inode) ((inode)->i_mapping->backing_dev_info) - -/* -* We don't actually have pdflush, but this one is exported though /proc... -*/ -int nr_pdflush_threads; -/* * Passed into wb_writeback(), essentially a subset of writeback_control */
@@ -50,6 +44,21 @@ struct wb_writeback_work {struct completion *done;/* set if the caller waits */ }; +/* +* Include the creation of the trace points after defining the +* wb_writeback_work structure so that the definition remains local to this +* file. +*/ +#define CREATE_TRACE_POINTS +#include <trace/events/writeback.h> + +#define inode_to_bdi (inode) ((inode)->i_mapping->backing_dev_info) + +/* +* We don't actually have pdflush, but this one is exported though /proc... +*/ +int nr_pdflush_threads; +/** * writeback_in_progress - determine whether there is writeback in progress * @bdi: the device's backing_dev_info structure.
@@ -65,6 +74,8 @@ int writeback_in_progress(struct backing_dev_info *bdi)static void bdi_queue_work (struct backing_dev_info *bdi,struct wb_writeback_work *work) { +trace_wb_sched_queue (bdi, work); +spin_lock (&bdi->wb_lock);list_add_tail (&work->list, &bdi->work_list);spin_unlock (&bdi->wb_lock);
@@ -74,12 +85,16 @@ static void bdi_queue_work(struct backing_dev_info *bdi,* it gets created and wakes up, we'll run this work. */ if (unlikely (!bdi->wb.task)) { +trace_wb_sched_default (bdi, work);wake_up_process (default_backing_dev_info.wb.task); }else {struct bdi_writeback *wb = &bdi->wb; -if (wb->task) +if (wb->task) { +trace_wb_sched_task (bdi, work);wake_up_process (wb->task); + }else +trace_wb_sched_notask (bdi, work); } }
@@ -95,8 +110,10 @@ __bdi_start_writeback(struct backing_dev_info *bdi, long nr_pages,*/ work =kzalloc (sizeof (*work),GFP_ATOMIC );if (!work) { -if (bdi->wb.task) +if (bdi->wb.task) { +trace_wb_sched_nowork (bdi, work);wake_up_process (bdi->wb.task); + }return ; }
@@ -751,6 +768,8 @@ long wb_do_writeback(struct bdi_writeback *wb, int force_wait)if (force_wait) work->sync_mode =WB_SYNC_ALL ; +trace_wb_sched_exec (bdi, work); + wrote +=wb_writeback (wb, work);/*
@@ -805,9 +824,13 @@ int bdi_writeback_thread(void *data)smp_mb__after_clear_bit ();wake_up_bit (&bdi->state, BDI_pending); +trace_wb_thread_start (bdi); +while (!kthread_should_stop ()) { pages_written =wb_do_writeback (wb,0 ); +trace_writeback_pages_written (pages_written); +if (pages_written) last_active = jiffies;else if (wait_jiffies !=-1UL ) {
@@ -845,6 +868,8 @@ int bdi_writeback_thread(void *data)*/ if (!list_empty (&bdi->work_list))wb_do_writeback (wb,1 ); + +trace_wb_thread_stop (bdi);return 0 ; }
include/trace/events/writeback.h new file +93 -0
93 lines not on this page · raw message
mm/backing-dev.c +3 -0
@@ -10,6 +10,7 @@#include <linux/module.h> #include <linux/writeback.h> #include <linux/device.h> +#include <trace/events/writeback.h> static atomic_long_t bdi_seq =ATOMIC_LONG_INIT (0 );
@@ -518,6 +519,7 @@ int bdi_register(struct backing_dev_info *bdi, struct device *parent,bdi_debug_register (bdi,dev_name (dev));set_bit (BDI_registered, &bdi->state); +trace_wb_bdi_register (bdi); exit:return ret; }
@@ -578,6 +580,7 @@ static void bdi_prune_sb(struct backing_dev_info *bdi)void bdi_unregister (struct backing_dev_info *bdi) {if (bdi->dev) { +trace_wb_bdi_unregister (bdi);bdi_prune_sb (bdi);if (!bdi_cap_flush_forker (bdi))
Signature · 1 line
1.7.1
Re: [PATCH 1/3] writeback: Initial tracing support
fs/fs-writeback.c int writeback_in_progress(struct backing_dev_info *bdi) · line 77
Quoted 4 lines
static void bdi_queue_work(struct
backing_dev_info*bdi,fs/fs-writeback.c +1
-0struct wb_writeback_work *work) { +trace_wb_sched_queue (bdi, work);
Okay, I'm getting more nitpicky with every repost, but the naming here seems odd.
First why the unreadle wb prefix instead of a proper writeback? And the sched in here seems rather useless, I'd just call it
trace_writeback_queue
fs/fs-writeback.c static void bdi_queue_work(struct backing_dev_info *bdi, · line 88
Quoted 5 lines
fs/fs-writeback.c +1
-0@@ -74,12 +85,16 @@ static void bdi_queue_work(struct backing_dev_info *bdi,* it gets created and wakes up, we'll run this work. */ if (unlikely (!bdi->wb.task)) { +trace_wb_sched_default (bdi, work);
trace_writeback_no_thread
fs/fs-writeback.c static void bdi_queue_work(struct backing_dev_info *bdi, · line 94
Quoted 7 lines
fs/fs-writeback.c +2
-1wake_up_process (default_backing_dev_info.wb.task); }else {struct bdi_writeback *wb = &bdi->wb; -if (wb->task) +if (wb->task) { +trace_wb_sched_task (bdi, work);
trace_writeback_wake
then again I don't think we actually need this, if we got the trace_writeback_queue event, and no trace_writeback_no_thread it's implicit that we got here.
fs/fs-writeback.c static void bdi_queue_work(struct backing_dev_info *bdi, · line 97
Quoted 3 lines
fs/fs-writeback.c +2
-0wake_up_process (wb->task); + }else +trace_wb_sched_notask (bdi, work);
This case can't actually happen as we checked for the task a few lines above. Might be worth to throw in preparation patch in your series to something like:
if (unlikely(!bdi->wb.task)) {
wake_up_process(default_backing_dev_info.wb.task);- } else {
- struct bdi_writeback *wb = &bdi->wb;
-
- if (wb->task)
- wake_up_process(wb->task);
- }
+ return;
+ }
+
+ wake_up_process(bdi->wb.task);
fs/fs-writeback.c __bdi_start_writeback(struct backing_dev_info *bdi, long nr_pages, · line 114
Quoted 10 lines
fs/fs-writeback.c +2
-1} }@@ -95,8 +110,10 @@ __bdi_start_writeback(struct backing_dev_info *bdi, long nr_pages,*/ work =kzalloc (sizeof (*work),GFP_ATOMIC );if (!work) { -if (bdi->wb.task) +if (bdi->wb.task) { +trace_wb_sched_nowork (bdi, work);
trace_writeback_nowork
include/trace/events/writeback.h line 32
Quoted 9 lines
include/trace/events/writeback.h new file +9
-0+TP_fast_assign ( + strncpy(__entry->name, dev_name(bdi->dev), 32); + __entry->nr_pages = work ? work->nr_pages :0 ; + __entry->sb_dev = work ? work->sb ? work->sb->s_dev :0 :0 ; + __entry->sync_mode = work ? work->sync_mode :-1 ; + __entry->for_kupdate = work ? work->for_kupdate :-1 ; + __entry->range_cyclic = work ? work->range_cyclic :-1 ; + __entry->for_background = work ? work->for_background :-1 ; + ),
If you had a separate class for those tracepoints that do not have a work item the code would be a lot simpler.
include/trace/events/writeback.h line 78
Quoted 12 lines
include/trace/events/writeback.h new file +12
-0+DECLARE_EVENT_CLASS (wb_thread_class, + TP_PROTO(struct backing_dev_info *bdi), +TP_ARGS (bdi), +TP_STRUCT__entry ( +__array (char, name,32 ) + ), +TP_fast_assign ( + strncpy(__entry->name, dev_name(bdi->dev), 32); + ), +TP_printk ("bdi %s" , + __entry->name + )
In fact you already have one.
Re: [PATCH 1/3] writeback: Initial tracing support
Quoted 8 lines · Christoph Hellwig
fs/fs-writeback.c int writeback_in_progress(struct backing_dev_info *bdi) · line 77
Quoted 4 lines
static void bdi_queue_work(struct
backing_dev_info*bdi,fs/fs-writeback.c +1
-0struct wb_writeback_work *work) { +trace_wb_sched_queue (bdi, work);Okay, I'm getting more nitpicky with every repost, but the naming here seems odd.
Quoted 4 lines
First why the unreadle wb prefix instead of a proper writeback? And the sched in here seems rather useless, I'd just call it
trace_writeback_queue
Done.
Quoted 19 lines
fs/fs-writeback.c static void bdi_queue_work(struct backing_dev_info *bdi, · line 88
Quoted 6 lines
fs/fs-writeback.c +1
-0@@ -74,12 +85,16 @@ static void bdi_queue_work(struct backing_dev_info *bdi,* it gets created and wakes up, we'll run this work. */ if (unlikely (!bdi->wb.task)) { +trace_wb_sched_default (bdi, work);
trace_writeback_no_threadfs/fs-writeback.c static void bdi_queue_work(struct backing_dev_info *bdi, · line 94
Quoted 7 lines
fs/fs-writeback.c +2
-1wake_up_process (default_backing_dev_info.wb.task); }else {struct bdi_writeback *wb = &bdi->wb; -if (wb->task) +if (wb->task) { +trace_wb_sched_task (bdi, work);
trace_writeback_wake
Quoted 3 lines
then again I don't think we actually need this, if we got the
trace_writeback_queueevent, and notrace_writeback_no_threadit's implicit that we got here.
OK, fixed.
Quoted 6 lines
fs/fs-writeback.c static void bdi_queue_work(struct backing_dev_info *bdi, · line 97
Quoted 3 lines
fs/fs-writeback.c +2
-0wake_up_process (wb->task); + }else +trace_wb_sched_notask (bdi, work);This case can't actually happen as we checked for the task a few lines above.
Right, my bad.
Quoted 17 lines
Might be worth to throw in preparation patch in your series to something like:
if (unlikely(!bdi->wb.task)) { wake_up_process(default_backing_dev_info.wb.task);(quoted diff) +4
-6- } else { - struct bdi_writeback *wb = &bdi->wb; - - if (wb->task) - wake_up_process(wb->task); - } + return; + } + + wake_up_process(bdi->wb.task);
Quoted 2 lines
Review static void bdi_queue_work(struct backing_dev_info *bdi, · line 99
Quoted 2 lines
(quoted diff) +0
-0} }
Perhaps. making the above changes means it's not necessary...
Quoted 11 lines
fs/fs-writeback.c __bdi_start_writeback(struct backing_dev_info *bdi, long nr_pages, · line 114
Quoted 8 lines
fs/fs-writeback.c +2
-1@@ -95,8 +110,10 @@ __bdi_start_writeback(struct backing_dev_info *bdi, long nr_pages,*/ work =kzalloc (sizeof (*work),GFP_ATOMIC );if (!work) { -if (bdi->wb.task) +if (bdi->wb.task) { +trace_wb_sched_nowork (bdi, work);
trace_writeback_nowork
Quoted 12 lines
include/trace/events/writeback.h line 32
Quoted 9 lines
include/trace/events/writeback.h new file +9
-0+TP_fast_assign ( + strncpy(__entry->name, dev_name(bdi->dev), 32); + __entry->nr_pages = work ? work->nr_pages :0 ; + __entry->sb_dev = work ? work->sb ? work->sb->s_dev :0 :0 ; + __entry->sync_mode = work ? work->sync_mode :-1 ; + __entry->for_kupdate = work ? work->for_kupdate :-1 ; + __entry->range_cyclic = work ? work->range_cyclic :-1 ; + __entry->for_background = work ? work->for_background :-1 ; + ),If you had a separate class for those tracepoints that do not have a work item the code would be a lot simpler.
Yup, fixed.
I'll post a new version in a short while.
Cheers,
Dave.
Signature · 2 lines
Dave Chinner [email protected]
PATCH 2/3 writeback: Add tracing to balance_dirty_pages
In reply to Dave ChinnerFrom: Dave Chinner <[email protected]>
Tracing high level background writeback events is good, but it doesn't give the entire picture. Add visibility into write throttling to catch IO dispatched by foreground throttling of processing dirtying lots of pages.
--- fs/fs-writeback.c | 5 +++ include/trace/events/writeback.h | 69 ++++++++++++++++++++++++++++++++++++++ mm/page-writeback.c | 4 ++ 3 files changed, 78 insertions(+), 0 deletions(-)
fs/fs-writeback.c +5 -0
@@ -659,10 +659,14 @@ static long wb_writeback(struct bdi_writeback *wb, wbc.more_io =0 ; wbc.nr_to_write =MAX_WRITEBACK_PAGES ; wbc.pages_skipped =0 ; + +trace_wbc_writeback_start (&wbc, wb->bdi);if (work->sb)__writeback_inodes_sb (work->sb, wb, &wbc);else writeback_inodes_wb (wb, &wbc); +trace_wbc_writeback_written (&wbc, wb->bdi); + work->nr_pages -=MAX_WRITEBACK_PAGES - wbc.nr_to_write; wrote +=MAX_WRITEBACK_PAGES - wbc.nr_to_write;
@@ -690,6 +694,7 @@ static long wb_writeback(struct bdi_writeback *wb,if (!list_empty (&wb->b_more_io)) { inode =list_entry (wb->b_more_io.prev, struct inode, i_list); +trace_wbc_writeback_wait (&wbc, wb->bdi);inode_wait_for_writeback (inode); }spin_unlock (&inode_lock);
include/trace/events/writeback.h +69 -0
75 lines not on this page · raw message
mm/page-writeback.c +4 -0
@@ -34,6 +34,7 @@#include <linux/syscalls.h> #include <linux/buffer_head.h> #include <linux/pagevec.h> +#include <trace/events/writeback.h> /* * After a CPU has dirtied this many pages, balance_dirty_pages_ratelimited
@@ -535,11 +536,13 @@ static void balance_dirty_pages(struct address_space *mapping,* threshold otherwise wait until the disk writes catch * up. */ +trace_wbc_balance_dirty_start (&wbc, bdi);if (bdi_nr_reclaimable > bdi_thresh) {writeback_inodes_wb (&bdi->wb, &wbc); pages_written += write_chunk - wbc.nr_to_write;get_dirty_limits (&background_thresh, &dirty_thresh, &bdi_thresh, bdi); +trace_wbc_balance_dirty_written (&wbc, bdi); }/*
@@ -565,6 +568,7 @@ static void balance_dirty_pages(struct address_space *mapping,if (pages_written >= write_chunk)break ;/* We've done our duty */ +trace_wbc_balance_dirty_wait (&wbc, bdi);__set_current_state (TASK_INTERRUPTIBLE );io_schedule_timeout (pause);
Signature · 1 line
1.7.1
Re: [PATCH 2/3] writeback: Add tracing to balance_dirty_pages
include/trace/events/writeback.h DEFINE_WB_THREAD_EVENT(wb_bdi_unregister); · line 116
Quoted 8 lines
include/trace/events/writeback.h +8
-0+ +TP_fast_assign ( + char *__no_bdi = "(no bdi)"; + +if (bdi) +strncpy (__entry->name,dev_name (bdi->dev),32 ); +else +strncpy (__entry->name, __no_bdi,32 );
I can't see a caller that doesn't have a bdi.
Re: [PATCH 2/3] writeback: Add tracing to balance_dirty_pages
Quoted 10 lines · Christoph Hellwig
include/trace/events/writeback.h DEFINE_WB_THREAD_EVENT(wb_bdi_unregister); · line 116
Quoted 8 lines
include/trace/events/writeback.h +8
-0+ +TP_fast_assign ( + char *__no_bdi = "(no bdi)"; + +if (bdi) +strncpy (__entry->name,dev_name (bdi->dev),32 ); +else +strncpy (__entry->name, __no_bdi,32 );I can't see a caller that doesn't have a bdi.
True. I think that was left over from the previous version where the bdi could be null. I'll fix it up.
Cheers,
Dave.
Signature · 2 lines
Dave Chinner [email protected]
PATCH 3/3 writeback: Add tracing to write_cache_pages
In reply to Dave ChinnerFrom: Dave Chinner <[email protected]>
Add a trace event to the ->writepage loop in write_cache_pages to give visibility into how the ->writepage call is changing variables within the writeback control structure. Of most interest is how wbc->nr_to_write changes from call to call, especially with filesystems that write multiple pages in ->writepage.
--- include/trace/events/writeback.h | 1 + mm/page-writeback.c | 1 + 2 files changed, 2 insertions(+), 0 deletions(-)
include/trace/events/writeback.h +1 -0
@@ -155,6 +155,7 @@ DEFINE_WBC_EVENT(wbc_writeback_wait);DEFINE_WBC_EVENT (wbc_balance_dirty_start);DEFINE_WBC_EVENT (wbc_balance_dirty_written);DEFINE_WBC_EVENT (wbc_balance_dirty_wait); +DEFINE_WBC_EVENT (wbc_writepage);#endif /* _TRACE_WRITEBACK_H */
mm/page-writeback.c +1 -0
@@ -933,6 +933,7 @@ continue_unlock:if (!clear_page_dirty_for_io (page)) goto continue_unlock; +trace_wbc_writepage (wbc, mapping->backing_dev_info); ret = (*writepage)(page, wbc, data);if (unlikely (ret)) {if (ret ==AOP_WRITEPAGE_ACTIVATE ) {
Signature · 1 line
1.7.1