writeback: account for time spent congestion_waited

There is strong evidence to indicate a lot of time is being spent in
congestion_wait(), some of it unnecessarily.  This patch adds a tracepoint
for congestion_wait to record when congestion_wait() was called, how long
the timeout was for and how long it actually slept.

Signed-off-by: Mel Gorman <mel@csn.ul.ie>
Reviewed-by: Minchan Kim <minchan.kim@gmail.com>
Reviewed-by: Johannes Weiner <hannes@cmpxchg.org>
Cc: Wu Fengguang <fengguang.wu@intel.com>
Cc: KAMEZAWA Hiroyuki <kamezawa.hiroyu@jp.fujitsu.com>
Cc: KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>
Cc: Rik van Riel <riel@redhat.com>
Signed-off-by: Andrew Morton <akpm@linux-foundation.org>
Signed-off-by: Linus Torvalds <torvalds@linux-foundation.org>

diff --git a/include/trace/events/writeback.h b/include/trace/events/writeback.h
index 0bb01ab2e984e2481e3d8d05d8c90ed4eec8db6e..d2b2654606ecee415d4cd3cfab9b53259379bd00 100644 (file)
--- a/include/trace/events/writeback.h
+++ b/include/trace/events/writeback.h
@@ -151,6 +151,34 @@ DEFINE_WBC_EVENT(wbc_balance_dirty_written);
 DEFINE_WBC_EVENT(wbc_balance_dirty_wait);
 DEFINE_WBC_EVENT(wbc_writepage);
 
+DECLARE_EVENT_CLASS(writeback_congest_waited_template,
+
+       TP_PROTO(unsigned int usec_timeout, unsigned int usec_delayed),
+
+       TP_ARGS(usec_timeout, usec_delayed),
+
+       TP_STRUCT__entry(
+               __field(        unsigned int,   usec_timeout    )
+               __field(        unsigned int,   usec_delayed    )
+       ),
+
+       TP_fast_assign(
+               __entry->usec_timeout   = usec_timeout;
+               __entry->usec_delayed   = usec_delayed;
+       ),
+
+       TP_printk("usec_timeout=%u usec_delayed=%u",
+                       __entry->usec_timeout,
+                       __entry->usec_delayed)
+);
+
+DEFINE_EVENT(writeback_congest_waited_template, writeback_congestion_wait,
+
+       TP_PROTO(unsigned int usec_timeout, unsigned int usec_delayed),
+
+       TP_ARGS(usec_timeout, usec_delayed)
+);
+
 #endif /* _TRACE_WRITEBACK_H */
 
 /* This part must be outside protection */

diff --git a/mm/backing-dev.c b/mm/backing-dev.c
index 65d420499a615bf68a3be8313c3b0d8b1b330178..55627306abe0042968ab1bf70b17f9cd1a74fdec 100644 (file)
--- a/mm/backing-dev.c
+++ b/mm/backing-dev.c
@@ -764,12 +764,17 @@ EXPORT_SYMBOL(set_bdi_congested);
 long congestion_wait(int sync, long timeout)
 {
        long ret;
+       unsigned long start = jiffies;
        DEFINE_WAIT(wait);
        wait_queue_head_t *wqh = &congestion_wqh[sync];
 
        prepare_to_wait(wqh, &wait, TASK_UNINTERRUPTIBLE);
        ret = io_schedule_timeout(timeout);
        finish_wait(wqh, &wait);
+
+       trace_writeback_congestion_wait(jiffies_to_usecs(timeout),
+                                       jiffies_to_usecs(jiffies - start));
+
        return ret;
 }
 EXPORT_SYMBOL(congestion_wait);