From: Frederic Weisbecker <fweisbec@gmail.com>
To: Ingo Molnar <mingo@elte.hu>
Cc: LKML <linux-kernel@vger.kernel.org>,
Li Zefan <lizf@cn.fujitsu.com>,
Frederic Weisbecker <fweisbec@gmail.com>,
Zhao Lei <zhaolei@cn.fujitsu.com>,
Steven Rostedt <rostedt@goodmis.org>,
Tom Zanussi <tzanussi@gmail.com>,
KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>,
Oleg Nesterov <oleg@redhat.com>,
Andrew Morton <akpm@linux-foundation.org>
Subject: [PATCH 15/19] tracing/workqueue: add execution time average column
Date: Thu, 30 Apr 2009 02:27:16 +0200 [thread overview]
Message-ID: <1241051240-4280-16-git-send-email-fweisbec@gmail.com> (raw)
In-Reply-To: <1241051240-4280-1-git-send-email-fweisbec@gmail.com>
We recently got a new column on the stats which shows the maximum execution
time of a worklet. This field is useful to find the worst latency
case a worklet can induce and propagate to the tasks waiting for pending
worklets on the queue.
To complete this worst case information, it's also useful to get
the time execution average of a worklet so that we also get the typical
case of latency it causes.
The header M_EXECus is also turned into "MAX us", so that we can have
a pair of MAX us / AVG us which can reflect more easily the role
of these columns.
Example of the new trace:
# CPU INSERTED EXECUTED MAX us AVG us TASKNAME:PID
# | | | | ` | -WORKFUNC
# | | | | | |
0 1254 1332 events/0:9
0 1 1 39 39 |-hpet_work+0x0/0x340
0 3 2 275 233 |-rt_worker_func+0x0/0x400
0 167 166 69 9 |-vmstat_update+0x0/0x40
0 776 776 106345 255 |-fb_flashcursor+0x0/0x3c0
0 142 142 504 14 |-console_callback+0x0/0x1e0
0 80 80 46941155 1340510 |-test_work+0x0/0x64
0 3 2 0 0 |-lru_add_drain_per_cpu+0x0/0x10
0 1 1 3 3 |-sync_cmos_clock+0x0/0x140
0 81 81 179 60 `-flush_to_ldisc+0x0/0x2f0
0 0 0 cpuset:11
0 1354 1354 khelper:12
0 1354 1354 143449 365 `-__call_usermodehelper+0x0/0xe0
0 0 0 kintegrityd/0:174
0 39 39 kblockd/0:180
0 26 26 170 42 |-blk_unplug_work+0x0/0x110
0 13 13 70 14 `-cfq_kick_queue+0x0/0x50
0 0 0 kacpid:186
0 0 0 kacpi_notify:187
0 0 0 tifm:498
0 312 312 ata/0:507
0 312 312 29 23 `-ata_pio_task+0x0/0x280
0 0 0 ata_aux:512
0 0 0 aio/0:867
0 0 0 crypto/0:897
0 0 0 scsi_tgtd/0:2367
0 0 0 iscsi_eh:2387
0 0 0 kpsmoused:2521
0 0 0 hd-audio0:2714
0 0 0 krxrpcd/0:2734
0 5 5 reiserfs/0:2896
0 5 5 268602 53724 `-flush_async_commits+0x0/0x90
1 510 580 events/1:10
1 1 1 67 67 |-hpet_work+0x0/0x340
1 168 167 79 11 |-vmstat_update+0x0/0x40
1 1 1 441 441 |-power_supply_changed_work+0x0/0x60
1 1 1 836 836 |-sysfs_add_func+0x0/0xb0
1 80 80 46940792 1346733 |-test_work+0x0/0x64
1 1 0 0 0 |-rekey_seq_generator+0x0/0x70
1 3 3 0 0 |-lru_add_drain_per_cpu+0x0/0x10
1 164 164 7065 57 |-console_callback+0x0/0x1e0
1 91 91 315 69 `-flush_to_ldisc+0x0/0x2f0
1 0 0 kintegrityd/1:177
1 44 44 kblockd/1:181
1 30 30 59 36 |-blk_unplug_work+0x0/0x110
1 14 14 167 20 `-cfq_kick_queue+0x0/0x50
1 258 258 ata/1:509
1 258 258 12968 119 `-ata_pio_task+0x0/0x280
1 0 0 aio/1:870
1 0 0 crypto/1:898
1 0 0 scsi_tgtd/1:2370
1 0 0 krxrpcd/1:2757
1 3 3 reiserfs/1:2897
1 3 3 4 4 `-flush_async_commits+0x0/0x90
[ Impact: report the typical latency case caused by a worklet ]
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Zhao Lei <zhaolei@cn.fujitsu.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Tom Zanussi <tzanussi@gmail.com>
Cc: KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>
Cc: Oleg Nesterov <oleg@redhat.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
---
kernel/trace/trace_workqueue.c | 16 +++++++++++-----
1 files changed, 11 insertions(+), 5 deletions(-)
diff --git a/kernel/trace/trace_workqueue.c b/kernel/trace/trace_workqueue.c
index 798a738..1c6555d 100644
--- a/kernel/trace/trace_workqueue.c
+++ b/kernel/trace/trace_workqueue.c
@@ -35,6 +35,7 @@ struct workfunc_stats {
/* save execution time temporarily for calculate executed time */
u64 start_time;
u64 max_executed_time;
+ u64 total_time;
};
/* A cpu workqueue thread */
@@ -191,6 +192,7 @@ found_wq:
continue;
executed_time = trace_clock_global() - wfnode->start_time;
+ wfnode->total_time += executed_time;
if (executed_time > wfnode->max_executed_time)
wfnode->max_executed_time = executed_time;
goto found_wf;
@@ -366,7 +368,7 @@ static int workqueue_stat_show(struct seq_file *s, void *p)
if (!wfstat->func) {
/* It is first dummy node, need to print workqueue info */
- seq_printf(s, " %3d %6d %6u %s:%d\n",
+ seq_printf(s, " %3d %6d %6u %s:%d\n",
cws->cpu,
cws->inserted,
cws->executed,
@@ -375,11 +377,13 @@ static int workqueue_stat_show(struct seq_file *s, void *p)
} else {
/* It is effect node, need to print workfunc info */
int lastwf = list_is_last(&wfstat->list, &cws->workfunclist);
- seq_printf(s, " %3d %6d %6u %6llu %c-%pF\n",
+ seq_printf(s, " %3d %6d %6u %6llu %6llu %c-%pF\n",
cws->cpu,
wfstat->inserted,
wfstat->executed,
ns2usecs(wfstat->max_executed_time),
+ !wfstat->executed ? 0 :
+ ns2usecs(wfstat->total_time / wfstat->executed),
lastwf ? '`' : '|',
wfstat->func);
}
@@ -389,9 +393,11 @@ static int workqueue_stat_show(struct seq_file *s, void *p)
static int workqueue_stat_headers(struct seq_file *s)
{
- seq_printf(s, "# CPU INSERTED EXECUTED M_EXECus TASKNAME:PID\n");
- seq_printf(s, "# | | | | `-WORKFUNC\n");
- seq_printf(s, "# | | | | |\n");
+ seq_printf(s, "# CPU INSERTED EXECUTED MAX us AVG us"
+ " TASKNAME:PID\n");
+ seq_printf(s, "# | | | | ` |"
+ " -WORKFUNC\n");
+ seq_printf(s, "# | | | | | |\n");
return 0;
}
--
1.6.2.3
next prev parent reply other threads:[~2009-04-30 0:32 UTC|newest]
Thread overview: 23+ messages / expand[flat|nested] mbox.gz Atom feed top
2009-04-30 0:27 [PATCH 00/19] tracing/workqueue: events support/enhancements, worklets tracing, fixes Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 01/19] ftrace, workqueuetrace: make workqueue tracepoints use TRACE_EVENT macro Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 02/19] trace_workqueue: use list_for_each_entry() instead of list_for_each_entry_safe() Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 03/19] trace_workqueue: remove cpu_workqueue_stats->first_entry Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 04/19] trace_workqueue: remove blank line between each cpu Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 05/19] trace_workqueue: add worklet information Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 06/19] tracing/workqueue: turn cpu_workqueue_stats::inserted into unsigned int Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 07/19] workqueue_tracepoint: introduce workqueue_handler_exit tracepoint and rename workqueue_execution to workqueue_handler_entry Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 08/19] workqueue_tracepoint: add workqueue_flush and worklet_cancel tracepoint Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 09/19] workqueue_tracepoint: change tracepoint name to fit worklet and workqueue lifecycle Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 10/19] workqueue_trace: separate worklet_insertion into worklet_enqueue and worklet_enqueue_delayed Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 11/19] tracing/workqueue: turn workfunc_stats::inserted into unsigned int Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 12/19] tracing/workqueue: avoid accessing task_struct's member variable in stat file read Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 13/19] tracing/workqueue: use list_for_each_entry instead of list_for_each_entry_safe in probe_workqueue_destruction() Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 14/19] tracing/workqueue: add max execution time mesurement for per worklet Frederic Weisbecker
2009-04-30 0:27 ` Frederic Weisbecker [this message]
2009-04-30 0:27 ` [PATCH 16/19] tracing/workqueue: add open/release file handlers Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 17/19] tracing/workqueue: defer workqueue stat release if needed Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 18/19] tracing/workqueue: use the original cpu affinity on probe_workqueue_destruction Frederic Weisbecker
2009-04-30 0:27 ` [PATCH 19/19] tracing/workqueue: provide documentation for the workqueue tracer Frederic Weisbecker
2009-04-30 1:19 ` KOSAKI Motohiro
2009-04-30 8:45 ` [PATCH 00/19] tracing/workqueue: events support/enhancements, worklets tracing, fixes Ingo Molnar
2009-04-30 12:48 ` Frederic Weisbecker
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=1241051240-4280-16-git-send-email-fweisbec@gmail.com \
--to=fweisbec@gmail.com \
--cc=akpm@linux-foundation.org \
--cc=kosaki.motohiro@jp.fujitsu.com \
--cc=linux-kernel@vger.kernel.org \
--cc=lizf@cn.fujitsu.com \
--cc=mingo@elte.hu \
--cc=oleg@redhat.com \
--cc=rostedt@goodmis.org \
--cc=tzanussi@gmail.com \
--cc=zhaolei@cn.fujitsu.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox
all inboxes | Powered by JetHome®