[PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

[PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

[Rajesh Bhagat]

>From 60ec8a88ba671fa0b424f7b4467dba3ea8a2a2c8 Mon Sep 17 00:00:00 2001
From: Rajesh Bhagat <rajesh.lnx@gmail.com>
Date: Tue, 20 Mar 2012 10:35:59 +0530
Subject: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

This patch resets the trace_array using tracing_reset_online_cpus, if same
tracer is set again instead of just returning from funtion tracing_set_tracer.

problem description
-------------------
once function tracer is set, set_ftrace_filter not working.
/debug/tracing # echo function > current_tracer
/debug/tracing # echo schedule > set_ftrace_filter
/debug/tracing # echo function > current_tracer
/debug/tracing #  cat trace
# tracer: function
#
#           TASK-PID    CPU#    TIMESTAMP  FUNCTION
#              | |       |          |         |
          <idle>-0     [000]    21.997778: irq_enter <-handle_IRQ
          <idle>-0     [000]    21.997785: idle_cpu <-irq_enter
          <idle>-0     [000]    21.997794: local_bh_disable <-irq_enter
          <idle>-0     [000]    21.997800: tick_check_idle <-irq_enter
          <idle>-0     [000]    21.997807:
tick_check_oneshot_broadcast <-tick_check_idle
          <idle>-0     [000]    21.997814: _local_bh_enable <-irq_enter

After applying this patch, only filtered functions are traced.

Signed-off-by: Rajesh Bhagat <rajesh.lnx@gmail.com>
---
 kernel/trace/trace.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index a3f1bc5..f4fb190 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3058,8 +3058,10 @@ static int tracing_set_tracer(const char *buf)
        ret = -EINVAL;
        goto out;
    }
-   if (t == current_trace)
+   if (t == current_trace) {
+       tracing_reset_online_cpus(tr);
        goto out;
+   }

    trace_branch_disable();
    if (current_trace && current_trace->reset)
-- 
1.7.6

Re: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

[Steven Rostedt]

On Wed, 2012-03-21 at 11:22 +0530, Rajesh Bhagat wrote:
> >From 60ec8a88ba671fa0b424f7b4467dba3ea8a2a2c8 Mon Sep 17 00:00:00 2001
> From: Rajesh Bhagat <rajesh.lnx@gmail.com>
> Date: Tue, 20 Mar 2012 10:35:59 +0530
> Subject: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue
> 
> This patch resets the trace_array using tracing_reset_online_cpus, if same
> tracer is set again instead of just returning from funtion tracing_set_tracer.
> 
> problem description
> -------------------
> once function tracer is set, set_ftrace_filter not working.
> /debug/tracing # echo function > current_tracer
> /debug/tracing # echo schedule > set_ftrace_filter
> /debug/tracing # echo function > current_tracer

Sorry no. The correct way you want to do this is:

/debug/tracing # echo > trace

That will reset the buffer for you and give you the desired result.

-- Steve



> /debug/tracing #  cat trace
> # tracer: function
> #
> #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
> #              | |       |          |         |
>           <idle>-0     [000]    21.997778: irq_enter <-handle_IRQ
>           <idle>-0     [000]    21.997785: idle_cpu <-irq_enter
>           <idle>-0     [000]    21.997794: local_bh_disable <-irq_enter
>           <idle>-0     [000]    21.997800: tick_check_idle <-irq_enter
>           <idle>-0     [000]    21.997807:
> tick_check_oneshot_broadcast <-tick_check_idle
>           <idle>-0     [000]    21.997814: _local_bh_enable <-irq_enter
> 
> After applying this patch, only filtered functions are traced.
> 
> Signed-off-by: Rajesh Bhagat <rajesh.lnx@gmail.com>
> ---
>  kernel/trace/trace.c |    4 +++-
>  1 files changed, 3 insertions(+), 1 deletions(-)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index a3f1bc5..f4fb190 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -3058,8 +3058,10 @@ static int tracing_set_tracer(const char *buf)
>         ret = -EINVAL;
>         goto out;
>     }
> -   if (t == current_trace)
> +   if (t == current_trace) {
> +       tracing_reset_online_cpus(tr);
>         goto out;
> +   }
> 
>     trace_branch_disable();
>     if (current_trace && current_trace->reset)

Re: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

[Rajesh Bhagat]

Hi Steven,

Thanks for the reply.

I was wondering, why would a user reset the trace __explicitly__
without even using it.
That is why i created a patch for it.

>> /debug/tracing # echo function > current_tracer
>> /debug/tracing # cat trace <------ Not performed
>> /debug/tracing # echo schedule > set_ftrace_filter
>> /debug/tracing # echo function > current_trace
>> /debug/tracing # cat trace <------- Only this is performed

- Rajesh

On Sat, Mar 24, 2012 at 1:06 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Wed, 2012-03-21 at 11:22 +0530, Rajesh Bhagat wrote:
>> >From 60ec8a88ba671fa0b424f7b4467dba3ea8a2a2c8 Mon Sep 17 00:00:00 2001
>> From: Rajesh Bhagat <rajesh.lnx@gmail.com>
>> Date: Tue, 20 Mar 2012 10:35:59 +0530
>> Subject: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue
>>
>> This patch resets the trace_array using tracing_reset_online_cpus, if same
>> tracer is set again instead of just returning from funtion tracing_set_tracer.
>>
>> problem description
>> -------------------
>> once function tracer is set, set_ftrace_filter not working.
>> /debug/tracing # echo function > current_tracer
>> /debug/tracing # echo schedule > set_ftrace_filter
>> /debug/tracing # echo function > current_tracer
>
> Sorry no. The correct way you want to do this is:
>
> /debug/tracing # echo > trace
>
> That will reset the buffer for you and give you the desired result.
>
> -- Steve
>
>
>
>> /debug/tracing #  cat trace
>> # tracer: function
>> #
>> #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
>> #              | |       |          |         |
>>           <idle>-0     [000]    21.997778: irq_enter <-handle_IRQ
>>           <idle>-0     [000]    21.997785: idle_cpu <-irq_enter
>>           <idle>-0     [000]    21.997794: local_bh_disable <-irq_enter
>>           <idle>-0     [000]    21.997800: tick_check_idle <-irq_enter
>>           <idle>-0     [000]    21.997807:
>> tick_check_oneshot_broadcast <-tick_check_idle
>>           <idle>-0     [000]    21.997814: _local_bh_enable <-irq_enter
>>
>> After applying this patch, only filtered functions are traced.
>>
>> Signed-off-by: Rajesh Bhagat <rajesh.lnx@gmail.com>
>> ---
>>  kernel/trace/trace.c |    4 +++-
>>  1 files changed, 3 insertions(+), 1 deletions(-)
>>
>> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>> index a3f1bc5..f4fb190 100644
>> --- a/kernel/trace/trace.c
>> +++ b/kernel/trace/trace.c
>> @@ -3058,8 +3058,10 @@ static int tracing_set_tracer(const char *buf)
>>         ret = -EINVAL;
>>         goto out;
>>     }
>> -   if (t == current_trace)
>> +   if (t == current_trace) {
>> +       tracing_reset_online_cpus(tr);
>>         goto out;
>> +   }
>>
>>     trace_branch_disable();
>>     if (current_trace && current_trace->reset)
>
>

Re: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

[Rajesh Bhagat]

Hi Steven,

Just to add to it, This problem occurs only in case when same tracer
is enabled again i.e. function on function.
In other case code does not hit below code, and anyways
tracing_reset_online_cpus and trace->init is called to reset the
trace.

>>> -   if (t == current_trace)
>>> +   if (t == current_trace) {
>>> +       tracing_reset_online_cpus(tr);
>>>         goto out;
>>> +   }

My point is, this issue is specific to a situation i.e. same tracer
set again, hence making resetting the trace not a very obvious choice.

Please comment.

-Rajesh

On Sat, Mar 24, 2012 at 9:47 AM, Rajesh Bhagat <rajesh.lnx@gmail.com> wrote:
> Hi Steven,
>
> Thanks for the reply.
>
> I was wondering, why would a user reset the trace __explicitly__
> without even using it.
> That is why i created a patch for it.
>
>>> /debug/tracing # echo function > current_tracer
>>> /debug/tracing # cat trace <------ Not performed
>>> /debug/tracing # echo schedule > set_ftrace_filter
>>> /debug/tracing # echo function > current_trace
>>> /debug/tracing # cat trace <------- Only this is performed
>
> - Rajesh
>
> On Sat, Mar 24, 2012 at 1:06 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
>> On Wed, 2012-03-21 at 11:22 +0530, Rajesh Bhagat wrote:
>>> >From 60ec8a88ba671fa0b424f7b4467dba3ea8a2a2c8 Mon Sep 17 00:00:00 2001
>>> From: Rajesh Bhagat <rajesh.lnx@gmail.com>
>>> Date: Tue, 20 Mar 2012 10:35:59 +0530
>>> Subject: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue
>>>
>>> This patch resets the trace_array using tracing_reset_online_cpus, if same
>>> tracer is set again instead of just returning from funtion tracing_set_tracer.
>>>
>>> problem description
>>> -------------------
>>> once function tracer is set, set_ftrace_filter not working.
>>> /debug/tracing # echo function > current_tracer
>>> /debug/tracing # echo schedule > set_ftrace_filter
>>> /debug/tracing # echo function > current_tracer
>>
>> Sorry no. The correct way you want to do this is:
>>
>> /debug/tracing # echo > trace
>>
>> That will reset the buffer for you and give you the desired result.
>>
>> -- Steve
>>
>>
>>
>>> /debug/tracing #  cat trace
>>> # tracer: function
>>> #
>>> #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
>>> #              | |       |          |         |
>>>           <idle>-0     [000]    21.997778: irq_enter <-handle_IRQ
>>>           <idle>-0     [000]    21.997785: idle_cpu <-irq_enter
>>>           <idle>-0     [000]    21.997794: local_bh_disable <-irq_enter
>>>           <idle>-0     [000]    21.997800: tick_check_idle <-irq_enter
>>>           <idle>-0     [000]    21.997807:
>>> tick_check_oneshot_broadcast <-tick_check_idle
>>>           <idle>-0     [000]    21.997814: _local_bh_enable <-irq_enter
>>>
>>> After applying this patch, only filtered functions are traced.
>>>
>>> Signed-off-by: Rajesh Bhagat <rajesh.lnx@gmail.com>
>>> ---
>>>  kernel/trace/trace.c |    4 +++-
>>>  1 files changed, 3 insertions(+), 1 deletions(-)
>>>
>>> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>>> index a3f1bc5..f4fb190 100644
>>> --- a/kernel/trace/trace.c
>>> +++ b/kernel/trace/trace.c
>>> @@ -3058,8 +3058,10 @@ static int tracing_set_tracer(const char *buf)
>>>         ret = -EINVAL;
>>>         goto out;
>>>     }
>>> -   if (t == current_trace)
>>> +   if (t == current_trace) {
>>> +       tracing_reset_online_cpus(tr);
>>>         goto out;
>>> +   }
>>>
>>>     trace_branch_disable();
>>>     if (current_trace && current_trace->reset)
>>
>>

Re: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

[Steven Rostedt]

On Sat, 2012-03-24 at 09:47 +0530, Rajesh Bhagat wrote:
> Hi Steven,
> 
> Thanks for the reply.
> 
> I was wondering, why would a user reset the trace __explicitly__
> without even using it.
> That is why i created a patch for it.
> 
> >> /debug/tracing # echo function > current_tracer
      ^
      |
   user starts using tracer

> >> /debug/tracing # cat trace <------ Not performed
> >> /debug/tracing # echo schedule > set_ftrace_filter
> >> /debug/tracing # echo function > current_trace
> >> /debug/tracing # cat trace <------- Only this is performed

Why the first "echo function"? That means you just started using the
tracer. You can (and should) do:

	# echo schedule > set_ftrace_filter
	# echo function > current_tracer

This IIRC is the documented way of using it.

That said, I may consider taking the patch, as another way of resetting
the tracer. I have to see what workflows it will affect first.

-- Steve

Re: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

[Rajesh Bhagat]

Hi Steven,

Thanks a lot for you feedback.

- Rajesh

On Sat, Mar 24, 2012 at 7:25 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Sat, 2012-03-24 at 09:47 +0530, Rajesh Bhagat wrote:
>> Hi Steven,
>>
>> Thanks for the reply.
>>
>> I was wondering, why would a user reset the trace __explicitly__
>> without even using it.
>> That is why i created a patch for it.
>>
>> >> /debug/tracing # echo function > current_tracer
>      ^
>      |
>   user starts using tracer
>
>> >> /debug/tracing # cat trace <------ Not performed
>> >> /debug/tracing # echo schedule > set_ftrace_filter
>> >> /debug/tracing # echo function > current_trace
>> >> /debug/tracing # cat trace <------- Only this is performed
>
> Why the first "echo function"? That means you just started using the
> tracer. You can (and should) do:
>
>        # echo schedule > set_ftrace_filter
>        # echo function > current_tracer
>
> This IIRC is the documented way of using it.
>
> That said, I may consider taking the patch, as another way of resetting
> the tracer. I have to see what workflows it will affect first.
>
> -- Steve
>
>

Re: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

[Steven Rostedt]

On Wed, 2012-03-21 at 11:22 +0530, Rajesh Bhagat wrote:

> Signed-off-by: Rajesh Bhagat <rajesh.lnx@gmail.com>
> ---
>  kernel/trace/trace.c |    4 +++-
>  1 files changed, 3 insertions(+), 1 deletions(-)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index a3f1bc5..f4fb190 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -3058,8 +3058,10 @@ static int tracing_set_tracer(const char *buf)
>         ret = -EINVAL;
>         goto out;
>     }
> -   if (t == current_trace)
> +   if (t == current_trace) {
> +       tracing_reset_online_cpus(tr);
>         goto out;
> +   }

BTW, this patch has major whitespace problems. You need to fix your mail
client. For a trivial patch like this, I can fix up, but anything else
will become a major issue. And we do not accept attachments.

-- Steve

Re: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

[Steven Rostedt]

On Sat, 2012-03-24 at 09:55 -0400, Steven Rostedt wrote:

> That said, I may consider taking the patch, as another way of resetting
> the tracer. I have to see what workflows it will affect first.

This is what I was afraid of. The tracers irqsoff and preemptoff do not
get reset if you echo the tracer name into the current_tracer. This
makes different tracers inconsistent.

All tracers must act the same. So, it's a no go for this patch, at least
in its current form.

-- Steve

Re: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

[Rajesh Bhagat]

Hi Steven,

I'm really sorry for this. :(
I'm unable to configure git send mail yet :(
>From next time, i will send patch using git send mail ONLY.

-Rajesh

On Mon, Mar 26, 2012 at 10:43 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Wed, 2012-03-21 at 11:22 +0530, Rajesh Bhagat wrote:
>
>> Signed-off-by: Rajesh Bhagat <rajesh.lnx@gmail.com>
>> ---
>>  kernel/trace/trace.c |    4 +++-
>>  1 files changed, 3 insertions(+), 1 deletions(-)
>>
>> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>> index a3f1bc5..f4fb190 100644
>> --- a/kernel/trace/trace.c
>> +++ b/kernel/trace/trace.c
>> @@ -3058,8 +3058,10 @@ static int tracing_set_tracer(const char *buf)
>>         ret = -EINVAL;
>>         goto out;
>>     }
>> -   if (t == current_trace)
>> +   if (t == current_trace) {
>> +       tracing_reset_online_cpus(tr);
>>         goto out;
>> +   }
>
> BTW, this patch has major whitespace problems. You need to fix your mail
> client. For a trivial patch like this, I can fix up, but anything else
> will become a major issue. And we do not accept attachments.
>
> -- Steve
>
>

Re: [PATCH 1/1] ftrace: fix dynamic ftrace filter reset issue

[Rajesh Bhagat]

Hi Steven,

Thanks for your feedback.
I will work on the V2 of this patch to get the mentioned issue resolved.

- Rajesh


On Mon, Mar 26, 2012 at 11:15 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Sat, 2012-03-24 at 09:55 -0400, Steven Rostedt wrote:
>
>> That said, I may consider taking the patch, as another way of resetting
>> the tracer. I have to see what workflows it will affect first.
>
> This is what I was afraid of. The tracers irqsoff and preemptoff do not
> get reset if you echo the tracer name into the current_tracer. This
> makes different tracers inconsistent.
>
> All tracers must act the same. So, it's a no go for this patch, at least
> in its current form.
>
> -- Steve
>
>