[PATCH v2 3/4] ftrace: add max execution time mesurement to workqueue tracer

[KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>]

Subject: [PATCH] ftrace: add max execution time mesurement to workqueue tracer

Too slow workqueue handler often introduce some trouble to system.
Then, administrator want to know may handler execution time.


Signed-off-by: KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>
Cc: Zhaolei <zhaolei@cn.fujitsu.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Tom Zanussi <tzanussi@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
---
 kernel/trace/trace_workqueue.c |   48 +++++++++++++++++++++++++++++++++++++----
 1 file changed, 44 insertions(+), 4 deletions(-)

Index: b/kernel/trace/trace_workqueue.c
===================================================================
--- a/kernel/trace/trace_workqueue.c	2009-04-13 13:23:59.000000000 +0900
+++ b/kernel/trace/trace_workqueue.c	2009-04-13 13:59:51.000000000 +0900
@@ -27,6 +27,10 @@ struct cpu_workqueue_stats {
  *  on a single CPU.
  */
 	unsigned int		    executed;
+
+	/* store handler execution time */
+	u64			    handler_start_time;
+	u64			    max_executed_time;
 };
 
 /* List of workqueue threads on one cpu */
@@ -77,6 +81,7 @@ probe_workqueue_entry(struct task_struct
 							list) {
 		if (node->pid == wq_thread->pid) {
 			node->executed++;
+			node->handler_start_time = trace_clock_global();
 			goto found;
 		}
 	}
@@ -85,6 +90,29 @@ found:
 	spin_unlock_irqrestore(&workqueue_cpu_stat(cpu)->lock, flags);
 }
 
+static void probe_workqueue_exit(struct task_struct *wq_thread,
+				 struct work_struct *work)
+{
+	int cpu = cpumask_first(&wq_thread->cpus_allowed);
+	struct cpu_workqueue_stats *node, *next;
+	unsigned long flags;
+
+	spin_lock_irqsave(&workqueue_cpu_stat(cpu)->lock, flags);
+	list_for_each_entry_safe(node, next, &workqueue_cpu_stat(cpu)->list,
+							list) {
+		if (node->pid == wq_thread->pid) {
+			u64 start = node->handler_start_time;
+			u64 executed_time = trace_clock_global() - start;
+
+			if (node->max_executed_time < executed_time)
+				node->max_executed_time = executed_time;
+			goto found;
+		}
+	}
+found:
+	spin_unlock_irqrestore(&workqueue_cpu_stat(cpu)->lock, flags);
+}
+
 /* Creation of a cpu workqueue thread */
 static void probe_workqueue_creation(struct task_struct *wq_thread, int cpu)
 {
@@ -195,6 +223,9 @@ static int workqueue_stat_show(struct se
 	int cpu = cws->cpu;
 	struct pid *pid;
 	struct task_struct *tsk;
+	unsigned long long exec_time = ns2usecs(cws->max_executed_time);
+	unsigned long exec_usec_rem = do_div(exec_time, USEC_PER_SEC);
+	unsigned long exec_secs = (unsigned long)exec_time;
 
 	spin_lock_irqsave(&workqueue_cpu_stat(cpu)->lock, flags);
 	if (&cws->list == workqueue_cpu_stat(cpu)->list.next)
@@ -205,8 +236,11 @@ static int workqueue_stat_show(struct se
 	if (pid) {
 		tsk = get_pid_task(pid, PIDTYPE_PID);
 		if (tsk) {
-			seq_printf(s, "%3d %6d     %6u       %s\n", cws->cpu,
+			seq_printf(s, "%3d %6d     %6u     %5lu.%06lu"
+				   "  %s\n",
+				   cws->cpu,
 				   atomic_read(&cws->inserted), cws->executed,
+				   exec_secs, exec_usec_rem,
 				   tsk->comm);
 			put_task_struct(tsk);
 		}
@@ -218,8 +252,8 @@ static int workqueue_stat_show(struct se
 
 static int workqueue_stat_headers(struct seq_file *s)
 {
-	seq_printf(s, "# CPU  INSERTED  EXECUTED   NAME\n");
-	seq_printf(s, "# |      |         |          |\n");
+	seq_printf(s, "# CPU  INSERTED  EXECUTED     MAX_TIME  NAME\n");
+	seq_printf(s, "# |      |         |           |         |\n");
 	return 0;
 }
 
@@ -259,10 +293,14 @@ int __init trace_workqueue_early_init(vo
 	if (ret)
 		goto no_insertion;
 
-	ret = register_trace_workqueue_creation(probe_workqueue_creation);
+	ret = register_trace_workqueue_handler_exit(probe_workqueue_exit);
 	if (ret)
 		goto no_handler_entry;
 
+	ret = register_trace_workqueue_creation(probe_workqueue_creation);
+	if (ret)
+		goto no_handler_exit;
+
 	ret = register_trace_workqueue_destruction(probe_workqueue_destruction);
 	if (ret)
 		goto no_creation;
@@ -276,6 +314,8 @@ int __init trace_workqueue_early_init(vo
 
 no_creation:
 	unregister_trace_workqueue_creation(probe_workqueue_creation);
+no_handler_exit:
+	unregister_trace_workqueue_handler_exit(probe_workqueue_exit);
 no_handler_entry:
 	unregister_trace_workqueue_handler_entry(probe_workqueue_entry);
 no_insertion: