lkml.org 
[lkml]   [2009]   [Apr]   [13]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    From
    Subject[PATCH v2 3/4] ftrace: add max execution time mesurement to workqueue tracer
    Date
    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:



    \
     
     \ /
      Last update: 2009-04-13 07:57    [W:4.675 / U:0.064 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site