On Tue, Dec 14, 2021 at 09:36:52AM -0500, Steven Rostedt wrote:
> On Tue, 14 Dec 2021 15:03:00 +0100
> Sebastian Andrzej Siewior <bigeasy@xxxxxxxxxxxxx> wrote:
>
> > Luca Abeni reported this:
> > | BUG: scheduling while atomic: kworker/u8:2/15203/0x00000003
> > | CPU: 1 PID: 15203 Comm: kworker/u8:2 Not tainted 4.19.1-rt3 #10
> > | Call Trace:
> > | rt_spin_lock+0x3f/0x50
> > | gen6_read32+0x45/0x1d0 [i915]
> > | g4x_get_vblank_counter+0x36/0x40 [i915]
> > | trace_event_raw_event_i915_pipe_update_start+0x7d/0xf0 [i915]
> >
> > The tracing events use trace_i915_pipe_update_start() among other events
> > use functions acquire spinlock_t locks which are transformed into
> > sleeping locks on PREEMPT_RT. A few trace points use
> > intel_get_crtc_scanline(), others use ->get_vblank_counter() wich also
> > might acquire a sleeping locks on PREEMPT_RT.
> > At the time the arguments are evaluated within trace point, preemption
> > is disabled and so the locks must not be acquired on PREEMPT_RT.
> >
> > Based on this I don't see any other way than disable trace points on
> > PREMPT_RT.
>
> Another way around this that I can see is if the data for the tracepoints
> can fit on the stack and add wrappers around the tracepoints. For example,
> looking at the first tracepoint in i915_trace.h:
>
> TRACE_EVENT(intel_pipe_enable,
> TP_PROTO(struct intel_crtc *crtc),
> TP_ARGS(crtc),
>
> TP_STRUCT__entry(
> __array(u32, frame, 3)
> __array(u32, scanline, 3)
> __field(enum pipe, pipe)
> ),
> TP_fast_assign(
> struct drm_i915_private *dev_priv = to_i915(crtc->base.dev);
> struct intel_crtc *it__;
> for_each_intel_crtc(&dev_priv->drm, it__) {
> __entry->frame[it__->pipe] = intel_crtc_get_vblank_counter(it__);
> __entry->scanline[it__->pipe] = intel_get_crtc_scanline(it__);
> }
> __entry->pipe = crtc->pipe;
> ),
>
> TP_printk("pipe %c enable, pipe A: frame=%u, scanline=%u, pipe B: frame=%u, scanline=%u, pipe C: frame=%u, scanline=%u",
> pipe_name(__entry->pipe),
> __entry->frame[PIPE_A], __entry->scanline[PIPE_A],
> __entry->frame[PIPE_B], __entry->scanline[PIPE_B],
> __entry->frame[PIPE_C], __entry->scanline[PIPE_C])
> );
>
> We could modify this to be:
>
> TRACE_EVENT(intel_pipe_enable,
> TP_PROTO(u32 *frame, u32 *scanline, enum pipe),
> TP_ARGS(frame, scanline, pipe),
>
> TP_STRUCT__entry(
> __array(u32, frame, 3)
> __array(u32, scanline, 3)
> __field(enum pipe, pipe)
> ),
> TP_fast_assign(
> int i;
> for (i = 0; i < 3; i++) {
> __entry->frame[i] = frame[i];
> __entry->scanline[i] = scanline[i];
> }
> __entry->pipe = pipe;
> ),
>
> TP_printk("pipe %c enable, pipe A: frame=%u, scanline=%u, pipe B: frame=%u, scanline=%u, pipe C: frame=%u, scanline=%u",
> pipe_name(__entry->pipe),
> __entry->frame[PIPE_A], __entry->scanline[PIPE_A],
> __entry->frame[PIPE_B], __entry->scanline[PIPE_B],
> __entry->frame[PIPE_C], __entry->scanline[PIPE_C])
> );
>
>
> static inline void do_trace_intel_pipe(struct intel_crtc *crtc)
> {
> u32 frame[3];
> u32 scanline[3];
> enum pipe pipe;
>
> if (!trace_intel_pipe_enable_enabled())
> return;
>
> struct drm_i915_private *dev_priv = to_i915(crtc->base.dev);
> struct intel_crtc *it__;
> for_each_intel_crtc(&dev_priv->drm, it__) {
> frame[it__->pipe] = intel_crtc_get_vblank_counter(it__);
> scanline[it__->pipe] = intel_get_crtc_scanline(it__);
> }
>
> trace_intel_pipe(frame, scanline, crtc->pipe);
> }
Looks lightly tedious. Can't we have "slow" (or whatever) versions of
the trace macros so we could just declare these the same was as before
without having to manually write that wrapper for every event?
--
Ville Syrjälä
Intel
