[PATCH 0/4] workqueue_trace: Add max execution time mesurement for per worklet

[PATCH 0/4] workqueue_trace: Add max execution time mesurement for per worklet

[Zhaolei]

Hi,

This patch add max execution time mesurement for per worklet.
It is useful for driver-developer and system administrator to
know which worklet runs how many time.

It need applied on top of patchset of:
workqueue_tracepoint: Add worklet tracepoints for worklet lifecycle tracing

Output is like:
 # CPU INSERTED EXECUTED M_EXECus TASKNAME:PID
 #  |     |        |        |      `-WORKFUNC
 #  |     |        |        |        |
     0      905      973          events/0:5
     0        1        1       37  |-reg_todo+0x0/0x41f
     0       13       12     2033  |-rt_worker_func+0x0/0x219
     0       49       48     3157  |-mce_work_fn+0x0/0x31
     0       14       13      939  |-check_corruption+0x0/0x2a
     0      707      706     3826  |-vmstat_update+0x0/0x33
     0        1        1     1846  |-power_supply_changed_work+0x0/0x3c
     0       11       11     2879  |-console_callback+0x0/0xe1
     0       30       29     1579  |-do_cache_clean+0x0/0x37
     0       74       74     2841  |-test_work+0x0/0x53
     0        3        2      252  |-rekey_seq_generator+0x0/0x5a
     0        1        1       21  |-grace_ender+0x0/0x14
     0        1        1     3701  `-flush_to_ldisc+0x0/0x15d
     0        0        0          cpuset:6
     0      658      658          khelper:7
     0      658      658     5735  `-__call_usermodehelper+0x0/0x77
     0        0        0          netns:11
 ...

Thanks
Zhaolei

[PATCH 1/4] tracing/workqueue: turn workfunc_stats::inserted into unsigned int

[Zhaolei]

struct workfunc_stats is belong to per_cpu struct of cpu_workqueue_stats,
which means we only need to serialize its accessing from one cpu.

And because trace_workqueue_insertion() is already inside a section
protected by the cpu workqueue lock, we can safely convert it into an
unsigned int.

[ Impact: cleanup ]

Reported-by: Oleg Nesterov <oleg@redhat.com>
Signed-off-by: Zhao Lei <zhaolei@cn.fujitsu.com>
---
 kernel/trace/trace_workqueue.c |   13 +++++--------
 1 files changed, 5 insertions(+), 8 deletions(-)

diff --git a/kernel/trace/trace_workqueue.c b/kernel/trace/trace_workqueue.c
index 69ae4aa..7a07d17 100644
--- a/kernel/trace/trace_workqueue.c
+++ b/kernel/trace/trace_workqueue.c
@@ -20,12 +20,9 @@ struct workfunc_stats {
 
 	/* Addr of worklet's callback function */
 	work_func_t			func;
-	/* Can be inserted on different workqueues, need to be atomic */
-	atomic_t			inserted;
-	/*
-	 * Don't need to be atomic, works are serialized in a single workqueue
-	 * thread on a single CPU.
-	 */
+
+	/* Protected by cpu workqueue lock */
+	unsigned int			inserted;
 	unsigned int			executed;
 };
 
@@ -80,7 +77,7 @@ int do_worklet_enqueue(struct cpu_workqueue_stats *cws,
 
 	list_add_tail(&wfstat->list, &cws->workfunclist);
 found:
-	atomic_inc(&wfstat->inserted);
+	wfstat->inserted++;
 
 	return 0;
 }
@@ -331,7 +328,7 @@ static int workqueue_stat_show(struct seq_file *s, void *p)
 		int lastwf = list_is_last(&wfstat->list, &cws->workfunclist);
 		seq_printf(s, "%3d %6d     %6u        %c-%pF\n",
 			cws->cpu,
-			atomic_read(&wfstat->inserted),
+			wfstat->inserted,
 			wfstat->executed,
 			lastwf ? '`' : '|',
 			wfstat->func);
-- 
1.5.5.3

[PATCH 2/4] tracing/workqueue: Avoid accessing task_struct's member variable in stat file read

[Zhaolei]

Workqueue task maybe destroyed when read stat file.
We should avoid getting information from task_struct this time.

Signed-off-by: Zhao Lei <zhaolei@cn.fujitsu.com>
Reported-by: Oleg Nesterov <oleg@redhat.com>
---
 kernel/trace/trace_workqueue.c |   50 ++++++++++++++++++++--------------------
 1 files changed, 25 insertions(+), 25 deletions(-)

diff --git a/kernel/trace/trace_workqueue.c b/kernel/trace/trace_workqueue.c
index 7a07d17..51ed57e 100644
--- a/kernel/trace/trace_workqueue.c
+++ b/kernel/trace/trace_workqueue.c
@@ -28,14 +28,22 @@ struct workfunc_stats {
 
 /* A cpu workqueue thread */
 struct cpu_workqueue_stats {
-	struct list_head            list;
-	int		            cpu;
-	pid_t			    pid;
+	struct list_head	list;
+	int			cpu;
+
 	/* Protected by cpu workqueue lock */
-	unsigned int	            inserted;
-	unsigned int		    executed;
+	unsigned int		inserted;
+	unsigned int		executed;
 	/* list of struct workfunc_stats in this workqueue */
-	struct list_head            workfunclist;
+	struct list_head	workfunclist;
+
+	/*
+	 * the task maybe destroyed when we read stat file
+	 * we define it to void * because we only use it as a identifier
+	 */
+	void			*task;
+	int			pid;
+	char			comm[TASK_COMM_LEN];
 };
 
 /* List of workqueue threads on one cpu */
@@ -93,7 +101,7 @@ probe_worklet_enqueue(struct task_struct *wq_thread, struct work_struct *work,
 
 	spin_lock_irqsave(&workqueue_cpu_stat(wqcpu)->lock, flags);
 	list_for_each_entry(node, &workqueue_cpu_stat(wqcpu)->list, list) {
-		if (node->pid == wq_thread->pid) {
+		if (node->task == wq_thread) {
 			/* we ignore error of do_worklet_insertion */
 			do_worklet_enqueue(node, work);
 			goto found;
@@ -124,7 +132,7 @@ probe_worklet_execute(struct task_struct *wq_thread, struct work_struct *work)
 	spin_lock_irqsave(&workqueue_cpu_stat(cpu)->lock, flags);
 
 	list_for_each_entry(node, &workqueue_cpu_stat(cpu)->list, list)
-		if (node->pid == wq_thread->pid) {
+		if (node->task == wq_thread) {
 			node->executed++;
 			goto found_wq;
 		}
@@ -163,7 +171,9 @@ static void probe_workqueue_creation(struct task_struct *wq_thread, int cpu)
 	INIT_LIST_HEAD(&cws->list);
 	cws->cpu = cpu;
 
+	cws->task = wq_thread;
 	cws->pid = wq_thread->pid;
+	strncpy(cws->comm, wq_thread->comm, TASK_COMM_LEN);
 	INIT_LIST_HEAD(&cws->workfunclist);
 
 	/*
@@ -204,7 +214,7 @@ static void probe_workqueue_destruction(struct task_struct *wq_thread)
 				 list) {
 		struct workfunc_stats *wfstat, *wfstatnext;
 
-		if (node->pid != wq_thread->pid)
+		if (node->task != wq_thread)
 			continue;
 
 		list_for_each_entry_safe(wfstat, wfstatnext,
@@ -304,25 +314,15 @@ static int workqueue_stat_show(struct seq_file *s, void *p)
 {
 	struct workfunc_stats *wfstat = p;
 	struct cpu_workqueue_stats *cws = wfstat->parent;
-	struct pid *pid;
-	struct task_struct *tsk;
 
 	if (!wfstat->func) {
 		/* It is first dummy node, need to print workqueue info */
-		pid = find_get_pid(cws->pid);
-		if (pid) {
-			tsk = get_pid_task(pid, PIDTYPE_PID);
-			if (tsk) {
-				seq_printf(s, "%3d %6d     %6u       %s:%d\n",
-					   cws->cpu,
-					   cws->inserted,
-					   cws->executed,
-					   tsk->comm,
-					   cws->pid);
-				put_task_struct(tsk);
-			}
-			put_pid(pid);
-		}
+		seq_printf(s, "%3d %6d     %6u       %s:%d\n",
+			   cws->cpu,
+			   cws->inserted,
+			   cws->executed,
+			   cws->comm,
+			   cws->pid);
 	} else {
 		/* It is effect node, need to print workfunc info */
 		int lastwf = list_is_last(&wfstat->list, &cws->workfunclist);
-- 
1.5.5.3

[PATCH 3/4] tracing/workqueue: Use list_for_each_entry instrad of list_for_each_entry_safe in probe_workqueue_destruction()

[Zhaolei]

No need to use list_for_each_entry_safe() because we just remove one list node
which is first found in list iteration.
(we don't continue list iteration after remove list node)

Signed-off-by: Zhao Lei <zhaolei@cn.fujitsu.com>
---
 kernel/trace/trace_workqueue.c |    5 ++---
 1 files changed, 2 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace_workqueue.c b/kernel/trace/trace_workqueue.c
index 51ed57e..b995bc0 100644
--- a/kernel/trace/trace_workqueue.c
+++ b/kernel/trace/trace_workqueue.c
@@ -206,12 +206,11 @@ static void probe_workqueue_destruction(struct task_struct *wq_thread)
 {
 	/* Workqueue only execute on one cpu */
 	int cpu = cpumask_first(&wq_thread->cpus_allowed);
-	struct cpu_workqueue_stats *node, *next;
+	struct cpu_workqueue_stats *node;
 	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) {
+	list_for_each_entry(node, &workqueue_cpu_stat(cpu)->list, list) {
 		struct workfunc_stats *wfstat, *wfstatnext;
 
 		if (node->task != wq_thread)
-- 
1.5.5.3

[PATCH 4/4] tracing/workqueue: Add max execution time mesurement for per worklet

[Zhaolei]

From: KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>

It is useful for driver-developer and system administrator to
know which worklet runs how many time.

Change Log:
v1: KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>
    add max execution time mesurement for per workqueue
v2: Zhao Lei <zhaolei@cn.fujitsu.com>
    add max execution time mesurement for per worklet instead of workqueue

Output is like:
 # CPU INSERTED EXECUTED M_EXECus TASKNAME:PID
 #  |     |        |        |      `-WORKFUNC
 #  |     |        |        |        |
     0      905      973          events/0:5
     0        1        1       37  |-reg_todo+0x0/0x41f
     0       13       12     2033  |-rt_worker_func+0x0/0x219
     0       49       48     3157  |-mce_work_fn+0x0/0x31
     0       14       13      939  |-check_corruption+0x0/0x2a
     0      707      706     3826  |-vmstat_update+0x0/0x33
     0        1        1     1846  |-power_supply_changed_work+0x0/0x3c
     0       11       11     2879  |-console_callback+0x0/0xe1
     0       30       29     1579  |-do_cache_clean+0x0/0x37
     0       74       74     2841  |-test_work+0x0/0x53
     0        3        2      252  |-rekey_seq_generator+0x0/0x5a
     0        1        1       21  |-grace_ender+0x0/0x14
     0        1        1     3701  `-flush_to_ldisc+0x0/0x15d
     0        0        0          cpuset:6
     0      658      658          khelper:7
     0      658      658     5735  `-__call_usermodehelper+0x0/0x77
     0        0        0          netns:11
 ...

Signed-off-by: Zhao Lei <zhaolei@cn.fujitsu.com>
Signed-off-by: KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>
---
 kernel/trace/trace_workqueue.c |   83 +++++++++++++++++++++++++++++++++------
 1 files changed, 70 insertions(+), 13 deletions(-)

diff --git a/kernel/trace/trace_workqueue.c b/kernel/trace/trace_workqueue.c
index b995bc0..30b0075 100644
--- a/kernel/trace/trace_workqueue.c
+++ b/kernel/trace/trace_workqueue.c
@@ -24,6 +24,17 @@ struct workfunc_stats {
 	/* Protected by cpu workqueue lock */
 	unsigned int			inserted;
 	unsigned int			executed;
+
+	/*
+	 * save latest work_struct's pointer to use as identifier in
+	 * probe_worklet_complete, because we can't use work_struct->...
+	 * after worklet got executed
+	 */
+	void				*work;
+
+	/* save execution time temporarily for calculate executed time */
+	u64				start_time;
+	u64				max_executed_time;
 };
 
 /* A cpu workqueue thread */
@@ -143,6 +154,8 @@ found_wq:
 	list_for_each_entry(wfnode, &node->workfunclist, list)
 		if (wfnode->func == work->func) {
 			wfnode->executed++;
+			wfnode->start_time = trace_clock_global();
+			wfnode->work = work;
 			goto found_wf;
 		}
 	pr_debug("trace_workqueue: worklet not found\n");
@@ -153,6 +166,43 @@ end:
 	spin_unlock_irqrestore(&workqueue_cpu_stat(cpu)->lock, flags);
 }
 
+/* Complete of a work */
+static void
+probe_worklet_complete(struct task_struct *wq_thread, void *work)
+{
+	int cpu = cpumask_first(&wq_thread->cpus_allowed);
+	struct cpu_workqueue_stats *node;
+	struct workfunc_stats *wfnode;
+	unsigned long flags;
+
+	spin_lock_irqsave(&workqueue_cpu_stat(cpu)->lock, flags);
+
+	list_for_each_entry(node, &workqueue_cpu_stat(cpu)->list, list)
+		if (node->task == wq_thread)
+			goto found_wq;
+	pr_debug("trace_workqueue: workqueue not found\n");
+	goto end;
+
+found_wq:
+	list_for_each_entry(wfnode, &node->workfunclist, list) {
+		u64 executed_time;
+
+		if (wfnode->work != work)
+			continue;
+
+		executed_time = trace_clock_global() - wfnode->start_time;
+		if (executed_time > wfnode->max_executed_time)
+			wfnode->max_executed_time = executed_time;
+		goto found_wf;
+	}
+	pr_debug("trace_workqueue: worklet not found\n");
+	goto end;
+
+found_wf:
+end:
+	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)
 {
@@ -316,7 +366,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,
@@ -325,10 +375,11 @@ 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        %c-%pF\n",
+		seq_printf(s, "  %3d   %6d   %6u   %6llu  %c-%pF\n",
 			cws->cpu,
 			wfstat->inserted,
 			wfstat->executed,
+			ns2usecs(wfstat->max_executed_time),
 			lastwf ? '`' : '|',
 			wfstat->func);
 	}
@@ -338,9 +389,9 @@ 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   TASKNAME:PID\n");
-	seq_printf(s, "# |      |         |        `-WORKFUNC\n");
-	seq_printf(s, "# |      |         |          |\n");
+	seq_printf(s, "# CPU INSERTED EXECUTED M_EXECus	 TASKNAME:PID\n");
+	seq_printf(s, "#  |     |        |        |      `-WORKFUNC\n");
+	seq_printf(s, "#  |     |        |        |        |\n");
 	return 0;
 }
 
@@ -379,19 +430,23 @@ int __init trace_workqueue_early_init(void)
 	ret = register_trace_worklet_enqueue_delayed(
 		probe_worklet_enqueue_delayed);
 	if (ret)
-		goto no_enqueue;
+		goto out_worklet_enqueue;
 
 	ret = register_trace_worklet_execute(probe_worklet_execute);
 	if (ret)
-		goto no_enqueue_delayed;
+		goto out_worklet_enqueue_delayed;
+
+	ret = register_trace_worklet_complete(probe_worklet_complete);
+	if (ret)
+		goto out_worklet_execute;
 
 	ret = register_trace_workqueue_creation(probe_workqueue_creation);
 	if (ret)
-		goto no_handler_entry;
+		goto out_worklet_complete;
 
 	ret = register_trace_workqueue_destruction(probe_workqueue_destruction);
 	if (ret)
-		goto no_creation;
+		goto out_workqueue_creation;
 
 	for_each_possible_cpu(cpu) {
 		spin_lock_init(&workqueue_cpu_stat(cpu)->lock);
@@ -400,13 +455,15 @@ int __init trace_workqueue_early_init(void)
 
 	return 0;
 
-no_creation:
+out_workqueue_creation:
 	unregister_trace_workqueue_creation(probe_workqueue_creation);
-no_handler_entry:
+out_worklet_complete:
+	unregister_trace_worklet_complete(probe_worklet_complete);
+out_worklet_execute:
 	unregister_trace_worklet_execute(probe_worklet_execute);
-no_enqueue_delayed:
+out_worklet_enqueue_delayed:
 	unregister_trace_worklet_enqueue_delayed(probe_worklet_enqueue_delayed);
-no_enqueue:
+out_worklet_enqueue:
 	unregister_trace_worklet_enqueue(probe_worklet_enqueue);
 out:
 	pr_warning("trace_workqueue: unable to trace workqueues\n");
-- 
1.5.5.3

Re: [PATCH 4/4] tracing/workqueue: Add max execution time mesurement for per worklet

[Oleg Nesterov]

I have no idea how the code actually looks with these patches applied,
so please don't take my words seriously, but

On 04/28, Zhaolei wrote:
>
> @@ -24,6 +24,17 @@ struct workfunc_stats {
>  	/* Protected by cpu workqueue lock */
>  	unsigned int			inserted;
>  	unsigned int			executed;
> +
> +	/*
> +	 * save latest work_struct's pointer to use as identifier in
> +	 * probe_worklet_complete, because we can't use work_struct->...
> +	 * after worklet got executed
> +	 */
> +	void				*work;

Do we really need it ?

> @@ -143,6 +154,8 @@ found_wq:
>  	list_for_each_entry(wfnode, &node->workfunclist, list)
>  		if (wfnode->func == work->func) {
>  			wfnode->executed++;
> +			wfnode->start_time = trace_clock_global();
> +			wfnode->work = work;
>  			goto found_wf;
>  		}
>  	pr_debug("trace_workqueue: worklet not found\n");
> @@ -153,6 +166,43 @@ end:
>  	spin_unlock_irqrestore(&workqueue_cpu_stat(cpu)->lock, flags);
>  }
>
> +/* Complete of a work */
> +static void
> +probe_worklet_complete(struct task_struct *wq_thread, void *work)
> +{
> +	int cpu = cpumask_first(&wq_thread->cpus_allowed);
> +	struct cpu_workqueue_stats *node;
> +	struct workfunc_stats *wfnode;
> +	unsigned long flags;
> +
> +	spin_lock_irqsave(&workqueue_cpu_stat(cpu)->lock, flags);
> +
> +	list_for_each_entry(node, &workqueue_cpu_stat(cpu)->list, list)
> +		if (node->task == wq_thread)
> +			goto found_wq;
> +	pr_debug("trace_workqueue: workqueue not found\n");
> +	goto end;
> +
> +found_wq:
> +	list_for_each_entry(wfnode, &node->workfunclist, list) {
> +		u64 executed_time;
> +
> +		if (wfnode->work != work)
> +			continue;

Perhaps we can add node->last_work (or whatever) instead? It should be
recorded by the "entry" handler. In this case probe_worklet_complete()
doesn't need to search for this work (and it doesn't need the argument).
We know that wfnode == node->last_work.

Oleg.

Re: [PATCH 0/4] workqueue_trace: Add max execution time mesurement for per worklet

[Frederic Weisbecker]

On Tue, Apr 28, 2009 at 06:51:33PM +0800, Zhaolei wrote:
> Hi,
> 
> This patch add max execution time mesurement for per worklet.
> It is useful for driver-developer and system administrator to
> know which worklet runs how many time.
> 
> It need applied on top of patchset of:
> workqueue_tracepoint: Add worklet tracepoints for worklet lifecycle tracing
> 
> Output is like:
>  # CPU INSERTED EXECUTED M_EXECus TASKNAME:PID
>  #  |     |        |        |      `-WORKFUNC
>  #  |     |        |        |        |
>      0      905      973          events/0:5
>      0        1        1       37  |-reg_todo+0x0/0x41f
>      0       13       12     2033  |-rt_worker_func+0x0/0x219
>      0       49       48     3157  |-mce_work_fn+0x0/0x31
>      0       14       13      939  |-check_corruption+0x0/0x2a
>      0      707      706     3826  |-vmstat_update+0x0/0x33
>      0        1        1     1846  |-power_supply_changed_work+0x0/0x3c
>      0       11       11     2879  |-console_callback+0x0/0xe1
>      0       30       29     1579  |-do_cache_clean+0x0/0x37
>      0       74       74     2841  |-test_work+0x0/0x53
>      0        3        2      252  |-rekey_seq_generator+0x0/0x5a
>      0        1        1       21  |-grace_ender+0x0/0x14
>      0        1        1     3701  `-flush_to_ldisc+0x0/0x15d
>      0        0        0          cpuset:6
>      0      658      658          khelper:7
>      0      658      658     5735  `-__call_usermodehelper+0x0/0x77
>      0        0        0          netns:11
>  ...
> 
> Thanks
> Zhaolei
> 

Thanks Zhaolei,

I've applied this series and the previous one to
git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git
 tracing/workqueue

Re: [PATCH 0/4] workqueue_trace: Add max execution time mesurement for per worklet

[Andrew Morton]

On Tue, 28 Apr 2009 18:51:33 +0800 Zhaolei <zhaolei@cn.fujitsu.com> wrote:

> Hi,
> 
> This patch add max execution time mesurement for per worklet.
> It is useful for driver-developer and system administrator to
> know which worklet runs how many time.

This seems more useful than the previous feature.

> It need applied on top of patchset of:
> workqueue_tracepoint: Add worklet tracepoints for worklet lifecycle tracing
> 
> Output is like:
>  # CPU INSERTED EXECUTED M_EXECus TASKNAME:PID
>  #  |     |        |        |      `-WORKFUNC
>  #  |     |        |        |        |
>      0      905      973          events/0:5
>      0        1        1       37  |-reg_todo+0x0/0x41f
>      0       13       12     2033  |-rt_worker_func+0x0/0x219
>      0       49       48     3157  |-mce_work_fn+0x0/0x31
>      0       14       13      939  |-check_corruption+0x0/0x2a
>      0      707      706     3826  |-vmstat_update+0x0/0x33
>      0        1        1     1846  |-power_supply_changed_work+0x0/0x3c
>      0       11       11     2879  |-console_callback+0x0/0xe1
>      0       30       29     1579  |-do_cache_clean+0x0/0x37
>      0       74       74     2841  |-test_work+0x0/0x53
>      0        3        2      252  |-rekey_seq_generator+0x0/0x5a
>      0        1        1       21  |-grace_ender+0x0/0x14
>      0        1        1     3701  `-flush_to_ldisc+0x0/0x15d
>      0        0        0          cpuset:6
>      0      658      658          khelper:7
>      0      658      658     5735  `-__call_usermodehelper+0x0/0x77
>      0        0        0          netns:11

What is the meaning of M_EXECus?  Mean execution time in microseconds,
I assume?  I wonder if that is sufficiently high resolution nowadays.

You'll note that all the functions are reported as "foo+0x0/0xN". 
There is a way of suppressing the unneeded and unuseful "+0x0/0xN",
but I forget what it is and the comments over lib/vsprintf.c:pointer()
didn't help.  I think it's %pS.

The patchset adds no user documentation for the feature and should not
(IMO) be merged in such a state.  Please.

Re: [PATCH 0/4] workqueue_trace: Add max execution time mesurement for per worklet

[Frederic Weisbecker]

On Wed, Apr 29, 2009 at 12:06:16AM -0700, Andrew Morton wrote:
> What is the meaning of M_EXECus?  Mean execution time in microseconds,
> I assume?  I wonder if that is sufficiently high resolution nowadays.


It's the maximum execution time encountered for a given worklet.
I also have a small patch, about ready, to get the average.

 
> You'll note that all the functions are reported as "foo+0x0/0xN". 
> There is a way of suppressing the unneeded and unuseful "+0x0/0xN",
> but I forget what it is and the comments over lib/vsprintf.c:pointer()
> didn't help.  I think it's %pS.


I don't know any way to perform this.
%pF and %pS will act pretty much the same, except:

Extract from lib/vsprintf.c:

 * Note: The difference between 'S' and 'F' is that on ia64 and ppc64
 * function pointers are really function descriptors, which contain a
 * pointer to the real address.

But the output formatting is the same: address, offset, size, modname.

I found it a bit annoying, so I proposed the following patch recently:

http://lkml.org/lkml/2009/4/15/310

And someone came with a better idea, IMO:

http://lkml.org/lkml/2009/4/17/105


> 
> The patchset adds no user documentation for the feature and should not
> (IMO) be merged in such a state.  Please.
>


Ok, I will try something today about the documentation.

Thanks!

Re: [PATCH 0/4] workqueue_trace: Add max execution time mesurement for per worklet

[Steven Rostedt]

On Wed, 29 Apr 2009, Frederic Weisbecker wrote:

> On Wed, Apr 29, 2009 at 12:06:16AM -0700, Andrew Morton wrote:
> > What is the meaning of M_EXECus?  Mean execution time in microseconds,
> > I assume?  I wonder if that is sufficiently high resolution nowadays.
> 
> 
> It's the maximum execution time encountered for a given worklet.
> I also have a small patch, about ready, to get the average.
> 
>  
> > You'll note that all the functions are reported as "foo+0x0/0xN". 
> > There is a way of suppressing the unneeded and unuseful "+0x0/0xN",
> > but I forget what it is and the comments over lib/vsprintf.c:pointer()
> > didn't help.  I think it's %pS.
> 
> 
> I don't know any way to perform this.
> %pF and %pS will act pretty much the same, except:
> 
> Extract from lib/vsprintf.c:
> 
>  * Note: The difference between 'S' and 'F' is that on ia64 and ppc64
>  * function pointers are really function descriptors, which contain a
>  * pointer to the real address.
> 
> But the output formatting is the same: address, offset, size, modname.

I could not find any way to remove it, thus I wrote my own version of %pF 
to get rid of the +0x0/0xN notations in the output for ftrace.

-- Steve

Re: [PATCH 0/4] workqueue_trace: Add max execution time mesurement for per worklet

[Steven Rostedt]

On Wed, 29 Apr 2009, Frederic Weisbecker wrote:
>  * pointer to the real address.
> 
> But the output formatting is the same: address, offset, size, modname.
> 
> I found it a bit annoying, so I proposed the following patch recently:
> 
> http://lkml.org/lkml/2009/4/15/310
> 
> And someone came with a better idea, IMO:
> 
> http://lkml.org/lkml/2009/4/17/105

Note,

If these ever do get merged, I would be happy to convert ftrace to use 
them to replace my version.

-- Steve

Re: [PATCH 0/4] workqueue_trace: Add max execution time mesurement for per worklet

[Andrew Morton]

On Wed, 29 Apr 2009 09:45:28 -0400 (EDT) Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> On Wed, 29 Apr 2009, Frederic Weisbecker wrote:
> >  * pointer to the real address.
> > 
> > But the output formatting is the same: address, offset, size, modname.
> > 
> > I found it a bit annoying, so I proposed the following patch recently:
> > 
> > http://lkml.org/lkml/2009/4/15/310

This looks OK.  I'd assumed it was merged.  Was there a problem with it?

> > And someone came with a better idea, IMO:
> > 
> > http://lkml.org/lkml/2009/4/17/105
> 
> Note,
> 
> If these ever do get merged, I would be happy to convert ftrace to use 
> them to replace my version.

I spose I could use magic powers to sneak it into .30?

Re: [PATCH 0/4] workqueue_trace: Add max execution time mesurement for per worklet

[Frederic Weisbecker]

On Wed, Apr 29, 2009 at 08:36:54AM -0700, Andrew Morton wrote:
> On Wed, 29 Apr 2009 09:45:28 -0400 (EDT) Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > 
> > On Wed, 29 Apr 2009, Frederic Weisbecker wrote:
> > >  * pointer to the real address.
> > > 
> > > But the output formatting is the same: address, offset, size, modname.
> > > 
> > > I found it a bit annoying, so I proposed the following patch recently:
> > > 
> > > http://lkml.org/lkml/2009/4/15/310
> 
> This looks OK.  I'd assumed it was merged.  Was there a problem with it?



No, I tested it without problem.


 
> > > And someone came with a better idea, IMO:
> > > 
> > > http://lkml.org/lkml/2009/4/17/105
> > 
> > Note,
> > 
> > If these ever do get merged, I would be happy to convert ftrace to use 
> > them to replace my version.
> 
> I spose I could use magic powers to sneak it into .30?


Thanks :)

Re: [PATCH 0/4] workqueue_trace: Add max execution time mesurement for per worklet

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> > > > And someone came with a better idea, IMO:
> > > > 
> > > > http://lkml.org/lkml/2009/4/17/105
> > > 
> > > Note,
> > > 
> > > If these ever do get merged, I would be happy to convert ftrace to use 
> > > them to replace my version.
> > 
> > I spose I could use magic powers to sneak it into .30?
> 
> Thanks :)

Andrew: if you do that then please pick up the commit i queued up in 
tip:core/printk.

	Ingo

Re: [PATCH 0/4] workqueue_trace: Add max execution time mesurementfor per worklet

[Zhaolei]

* From: "Frederic Weisbecker" <fweisbec@gmail.com>
> On Wed, Apr 29, 2009 at 12:06:16AM -0700, Andrew Morton wrote:
>> What is the meaning of M_EXECus?  Mean execution time in microseconds,
>> I assume?  I wonder if that is sufficiently high resolution nowadays.
> 
> 
> It's the maximum execution time encountered for a given worklet.
> I also have a small patch, about ready, to get the average.
> 
> 
>> You'll note that all the functions are reported as "foo+0x0/0xN". 
>> There is a way of suppressing the unneeded and unuseful "+0x0/0xN",
>> but I forget what it is and the comments over lib/vsprintf.c:pointer()
>> didn't help.  I think it's %pS.
> 
> 
> I don't know any way to perform this.
> %pF and %pS will act pretty much the same, except:
> 
> Extract from lib/vsprintf.c:
> 
> * Note: The difference between 'S' and 'F' is that on ia64 and ppc64
> * function pointers are really function descriptors, which contain a
> * pointer to the real address.
> 
> But the output formatting is the same: address, offset, size, modname.
> 
> I found it a bit annoying, so I proposed the following patch recently:
> 
> http://lkml.org/lkml/2009/4/15/310
> 
> And someone came with a better idea, IMO:
> 
> http://lkml.org/lkml/2009/4/17/105
> 
> 
>> 
>> The patchset adds no user documentation for the feature and should not
>> (IMO) be merged in such a state.  Please.
>>
> 
> 
> Ok, I will try something today about the documentation.
> 
> Thanks!
Hello,

To Frederic
Thanks for reply this mail for me.
Your saying is better than me.

To Andrew:
Sorry for replay late, I was rest yesterday.
Frederic's answer is all I wish to say.

Thanks
Zhaolei


> 
> 
>ÿôèº{.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¥

Re: Re: [PATCH 4/4] tracing/workqueue: Add max execution time mesurement for per worklet

[Zhaolei]

Oleg Nesterov wrote:
> I have no idea how the code actually looks with these patches applied,
> so please don't take my words seriously, but
> 
> On 04/28, Zhaolei wrote:
>> @@ -24,6 +24,17 @@ struct workfunc_stats {
>>  	/* Protected by cpu workqueue lock */
>>  	unsigned int			inserted;
>>  	unsigned int			executed;
>> +
>> +	/*
>> +	 * save latest work_struct's pointer to use as identifier in
>> +	 * probe_worklet_complete, because we can't use work_struct->...
>> +	 * after worklet got executed
>> +	 */
>> +	void				*work;
> 
> Do we really need it ?
> 
>> @@ -143,6 +154,8 @@ found_wq:
>>  	list_for_each_entry(wfnode, &node->workfunclist, list)
>>  		if (wfnode->func == work->func) {
>>  			wfnode->executed++;
>> +			wfnode->start_time = trace_clock_global();
>> +			wfnode->work = work;
>>  			goto found_wf;
>>  		}
>>  	pr_debug("trace_workqueue: worklet not found\n");
>> @@ -153,6 +166,43 @@ end:
>>  	spin_unlock_irqrestore(&workqueue_cpu_stat(cpu)->lock, flags);
>>  }
>>
>> +/* Complete of a work */
>> +static void
>> +probe_worklet_complete(struct task_struct *wq_thread, void *work)
>> +{
>> +	int cpu = cpumask_first(&wq_thread->cpus_allowed);
>> +	struct cpu_workqueue_stats *node;
>> +	struct workfunc_stats *wfnode;
>> +	unsigned long flags;
>> +
>> +	spin_lock_irqsave(&workqueue_cpu_stat(cpu)->lock, flags);
>> +
>> +	list_for_each_entry(node, &workqueue_cpu_stat(cpu)->list, list)
>> +		if (node->task == wq_thread)
>> +			goto found_wq;
>> +	pr_debug("trace_workqueue: workqueue not found\n");
>> +	goto end;
>> +
>> +found_wq:
>> +	list_for_each_entry(wfnode, &node->workfunclist, list) {
>> +		u64 executed_time;
>> +
>> +		if (wfnode->work != work)
>> +			continue;
> 
> Perhaps we can add node->last_work (or whatever) instead? It should be
> recorded by the "entry" handler. In this case probe_worklet_complete()
> doesn't need to search for this work (and it doesn't need the argument).
> We know that wfnode == node->last_work.
Hello, Oleg

Sorry for reply late.

Thanks for review of this patch.
This is indeed a good idea, I will change to this way

Thanks
Zhaolei

> 
> Oleg.
> 
>