writeback: trace event balance_dirty_pages

Useful for analyzing the dynamics of the throttling algorithms and debugging user reported problems. Signed-off-by: Wu Fengguang <fengguang.wu@intel.com>

writeback: trace event balance_dirty_pages
Useful for analyzing the dynamics of the throttling algorithms and debugging user reported problems. Signed-off-by: Wu Fengguang <fengguang.wu@intel.com>
Wu Fengguang
1 parent b48c104d22
Showing 2 changed files with 95 additions and 0 deletions Side-by-side Diff
include/trace/events/writeback.h
mm/page-writeback.c
@@ -271,6 +271,79 @@
 	)
 );
  
+TRACE_EVENT(balance_dirty_pages,
+
+	TP_PROTO(struct backing_dev_info *bdi,
+		 unsigned long thresh,
+		 unsigned long bg_thresh,
+		 unsigned long dirty,
+		 unsigned long bdi_thresh,
+		 unsigned long bdi_dirty,
+		 unsigned long dirty_ratelimit,
+		 unsigned long task_ratelimit,
+		 unsigned long dirtied,
+		 long pause,
+		 unsigned long start_time),
+
+	TP_ARGS(bdi, thresh, bg_thresh, dirty, bdi_thresh, bdi_dirty,
+		dirty_ratelimit, task_ratelimit,
+		dirtied, pause, start_time),
+
+	TP_STRUCT__entry(
+		__array(	 char,	bdi, 32)
+		__field(unsigned long,	limit)
+		__field(unsigned long,	setpoint)
+		__field(unsigned long,	dirty)
+		__field(unsigned long,	bdi_setpoint)
+		__field(unsigned long,	bdi_dirty)
+		__field(unsigned long,	dirty_ratelimit)
+		__field(unsigned long,	task_ratelimit)
+		__field(unsigned int,	dirtied)
+		__field(unsigned int,	dirtied_pause)
+		__field(unsigned long,	paused)
+		__field(	 long,	pause)
+	),
+
+	TP_fast_assign(
+		unsigned long freerun = (thresh + bg_thresh) / 2;
+		strlcpy(__entry->bdi, dev_name(bdi->dev), 32);
+
+		__entry->limit		= global_dirty_limit;
+		__entry->setpoint	= (global_dirty_limit + freerun) / 2;
+		__entry->dirty		= dirty;
+		__entry->bdi_setpoint	= __entry->setpoint *
+						bdi_thresh / (thresh + 1);
+		__entry->bdi_dirty	= bdi_dirty;
+		__entry->dirty_ratelimit = KBps(dirty_ratelimit);
+		__entry->task_ratelimit	= KBps(task_ratelimit);
+		__entry->dirtied	= dirtied;
+		__entry->dirtied_pause	= current->nr_dirtied_pause;
+		__entry->pause		= pause * 1000 / HZ;
+		__entry->paused		= (jiffies - start_time) * 1000 / HZ;
+	),
+
+
+	TP_printk("bdi %s: "
+		  "limit=%lu setpoint=%lu dirty=%lu "
+		  "bdi_setpoint=%lu bdi_dirty=%lu "
+		  "dirty_ratelimit=%lu task_ratelimit=%lu "
+		  "dirtied=%u dirtied_pause=%u "
+		  "paused=%lu pause=%ld",
+		  __entry->bdi,
+		  __entry->limit,
+		  __entry->setpoint,
+		  __entry->dirty,
+		  __entry->bdi_setpoint,
+		  __entry->bdi_dirty,
+		  __entry->dirty_ratelimit,
+		  __entry->task_ratelimit,
+		  __entry->dirtied,
+		  __entry->dirtied_pause,
+		  __entry->paused,	/* ms */
+		  __entry->pause	/* ms */
+	  )
+);
+
 DECLARE_EVENT_CLASS(writeback_congest_waited_template,
  
 	TP_PROTO(unsigned int usec_timeout, unsigned int usec_delayed),
@@ -1103,12 +1103,34 @@
 					pos_ratio >> RATELIMIT_CALC_SHIFT;
 		pause = (HZ * pages_dirtied) / (task_ratelimit | 1);
 		if (unlikely(pause <= 0)) {
+			trace_balance_dirty_pages(bdi,
+						  dirty_thresh,
+						  background_thresh,
+						  nr_dirty,
+						  bdi_thresh,
+						  bdi_dirty,
+						  dirty_ratelimit,
+						  task_ratelimit,
+						  pages_dirtied,
+						  pause,
+						  start_time);
 			pause = 1; /* avoid resetting nr_dirtied_pause below */
 			break;
 		}
 		pause = min(pause, max_pause);
  
 pause:
+		trace_balance_dirty_pages(bdi,
+					  dirty_thresh,
+					  background_thresh,
+					  nr_dirty,
+					  bdi_thresh,
+					  bdi_dirty,
+					  dirty_ratelimit,
+					  task_ratelimit,
+					  pages_dirtied,
+					  pause,
+					  start_time);
 		__set_current_state(TASK_UNINTERRUPTIBLE);
 		io_schedule_timeout(pause);
...	...	@@ -271,6 +271,79 @@
271	271	)
272	272	);
273	273
	274	+TRACE_EVENT(balance_dirty_pages,
	275	+
	276	+ TP_PROTO(struct backing_dev_info *bdi,
	277	+ unsigned long thresh,
	278	+ unsigned long bg_thresh,
	279	+ unsigned long dirty,
	280	+ unsigned long bdi_thresh,
	281	+ unsigned long bdi_dirty,
	282	+ unsigned long dirty_ratelimit,
	283	+ unsigned long task_ratelimit,
	284	+ unsigned long dirtied,
	285	+ long pause,
	286	+ unsigned long start_time),
	287	+
	288	+ TP_ARGS(bdi, thresh, bg_thresh, dirty, bdi_thresh, bdi_dirty,
	289	+ dirty_ratelimit, task_ratelimit,
	290	+ dirtied, pause, start_time),
	291	+
	292	+ TP_STRUCT__entry(
	293	+ __array( char, bdi, 32)
	294	+ __field(unsigned long, limit)
	295	+ __field(unsigned long, setpoint)
	296	+ __field(unsigned long, dirty)
	297	+ __field(unsigned long, bdi_setpoint)
	298	+ __field(unsigned long, bdi_dirty)
	299	+ __field(unsigned long, dirty_ratelimit)
	300	+ __field(unsigned long, task_ratelimit)
	301	+ __field(unsigned int, dirtied)
	302	+ __field(unsigned int, dirtied_pause)
	303	+ __field(unsigned long, paused)
	304	+ __field( long, pause)
	305	+ ),
	306	+
	307	+ TP_fast_assign(
	308	+ unsigned long freerun = (thresh + bg_thresh) / 2;
	309	+ strlcpy(__entry->bdi, dev_name(bdi->dev), 32);
	310	+
	311	+ __entry->limit = global_dirty_limit;
	312	+ __entry->setpoint = (global_dirty_limit + freerun) / 2;
	313	+ __entry->dirty = dirty;
	314	+ __entry->bdi_setpoint = __entry->setpoint *
	315	+ bdi_thresh / (thresh + 1);
	316	+ __entry->bdi_dirty = bdi_dirty;
	317	+ __entry->dirty_ratelimit = KBps(dirty_ratelimit);
	318	+ __entry->task_ratelimit = KBps(task_ratelimit);
	319	+ __entry->dirtied = dirtied;
	320	+ __entry->dirtied_pause = current->nr_dirtied_pause;
	321	+ __entry->pause = pause * 1000 / HZ;
	322	+ __entry->paused = (jiffies - start_time) * 1000 / HZ;
	323	+ ),
	324	+
	325	+
	326	+ TP_printk("bdi %s: "
	327	+ "limit=%lu setpoint=%lu dirty=%lu "
	328	+ "bdi_setpoint=%lu bdi_dirty=%lu "
	329	+ "dirty_ratelimit=%lu task_ratelimit=%lu "
	330	+ "dirtied=%u dirtied_pause=%u "
	331	+ "paused=%lu pause=%ld",
	332	+ __entry->bdi,
	333	+ __entry->limit,
	334	+ __entry->setpoint,
	335	+ __entry->dirty,
	336	+ __entry->bdi_setpoint,
	337	+ __entry->bdi_dirty,
	338	+ __entry->dirty_ratelimit,
	339	+ __entry->task_ratelimit,
	340	+ __entry->dirtied,
	341	+ __entry->dirtied_pause,
	342	+ __entry->paused, /* ms */
	343	+ __entry->pause /* ms */
	344	+ )
	345	+);
	346	+
274	347	DECLARE_EVENT_CLASS(writeback_congest_waited_template,
275	348
276	349	TP_PROTO(unsigned int usec_timeout, unsigned int usec_delayed),
...	...	@@ -1103,12 +1103,34 @@
1103	1103	pos_ratio >> RATELIMIT_CALC_SHIFT;
1104	1104	pause = (HZ * pages_dirtied) / (task_ratelimit \| 1);
1105	1105	if (unlikely(pause <= 0)) {
	1106	+ trace_balance_dirty_pages(bdi,
	1107	+ dirty_thresh,
	1108	+ background_thresh,
	1109	+ nr_dirty,
	1110	+ bdi_thresh,
	1111	+ bdi_dirty,
	1112	+ dirty_ratelimit,
	1113	+ task_ratelimit,
	1114	+ pages_dirtied,
	1115	+ pause,
	1116	+ start_time);
1106	1117	pause = 1; /* avoid resetting nr_dirtied_pause below */
1107	1118	break;
1108	1119	}
1109	1120	pause = min(pause, max_pause);
1110	1121
1111	1122	pause:
	1123	+ trace_balance_dirty_pages(bdi,
	1124	+ dirty_thresh,
	1125	+ background_thresh,
	1126	+ nr_dirty,
	1127	+ bdi_thresh,
	1128	+ bdi_dirty,
	1129	+ dirty_ratelimit,
	1130	+ task_ratelimit,
	1131	+ pages_dirtied,
	1132	+ pause,
	1133	+ start_time);
1112	1134	__set_current_state(TASK_UNINTERRUPTIBLE);
1113	1135	io_schedule_timeout(pause);
1114	1136