Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::3:2 as permitted sender) client-ip=2620:137:e000::3:2;
From:   Jiri Olsa <olsajiri@gmail.com>
Date:   Thu, 2 Nov 2023 09:50:05 +0100
To:     Steven Rostedt <rostedt@goodmis.org>
Cc:     Jiri Olsa <olsajiri@gmail.com>,
        "Masami Hiramatsu (Google)" <mhiramat@kernel.org>,
        Florent Revest <revest@chromium.org>,
        linux-trace-kernel@vger.kernel.org, bpf@vger.kernel.org,
        linux-kernel@vger.kernel.org
Subject: Re: [QUESTION] ftrace_test_recursion_trylock behaviour
Message-ID: <ZUNivSK2brywL0J6@krava>
References: <ZUKLnmYyHpthlMEE@krava>
 <20231101134556.5d4a46c3@gandalf.local.home>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20231101134556.5d4a46c3@gandalf.local.home>
Precedence: bulk

On Wed, Nov 01, 2023 at 01:45:56PM -0400, Steven Rostedt wrote:
> On Wed, 1 Nov 2023 18:32:14 +0100
> Jiri Olsa <olsajiri@gmail.com> wrote:
> 
> > hi,
> > I'm doing some testing on top of fprobes and noticed that the
> > ftrace_test_recursion_trylock allows caller from the same context
> > going through twice.
> > 
> > The change below adds extra fprobe on stack_trace_print, which is
> > called within the sample_entry_handler and I can see it being executed
> > with following trace output:
> > 
> >            <...>-457     [003] ...1.    32.352554: sample_entry_handler:
> > Enter <kernel_clone+0x0/0x380> ip = 0xffffffff81177420 <...>-457
> > [003] ...2.    32.352578: sample_entry_handler_extra: Enter
> > <stack_trace_print+0x0/0x60> ip = 0xffffffff8127ae70
> > 
> > IOW nested ftrace_test_recursion_trylock call in the same context
> > succeeded.
> > 
> > It seems the reason is the TRACE_CTX_TRANSITION bit logic.
> > 
> > Just making sure it's intentional.. we have kprobe_multi code on top of
> > fprobe with another re-entry logic and that might behave differently based
> > on ftrace_test_recursion_trylock logic.
> 
> Yes it's intentional, as it's a work around for an issue that may be
> cleared up now with Peter Zijlstra's noinstr updates.
> 
> The use case for that TRACE_CTX_TRANSITION is when a function is traced
> just after an interrupt was triggered but before the preempt count was
> updated to let us know that we are in an interrupt context.
> 
> Daniel Bristot reported a regression after the trylock was first introduced
> where the interrupt entry function was traced sometimes but not always.
> That's because if the interrupt happened normally, it would be traced, but
> if the interrupt happened when another event was being traced, the recursion
> logic would see that the trace of the interrupt was happening in the same
> context as the event it interrupted and drop the interrupt trace. But after
> the preempt count was updated, the other functions in the interrupt would be
> seen. This led to very confusing trace output.
> 
> The solution to that was this workaround hack, where the trace recursion
> logic would allow a single recursion (the interrupt preempting another
> trace before it set preempt count).
> 
> But with noinstr, there should be no more instances of this problem and we
> can drop that extra bit. But the last I checked, there were a few places
> that still could be traced without the preempt_count set. I'll have to
> re-investigate.

I see, so I'll keep in mind that it could change in the future

thanks,
jirka