Message-ID: <20210312211353.422067021@goodmis.org>
Date:   Fri, 12 Mar 2021 16:13:53 -0500
From:   Steven Rostedt <rostedt@...dmis.org>
To:     linux-kernel@...r.kernel.org
Cc:     Ingo Molnar <mingo@...nel.org>,
        Andrew Morton <akpm@...ux-foundation.org>,
        "Zanussi, Tom" <tom.zanussi@...ux.intel.com>,
        Masami Hiramatsu <mhiramat@...nel.org>,
        "Yordan Karadzhov" <y.karadz@...il.com>
Subject: [PATCH 0/7] tracing: Have ring_buffer_event_time_stamp() work for all events


Yordan has been working on a patch set that will not repeat functions
in the function tracer but instead show a single event that states that
the previous function repeated X amount of times. I recommended that
this should also show the time of the last function that repeated.
To save on space, Yordan suggested to use a 32 bit delta instead of
a full 64 bit timestamp of the last event. But to create this delta,
we need a way to extract the time of the repeat event and use that
to calculate the delta of the last function event.

But currently the ring_buffer_event_time_stamp() only works if all events
has an absolute time stamp attached to it. That would be counter productive
to make all functions record the full time stamp because we wanted to
use a 32 bit counter instead of a 64 bit counter for the rare repeat event!

This patch series makes ring_buffer_event_time_stamp() work for all
non committed events (after reserve and before it is committed).
The trick is that the per CPU descriptor of the buffer holds the time
stamp used for the event being processed. It has a nesting of 5 levels
to deal with interrupts that add events. Extracting the time for the event
can only be done for the current event being processed and not yet
committed.

To achieve this, the buffer that the event is on needs to be passed to
the ring_buffer_event_time_stamp(). That caused a bit of churn for
the histogram code, because that buffer wasn't available at the time
the ring_buffer_event_time_stamp() was called. Although the hist_field
contained a pointer to the trace_array that holds the ring buffer,
if tracing was disabled, then a temporary buffer was used instead,
and that temporary buffer would need to be passed to the
ring_buffer_event_time_stamp(). That buffer is exposed to the trace event
logic, but was not passed down into the trigger code. That had to be
done to take advantage of the new code.

The second to last patch adds verifier logic (although commented out)
that was used to debug the issue when a temporary buffer was in use.
It proved to be very valuable and is kept in, in case this needs to be
debugged again.

Finally the last patch is for use with Yordan's work, and is needed because
when filtering is enabled, the event being processed may not even be
on the buffer, and the tracing_event_time_stamp() checks for that and
will just use the current time stamp if the event is not reserved yet.
This could be used also for the histogram code, but wanted to hold off
on that.

Steven Rostedt (VMware) (7):
      ring-buffer: Separate out internal use of ring_buffer_event_time_stamp()
      ring-buffer: Add a event_stamp to cpu_buffer for each level of nesting
      tracing: Pass buffer of event to trigger operations
      ring-buffer: Allow ring_buffer_event_time_stamp() to return time stamp of all events
      tracing: Use a no_filter_buffering_ref to stop using the filter buffer
      ring-buffer: Add verifier for using ring_buffer_event_time_stamp()
      tracing: Add tracing_event_time_stamp() API

----
 include/linux/ring_buffer.h         |   3 +-
 include/linux/trace_events.h        |   5 +-
 kernel/trace/ring_buffer.c          | 138 ++++++++++++++++++++++++++++++------
 kernel/trace/trace.c                |  40 ++++++-----
 kernel/trace/trace.h                |   9 +--
 kernel/trace/trace_events_hist.c    |  97 ++++++++++++++++---------
 kernel/trace/trace_events_trigger.c |  45 +++++++-----
 7 files changed, 239 insertions(+), 98 deletions(-)

Powered by blists - more mailing lists