Re: [PATCH v2 2/4] ftrace: introduce workqueue_handler_exit tracepoint and rename workqueue_execution to workqueue_handler_entry

[Frederic Weisbecker <fweisbec@gmail.com>]

On Mon, Apr 13, 2009 at 02:53:01PM +0900, KOSAKI Motohiro wrote:
> Subject: [PATCH] ftrace: introduce workqueue_handler_exit tracepoint and rename workqueue_execution to workqueue_handler_entry
> 
> Entry/exit handler pair is useful common tracepoint technique. it can mesure handler consumption time.
> 
> Then, workqueue also handler-exit tracepoint and rename execution to handler-entry.
> 
> 
> 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>
> ---
>  include/trace/workqueue_event_types.h |   25 ++++++++++++++++++++++++-
>  kernel/trace/trace_workqueue.c        |   10 +++++-----
>  kernel/workqueue.c                    |    6 ++++--
>  3 files changed, 33 insertions(+), 8 deletions(-)
> 
> Index: b/include/trace/workqueue_event_types.h
> ===================================================================
> --- a/include/trace/workqueue_event_types.h	2009-04-13 13:10:27.000000000 +0900
> +++ b/include/trace/workqueue_event_types.h	2009-04-13 13:10:27.000000000 +0900
> @@ -32,7 +32,7 @@ TRACE_EVENT(workqueue_insertion,
>  		__entry->thread_pid, __entry->func)
>  );
>  
> -TRACE_EVENT(workqueue_execution,
> +TRACE_EVENT(workqueue_handler_entry,
>  
>  	TP_PROTO(struct task_struct *wq_thread, struct work_struct *work),
>  
> @@ -56,6 +56,29 @@ TRACE_EVENT(workqueue_execution,
>  		__entry->thread_pid, __entry->func)
>  );
>  
> +TRACE_EVENT(workqueue_handler_exit,
> +	TP_PROTO(struct task_struct *wq_thread, struct work_struct *work),
> +
> +	TP_ARGS(wq_thread, work),
> +
> +	TP_STRUCT__entry(
> +		__array(char,			thread_comm, TASK_COMM_LEN)
> +		__field(pid_t,			thread_pid)
> +		__field(struct work_struct *,	work)
> +		__field(work_func_t,		func)
> +	),
> +
> +	TP_fast_assign(
> +		memcpy(__entry->thread_comm, wq_thread->comm, TASK_COMM_LEN);
> +		__entry->thread_pid	= wq_thread->pid;
> +		__entry->work		= work;
> +		__entry->func		= work->func;
> +	),
> +
> +	TP_printk("thread=%s:%d func=%pF", __entry->thread_comm,
> +		  __entry->thread_pid, __entry->func)
> +);
> +
>  /* Trace the creation of one workqueue thread on a cpu */
>  TRACE_EVENT(workqueue_creation,
>  
> Index: b/kernel/trace/trace_workqueue.c
> ===================================================================
> --- a/kernel/trace/trace_workqueue.c	2009-04-13 13:10:19.000000000 +0900
> +++ b/kernel/trace/trace_workqueue.c	2009-04-13 13:12:36.000000000 +0900
> @@ -65,7 +65,7 @@ found:
>  
>  /* Execution of a work */
>  static void
> -probe_workqueue_execution(struct task_struct *wq_thread,
> +probe_workqueue_entry(struct task_struct *wq_thread,
>  			  struct work_struct *work)
>  {
>  	int cpu = cpumask_first(&wq_thread->cpus_allowed);
> @@ -255,13 +255,13 @@ int __init trace_workqueue_early_init(vo
>  	if (ret)
>  		goto out;
>  
> -	ret = register_trace_workqueue_execution(probe_workqueue_execution);
> +	ret = register_trace_workqueue_handler_entry(probe_workqueue_entry);
>  	if (ret)
>  		goto no_insertion;
>  
>  	ret = register_trace_workqueue_creation(probe_workqueue_creation);
>  	if (ret)
> -		goto no_execution;
> +		goto no_handler_entry;
>  
>  	ret = register_trace_workqueue_destruction(probe_workqueue_destruction);
>  	if (ret)
> @@ -276,8 +276,8 @@ int __init trace_workqueue_early_init(vo
>  
>  no_creation:
>  	unregister_trace_workqueue_creation(probe_workqueue_creation);
> -no_execution:
> -	unregister_trace_workqueue_execution(probe_workqueue_execution);
> +no_handler_entry:
> +	unregister_trace_workqueue_handler_entry(probe_workqueue_entry);
>  no_insertion:
>  	unregister_trace_workqueue_insertion(probe_workqueue_insertion);
>  out:
> Index: b/kernel/workqueue.c
> ===================================================================
> --- a/kernel/workqueue.c	2009-04-13 13:06:36.000000000 +0900
> +++ b/kernel/workqueue.c	2009-04-13 13:14:15.000000000 +0900
> @@ -262,7 +262,8 @@ int queue_delayed_work_on(int cpu, struc
>  }
>  EXPORT_SYMBOL_GPL(queue_delayed_work_on);
>  
> -DEFINE_TRACE(workqueue_execution);
> +DEFINE_TRACE(workqueue_handler_entry);
> +DEFINE_TRACE(workqueue_handler_exit);
>  
>  static void run_workqueue(struct cpu_workqueue_struct *cwq)
>  {
> @@ -282,7 +283,6 @@ static void run_workqueue(struct cpu_wor
>  		 */
>  		struct lockdep_map lockdep_map = work->lockdep_map;
>  #endif
> -		trace_workqueue_execution(cwq->thread, work);
>  		cwq->current_work = work;
>  		list_del_init(cwq->worklist.next);
>  		spin_unlock_irq(&cwq->lock);
> @@ -291,7 +291,9 @@ static void run_workqueue(struct cpu_wor
>  		work_clear_pending(work);
>  		lock_map_acquire(&cwq->wq->lockdep_map);
>  		lock_map_acquire(&lockdep_map);
> +		trace_workqueue_handler_entry(cwq->thread, work);
>  		f(work);
> +		trace_workqueue_handler_exit(cwq->thread, work);
>  		lock_map_release(&lockdep_map);
>  		lock_map_release(&cwq->wq->lockdep_map);



Whatever we choose a per work or per workqueue latency measurement
(see my comment on the second patch) this patch makes sense.

Thanks!

Acked-by: Frederic Weisbecker <fweisbec@gmail.com>

(Also adding Oleg in Cc).