Received-SPF: pass (google.com: domain of linux-kernel+bounces-57855-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.48.161 as permitted sender) client-ip=147.75.48.161;
Message-ID: <8c986cb3-61b3-4f65-81c9-ffcfa994390f@linux.ibm.com>
Date: Thu, 8 Feb 2024 11:25:50 +0100
Precedence: bulk
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Subject: Re: [PATCH] tracing: use ring_buffer_record_is_set_on() in
 tracer_tracing_is_on()
Content-Language: en-US
To: Steven Rostedt <rostedt@goodmis.org>, Sven Schnelle <svens@linux.ibm.com>
Cc: Masami Hiramatsu <mhiramat@kernel.org>,
        Mathieu Desnoyers <mathieu.desnoyers@efficios.com>,
        linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org
References: <20240205065340.2848065-1-svens@linux.ibm.com>
 <20240205075504.1b55f29c@rorschach.local.home>
 <yt9djznj3vbl.fsf@linux.ibm.com>
 <20240205092353.523cc1ef@rorschach.local.home>
 <yt9d34u63xxz.fsf@linux.ibm.com> <yt9dsf262d2n.fsf@linux.ibm.com>
 <20240206060113.39c0f5bc@rorschach.local.home>
 <yt9deddovn3w.fsf@linux.ibm.com>
 <20240207060923.182ecb55@rorschach.local.home>
 <9a062196-ccbe-440e-a2f9-23eb8c5eb837@linux.ibm.com>
 <20240207072812.4a29235f@rorschach.local.home>
 <yt9dzfwch00u.fsf@linux.ibm.com>
 <20240207104703.071ee985@rorschach.local.home>
From: Mete Durlu <meted@linux.ibm.com>
In-Reply-To: <20240207104703.071ee985@rorschach.local.home>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit

On 2/7/24 16:47, Steven Rostedt wrote:
> On Wed, 07 Feb 2024 14:33:21 +0100
> Sven Schnelle <svens@linux.ibm.com> wrote:
> 
>> My assumption without reading the code is that something like this
>> happens:
>>
>> CPU0                             CPU1
>> [ringbuffer enabled]
>>                                   ring_buffer_write()
>>                                       if (atomic_read(&buffer->record_disabled))
>>                                              goto out;
>> echo 0 > tracing_on
>> record_disabled |= RB_BUFFER_OFF
>> csum1=`md5sum trace`
> 
> Note, the CPU1 is performing with preemption disabled, so for this to
> happen, something really bad happened on CPU0 to delay preempt disabled
> section so long to allow the trace to be read. Perhaps we should have
> the return of the echo 0 > tracing_on require a synchronize_rcu() to
> make sure all ring buffers see it disabled before it returns.
> 
> But unless your system is doing something really stressed to cause the
> preempt disabled section to take so long, I highly doubt this was the
> race.
> 

I have been only able to reliably reproduce this issue when the system
is under load from stressors. But I am not sure if it can be considered
as *really stressed*.

system : 8 cpus (4 physical cores)
load   : stress-ng --fanotify 1 (or --context 2)
result : ~5/10 test fails

of course as load increases test starts to fail more often, but a
single stressor doesn't seem like much to me for a 4 core machine.

after adding synchronize_rcu() + patch from Sven, I am no longer seeing
failures with the setup above. So it seems like synchronize_rcu() did
the trick(or at least it helps a lot) for the case described on the
previous mail. I couldn't trigger the failure yet, not even with
increased load(but now the test case takes > 5mins to finish :) ).

Here is the diff:

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
@@ -9328,10 +9328,12 @@ rb_simple_write(struct file *filp, const char 
__user *ubuf,
                         val = 0; /* do nothing */
                 } else if (val) {
                         tracer_tracing_on(tr);
+                       synchronize_rcu();
                         if (tr->current_trace->start)
                                 tr->current_trace->start(tr);
                 } else {
                         tracer_tracing_off(tr);
+                       synchronize_rcu();
                         if (tr->current_trace->stop)
                                 tr->current_trace->stop(tr);

Not 100% sure if these were the correct places to add them.