[PATCH 0/4] delayacct: save max CPU/IO/SWAP/RECLAIM delays

[PATCH 0/4] delayacct: save max CPU/IO/SWAP/RECLAIM delays

[Satoru Moriya]

In the latency sensitive systems, we usually focus on the worst latency.
And so, it is useful to save max delays into the per-task delay
accounting functionality.

Example output:
(on 100 concurrent dd reading sparse files w/ 1 dd writing a file)

CPU             count     real total  virtual total    delay total      delay_max  delay average
                  222       45993008       74603882        7637295        3691858          0.034ms
IO              count    delay total      delay max  delay average
                    2       21812073       12728672             10ms
SWAP            count    delay total      delay max  delay average
                    0              0              0              0ms
RECLAIM         count    delay total      delay_max  delay average
                    2         348488         211985              0ms

Any comments are welcome.


Satoru Moriya (4):
  sched: add members to struct sched_info to save maximum
  delayacct: add members to struct task_delay_info to save max delays
  delayacct: update taskstats to save max delays
  getdelays: show max CPU/IO/SWAP/RECLAIM delays

 Documentation/accounting/getdelays.c          |   28 ++++++++++++++----------
 Documentation/accounting/taskstats-struct.txt |    9 ++++++++
 include/linux/sched.h                         |    5 ++++
 include/linux/taskstats.h                     |    8 ++++++-
 kernel/delayacct.c                            |   25 +++++++++++++++++----
 kernel/sched_stats.h                          |    5 ++++
 6 files changed, 62 insertions(+), 18 deletions(-)

-- 
1.7.6.4

[PATCH 1/4] sched: add members to struct sched_info to save maximum

[Satoru Moriya]

This patch adds members to struct sched_info and save max delays
into it.

Signed-off-by: Satoru Moriya <satoru.moriya@hds.com>
---
 include/linux/sched.h |    2 ++
 kernel/sched_stats.h  |    5 +++++
 2 files changed, 7 insertions(+), 0 deletions(-)

diff --git a/include/linux/sched.h b/include/linux/sched.h
index 1c4f3e9..1665e2c 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -736,6 +736,8 @@ struct sched_info {
 	/* cumulative counters */
 	unsigned long pcount;	      /* # of times run on this cpu */
 	unsigned long long run_delay; /* time spent waiting on a runqueue */
+	unsigned long long max_delay; /* max run_delay */
+	unsigned long long prev_cpu_delay; /* time spent waiting on prev cpus' runqueue */
 
 	/* timestamps */
 	unsigned long long last_arrival,/* when we last ran on a cpu */
diff --git a/kernel/sched_stats.h b/kernel/sched_stats.h
index 87f9e36..48e9db9 100644
--- a/kernel/sched_stats.h
+++ b/kernel/sched_stats.h
@@ -171,6 +171,7 @@ static inline void sched_info_dequeued(struct task_struct *t)
 			delta = now - t->sched_info.last_queued;
 	sched_info_reset_dequeued(t);
 	t->sched_info.run_delay += delta;
+	t->sched_info.prev_cpu_delay += delta;
 
 	rq_sched_info_dequeued(task_rq(t), delta);
 }
@@ -190,6 +191,10 @@ static void sched_info_arrive(struct task_struct *t)
 	t->sched_info.run_delay += delta;
 	t->sched_info.last_arrival = now;
 	t->sched_info.pcount++;
+	t->sched_info.prev_cpu_delay += delta;
+	if (t->sched_info.max_delay < t->sched_info.prev_cpu_delay)
+		t->sched_info.max_delay = t->sched_info.prev_cpu_delay;
+	t->sched_info.prev_cpu_delay = 0;
 
 	rq_sched_info_arrive(task_rq(t), delta);
 }
-- 
1.7.6.4

[PATCH 2/4] delayacct: add members to struct task_delay_info to save max delays

[Satoru Moriya]

This patch adds members to struct task_delay_info and a parameter to
delayacct_end() and saves maximum values for IO/SWAP/RECLAIM delays.

Signed-off-by: Satoru Moriya <satoru.moriya@hds.com>
---
 include/linux/sched.h |    3 +++
 kernel/delayacct.c    |   13 +++++++++----
 2 files changed, 12 insertions(+), 4 deletions(-)

diff --git a/include/linux/sched.h b/include/linux/sched.h
index 1665e2c..edd8ad2 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -768,6 +768,8 @@ struct task_delay_info {
 	struct timespec blkio_start, blkio_end;	/* Shared by blkio, swapin */
 	u64 blkio_delay;	/* wait for sync block io completion */
 	u64 swapin_delay;	/* wait for swapin block io completion */
+	u64 blkio_delay_max;    /* max wait for sync block io completion */
+	u64 swapin_delay_max;   /* max wait for swapin block io completion */
 	u32 blkio_count;	/* total count of the number of sync block */
 				/* io operations performed */
 	u32 swapin_count;	/* total count of the number of swapin block */
@@ -775,6 +777,7 @@ struct task_delay_info {
 
 	struct timespec freepages_start, freepages_end;
 	u64 freepages_delay;	/* wait for memory reclaim */
+	u64 freepages_delay_max;/* max wait for memory reclaim */
 	u32 freepages_count;	/* total count of memory reclaim */
 };
 #endif	/* CONFIG_TASK_DELAY_ACCT */
diff --git a/kernel/delayacct.c b/kernel/delayacct.c
index 418b3f7..33d090b 100644
--- a/kernel/delayacct.c
+++ b/kernel/delayacct.c
@@ -61,7 +61,7 @@ static inline void delayacct_start(struct timespec *start)
  */
 
 static void delayacct_end(struct timespec *start, struct timespec *end,
-				u64 *total, u32 *count)
+				u64 *total, u32 *count, u64 *max)
 {
 	struct timespec ts;
 	s64 ns;
@@ -76,6 +76,8 @@ static void delayacct_end(struct timespec *start, struct timespec *end,
 	spin_lock_irqsave(&current->delays->lock, flags);
 	*total += ns;
 	(*count)++;
+	if (*max < ns)
+		*max = ns;
 	spin_unlock_irqrestore(&current->delays->lock, flags);
 }
 
@@ -91,12 +93,14 @@ void __delayacct_blkio_end(void)
 		delayacct_end(&current->delays->blkio_start,
 			&current->delays->blkio_end,
 			&current->delays->swapin_delay,
-			&current->delays->swapin_count);
+			&current->delays->swapin_count,
+			&current->delays->swapin_delay_max);
 	else	/* Other block I/O */
 		delayacct_end(&current->delays->blkio_start,
 			&current->delays->blkio_end,
 			&current->delays->blkio_delay,
-			&current->delays->blkio_count);
+			&current->delays->blkio_count,
+			&current->delays->blkio_delay_max);
 }
 
 int __delayacct_add_tsk(struct taskstats *d, struct task_struct *tsk)
@@ -181,6 +185,7 @@ void __delayacct_freepages_end(void)
 	delayacct_end(&current->delays->freepages_start,
 			&current->delays->freepages_end,
 			&current->delays->freepages_delay,
-			&current->delays->freepages_count);
+			&current->delays->freepages_count,
+			&current->delays->freepages_delay_max);
 }
 
-- 
1.7.6.4

[PATCH 3/4] delayacct: update taskstats to save max delays

[Satoru Moriya]

This patch adds memberes to struct taskstats to save maximum
CPU/IO/SWAP/RECLAIM delays and saves them in __delayacct_and_tsk().

Signed-off-by: Satoru Moriya <satoru.moriya@hds.com>
---
 Documentation/accounting/taskstats-struct.txt |    9 +++++++++
 include/linux/taskstats.h                     |    8 +++++++-
 kernel/delayacct.c                            |   12 +++++++++++-
 3 files changed, 27 insertions(+), 2 deletions(-)

diff --git a/Documentation/accounting/taskstats-struct.txt b/Documentation/accounting/taskstats-struct.txt
index e7512c0..f7c0fa6 100644
--- a/Documentation/accounting/taskstats-struct.txt
+++ b/Documentation/accounting/taskstats-struct.txt
@@ -28,6 +28,8 @@ There are three different groups of fields in the struct taskstats:
 
 6) Extended delay accounting fields for memory reclaim
 
+7) Extended delay accounting fields for maximum delay
+
 Future extension should add fields to the end of the taskstats struct, and
 should not change the relative position of each field within the struct.
 
@@ -177,4 +179,11 @@ struct taskstats {
 	/* Delay waiting for memory reclaim */
 	__u64	freepages_count;
 	__u64	freepages_delay_total;
+
+7) Extended delay accounting fields for maximum delay
+        /* Max value for each delay */
+        __u64   cpu_delay_max;
+        __u64   blkio_delay_max;
+        __u64   swapin_delay_max;
+        __u64   freepages_delay_max;
 }
diff --git a/include/linux/taskstats.h b/include/linux/taskstats.h
index 2466e55..1a775fb 100644
--- a/include/linux/taskstats.h
+++ b/include/linux/taskstats.h
@@ -33,7 +33,7 @@
  */
 
 
-#define TASKSTATS_VERSION	8
+#define TASKSTATS_VERSION	9
 #define TS_COMM_LEN		32	/* should be >= TASK_COMM_LEN
 					 * in linux/sched.h */
 
@@ -163,6 +163,12 @@ struct taskstats {
 	/* Delay waiting for memory reclaim */
 	__u64	freepages_count;
 	__u64	freepages_delay_total;
+
+	/* Max value for each delay */
+	__u64   cpu_delay_max;
+	__u64   blkio_delay_max;
+	__u64   swapin_delay_max;
+	__u64   freepages_delay_max;
 };
 
 
diff --git a/kernel/delayacct.c b/kernel/delayacct.c
index 33d090b..ad0fdb5 100644
--- a/kernel/delayacct.c
+++ b/kernel/delayacct.c
@@ -107,7 +107,7 @@ int __delayacct_add_tsk(struct taskstats *d, struct task_struct *tsk)
 {
 	s64 tmp;
 	unsigned long t1;
-	unsigned long long t2, t3;
+	unsigned long long t2, t3, t4;
 	unsigned long flags;
 	struct timespec ts;
 
@@ -135,6 +135,7 @@ int __delayacct_add_tsk(struct taskstats *d, struct task_struct *tsk)
 	t1 = tsk->sched_info.pcount;
 	t2 = tsk->sched_info.run_delay;
 	t3 = tsk->se.sum_exec_runtime;
+	t4 = tsk->sched_info.max_delay;
 
 	d->cpu_count += t1;
 
@@ -145,6 +146,9 @@ int __delayacct_add_tsk(struct taskstats *d, struct task_struct *tsk)
 	d->cpu_run_virtual_total =
 		(tmp < (s64)d->cpu_run_virtual_total) ?	0 : tmp;
 
+	if (d->cpu_delay_max < t4)
+		d->cpu_delay_max = t4;
+
 	/* zero XXX_total, non-zero XXX_count implies XXX stat overflowed */
 
 	spin_lock_irqsave(&tsk->delays->lock, flags);
@@ -157,6 +161,12 @@ int __delayacct_add_tsk(struct taskstats *d, struct task_struct *tsk)
 	d->blkio_count += tsk->delays->blkio_count;
 	d->swapin_count += tsk->delays->swapin_count;
 	d->freepages_count += tsk->delays->freepages_count;
+	if (d->blkio_delay_max < tsk->delays->blkio_delay_max)
+		d->blkio_delay_max = tsk->delays->blkio_delay_max;
+	if (d->swapin_delay_max < tsk->delays->swapin_delay_max)
+		d->swapin_delay_max = tsk->delays->swapin_delay_max;
+	if (d->freepages_delay_max < tsk->delays->freepages_delay_max)
+		d->freepages_delay_max = tsk->delays->freepages_delay_max;
 	spin_unlock_irqrestore(&tsk->delays->lock, flags);
 
 done:
-- 
1.7.6.4

[PATCH 4/4] getdelays: show max CPU/IO/SWAP/RECLAIM delays

[Satoru Moriya]

With this patch, getdelays shows maximum delay which it gets from kernel
via taskstats interface.

Output example:
(on 100 concurrent dd reading sparse files with 1 dd writing a file)

CPU             count     real total  virtual total    delay total      delay_max  delay average
                  234       61990576       78703354         543649         138417          0.002ms
IO              count    delay total      delay max  delay average
                   16      184774999       61259321             11ms
SWAP            count    delay total      delay max  delay average
                    0              0              0              0ms
RECLAIM         count    delay total      delay_max  delay average
                   20        4249456         381288              0ms


Signed-off-by: Satoru Moriya <satoru.moriya@hds.com>
---
 Documentation/accounting/getdelays.c |   28 ++++++++++++++++------------
 1 files changed, 16 insertions(+), 12 deletions(-)

diff --git a/Documentation/accounting/getdelays.c b/Documentation/accounting/getdelays.c
index f6318f6..69d3ec4 100644
--- a/Documentation/accounting/getdelays.c
+++ b/Documentation/accounting/getdelays.c
@@ -197,32 +197,36 @@ static int get_family_id(int sd)
 
 static void print_delayacct(struct taskstats *t)
 {
-	printf("\n\nCPU   %15s%15s%15s%15s%15s\n"
-	       "      %15llu%15llu%15llu%15llu%15.3fms\n"
-	       "IO    %15s%15s%15s\n"
-	       "      %15llu%15llu%15llums\n"
-	       "SWAP  %15s%15s%15s\n"
-	       "      %15llu%15llu%15llums\n"
-	       "RECLAIM  %12s%15s%15s\n"
-	       "      %15llu%15llu%15llums\n",
+	printf("\n\nCPU   %15s%15s%15s%15s%15s%15s\n"
+	       "      %15llu%15llu%15llu%15llu%15llu%15.3fms\n"
+	       "IO    %15s%15s%15s%15s\n"
+	       "      %15llu%15llu%15llu%15llums\n"
+	       "SWAP  %15s%15s%15s%15s\n"
+	       "      %15llu%15llu%15llu%15llums\n"
+	       "RECLAIM  %12s%15s%15s%15s\n"
+	       "      %15llu%15llu%15llu%15llums\n",
 	       "count", "real total", "virtual total",
-	       "delay total", "delay average",
+	       "delay total", "delay_max", "delay average",
 	       (unsigned long long)t->cpu_count,
 	       (unsigned long long)t->cpu_run_real_total,
 	       (unsigned long long)t->cpu_run_virtual_total,
 	       (unsigned long long)t->cpu_delay_total,
+	       (unsigned long long)t->cpu_delay_max,
 	       average_ms((double)t->cpu_delay_total, t->cpu_count),
-	       "count", "delay total", "delay average",
+	       "count", "delay total", "delay max", "delay average",
 	       (unsigned long long)t->blkio_count,
 	       (unsigned long long)t->blkio_delay_total,
+	       (unsigned long long)t->blkio_delay_max,
 	       average_ms(t->blkio_delay_total, t->blkio_count),
-	       "count", "delay total", "delay average",
+	       "count", "delay total", "delay max", "delay average",
 	       (unsigned long long)t->swapin_count,
 	       (unsigned long long)t->swapin_delay_total,
+	       (unsigned long long)t->swapin_delay_max,
 	       average_ms(t->swapin_delay_total, t->swapin_count),
-	       "count", "delay total", "delay average",
+	       "count", "delay total", "delay_max", "delay average",
 	       (unsigned long long)t->freepages_count,
 	       (unsigned long long)t->freepages_delay_total,
+	       (unsigned long long)t->freepages_delay_max,
 	       average_ms(t->freepages_delay_total, t->freepages_count));
 }
 
-- 
1.7.6.4

Re: [PATCH 0/4] delayacct: save max CPU/IO/SWAP/RECLAIM delays

[Peter Zijlstra]

On Mon, 2011-11-28 at 17:44 -0500, Satoru Moriya wrote:
> In the latency sensitive systems, we usually focus on the worst latency.
> And so, it is useful to save max delays into the per-task delay
> accounting functionality.
> 
> Example output:
> (on 100 concurrent dd reading sparse files w/ 1 dd writing a file)
> 
> CPU             count     real total  virtual total    delay total      delay_max  delay average
>                   222       45993008       74603882        7637295        3691858          0.034ms
> IO              count    delay total      delay max  delay average
>                     2       21812073       12728672             10ms
> SWAP            count    delay total      delay max  delay average
>                     0              0              0              0ms
> RECLAIM         count    delay total      delay_max  delay average
>                     2         348488         211985              0ms
> 
> Any comments are welcome.

No!!!

Linus told us to be bastards, so there you have it.

There's way too many different accounting crap thingies around. And now
I get a patch without any justification what so ever. So no, piss off.

RE: [PATCH 0/4] delayacct: save max CPU/IO/SWAP/RECLAIM delays

[Satoru Moriya]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 1028 bytes --]

On 11/29/2011 04:23 AM, Peter Zijlstra wrote:
> On Mon, 2011-11-28 at 17:44 -0500, Satoru Moriya wrote:
>> In the latency sensitive systems, we usually focus on the worst latency.
>> And so, it is useful to save max delays into the per-task delay 
>> accounting functionality.
>>
> 
> No!!!
> 
> Linus told us to be bastards, so there you have it.
> 
> There's way too many different accounting crap thingies around. And 
> now I get a patch without any justification what so ever. So no, piss off.

I agree that there are other ways to get max latency.

I think that with delayacct we can easily get delay statistics
which each task or task-group encountered in their life time
because delayacct records "per-task" delay.

But I just may not know better tools/functions.

Do you think which tools/functions is the best one (to extend)?
ftrace? perf?

Regards,
Satoru
ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥