Re: [PATCH] tracing/function-graph-tracer: handle ftrace_printk entries

[Frédéric Weisbecker]

2008/12/4 Steven Rostedt <rostedt@xxxxxxxxxxx>:
>
> On Wed, 3 Dec 2008, Frederic Weisbecker wrote:
>
>> Handle the TRACE_PRINT entries from the function grapg tracer
>> and output them as a C comment just below the function that called
>> it, as if it was a comment inside this function.
>
> Cool, thanks!
>
>>
>> Example with an ftrace_printk inside might_sleep() function:
>>
>> void __might_sleep(char *file, int line)
>> {
>>       static unsigned long prev_jiffy;        /* ratelimiting */
>>
>>       ftrace_printk("Hi I'm a comment in might_sleep() :-)");
>>
>> A chunk of a resulting trace:
>>
>>  0)               |                                _reiserfs_free_block() {
>>  0)               |                                  reiserfs_read_bitmap_block() {
>>  0)               |                                    __bread() {
>>  0)               |                                      __getblk() {
>>  0)               |                                        __find_get_block() {
>>  0)   0.698 us    |                                          mark_page_accessed();
>>  0)   2.267 us    |                                        }
>>  0)               |                                        __might_sleep() {
>>  0)               |                                          /* Hi I'm a comment in might_sleep() :-) */
>>  0)   1.321 us    |                                        }
>>  0)   5.872 us    |                                      }
>>  0)   7.313 us    |                                    }
>>  0)   8.718 us    |                                  }
>>
>> And this patch bring two minor fixes:
>>
>> _ The newline after a switch-out task has disappeared
>> _ The "|" sign just before the cpu number on task-switch has been deleted.
>>
>>  0)   0.616 us    |                pick_next_task_rt();
>>  0)   1.457 us    |                _spin_trylock();
>>  0)   0.653 us    |                _spin_unlock();
>>  0)   0.728 us    |                _spin_trylock();
>>  0)   0.631 us    |                _spin_unlock();
>>  0)   0.729 us    |                native_load_sp0();
>>  0)   0.593 us    |                native_load_tls();
>>  ------------------------------------------
>>  0)    cat-2834    =>   migrati-3
>>  ------------------------------------------
>>
>>  0)               |    finish_task_switch() {
>>  0)   0.841 us    |      _spin_unlock_irq();
>>  0)   0.616 us    |      post_schedule_rt();
>>  0)   3.882 us    |    }
>>
>>
>> Cc: Steven Rostedt <rostedt@xxxxxxxxxxx>
>> Cc: Pekka Paalanen <pq@xxxxxx>
>> Signed-off-by: Frederic Weisbecker <fweisbec@xxxxxxxxx>
>> ---
>>  kernel/trace/trace.c                 |   28 ++++++++++---
>>  kernel/trace/trace.h                 |    4 +-
>>  kernel/trace/trace_functions_graph.c |   72 +++++++++++++++++++++++++++++++++-
>>  kernel/trace/trace_mmiotrace.c       |    2 +-
>>  4 files changed, 97 insertions(+), 9 deletions(-)
>>
>> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>> index 8b6409a..1ca74c0 100644
>> --- a/kernel/trace/trace.c
>> +++ b/kernel/trace/trace.c
>> @@ -3335,7 +3335,7 @@ static int mark_printk(const char *fmt, ...)
>>       int ret;
>>       va_list args;
>>       va_start(args, fmt);
>> -     ret = trace_vprintk(0, fmt, args);
>> +     ret = trace_vprintk(0, -1, fmt, args);
>>       va_end(args);
>>       return ret;
>>  }
>> @@ -3564,9 +3564,16 @@ static __init int tracer_init_debugfs(void)
>>       return 0;
>>  }
>>
>> -int trace_vprintk(unsigned long ip, const char *fmt, va_list args)
>> +int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
>>  {
>> -     static DEFINE_SPINLOCK(trace_buf_lock);
>> +     /*
>> +      * Raw Spinlock because a normal spinlock would be traced here
>> +      * and append an irrelevant couple spin_lock_irqsave/
>> +      * spin_unlock_irqrestore traced by ftrace around this
>> +      * TRACE_PRINTK trace.
>> +      */
>> +     static raw_spinlock_t trace_buf_lock =
>> +                             (raw_spinlock_t)__RAW_SPIN_LOCK_UNLOCKED;
>>       static char trace_buf[TRACE_BUF_SIZE];
>>
>>       struct ring_buffer_event *event;
>> @@ -3587,7 +3594,8 @@ int trace_vprintk(unsigned long ip, const char *fmt, va_list args)
>>       if (unlikely(atomic_read(&data->disabled)))
>>               goto out;
>>
>> -     spin_lock_irqsave(&trace_buf_lock, flags);
>> +     local_irq_save(flags);
>> +     __raw_spin_lock(&trace_buf_lock);
>>       len = vsnprintf(trace_buf, TRACE_BUF_SIZE, fmt, args);
>
> I wonder if we should add a new flag called "NOTRACE" to the new
> current->trace flags. When set, tracing is stopped for the task. Then we
> can still use spinlock here. We only want to use raw if the tracing will
> cause lockdep to fail, not just to prevent traces.
>
> We could do something like:
>
>  pause_trace(current); /* sets the "notrace" flag */
>
>  unpause_trace(current); /* clears the "notrace" flag */
>


pause_trace seems to me too much generic. Would you want to use it for
normal ftrace too?
I guess I could name it (un)pause_ftrace.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/