From: Leo Li <[email protected]>
It's useful to trace vblank get/put and enable/disable (plus their
deferred variants) when debugging. The trace stack feature for events
can be especially useful.
Using trace-cmd, one can obtain a trace like so:
trace-cmd record -e drm_vblank*
# With deferred events and stack info:
trace-cmd record -e drm_vblank* -e drm_deferred_vblank* -T
Signed-off-by: Leo Li <[email protected]>
---
drivers/gpu/drm/drm_trace.h | 112 +++++++++++++++++++++++++++++++++++
drivers/gpu/drm/drm_vblank.c | 34 +++++++++--
2 files changed, 140 insertions(+), 6 deletions(-)
diff --git a/drivers/gpu/drm/drm_trace.h b/drivers/gpu/drm/drm_trace.h
index 11c6dd577e8ed..3372513a10eeb 100644
--- a/drivers/gpu/drm/drm_trace.h
+++ b/drivers/gpu/drm/drm_trace.h
@@ -66,6 +66,118 @@ TRACE_EVENT(drm_vblank_event_delivered,
__entry->seq)
);
+DECLARE_EVENT_CLASS(drm_vblank_get_put_template,
+ TP_PROTO(int crtc, int refcount),
+ TP_ARGS(crtc, refcount),
+ TP_STRUCT__entry(
+ __field(int, crtc)
+ __field(int, refcount)
+ ),
+ TP_fast_assign(
+ __entry->crtc = crtc;
+ __entry->refcount = refcount;
+ ),
+ TP_printk(
+ "crtc=%d, refcount=%u",
+ __entry->crtc, __entry->refcount
+ )
+);
+
+DEFINE_EVENT(drm_vblank_get_put_template, drm_vblank_get,
+ TP_PROTO(int crtc, int refcount),
+ TP_ARGS(crtc, refcount));
+
+/* put's refcount not sync'd using vbl_lock, use for debugging purposes only */
+DEFINE_EVENT(drm_vblank_get_put_template, drm_vblank_put,
+ TP_PROTO(int crtc, int refcount),
+ TP_ARGS(crtc, refcount));
+
+DECLARE_EVENT_CLASS(drm_vblank_on_off_template,
+ TP_PROTO(int crtc, int refcount, bool enabled, bool
inmodeset),
+ TP_ARGS(crtc, refcount, enabled, inmodeset),
+ TP_STRUCT__entry(
+ __field(int, crtc)
+ __field(int, refcount)
+ __field(bool, enabled)
+ __field(bool, inmodeset)
+ ),
+ TP_fast_assign(
+ __entry->crtc = crtc;
+ __entry->refcount = refcount;
+ __entry->enabled = enabled;
+ __entry->inmodeset = inmodeset;
+ ),
+ TP_printk(
+ "crtc=%d, refcount=%u, enabled=%s, inmodeset=%s",
+ __entry->crtc, __entry->refcount,
+ __entry->enabled ? "true" : "false",
+ __entry->inmodeset ? "true" : "false"
+ )
+);
+
+DEFINE_EVENT(drm_vblank_on_off_template, drm_vblank_on,
+ TP_PROTO(int crtc, int refcount, bool enabled, bool inmodeset),
+ TP_ARGS(crtc, refcount, enabled, inmodeset));
+
+DEFINE_EVENT(drm_vblank_on_off_template, drm_vblank_off,
+ TP_PROTO(int crtc, int refcount, bool enabled, bool inmodeset),
+ TP_ARGS(crtc, refcount, enabled, inmodeset));
+
+DECLARE_EVENT_CLASS(drm_deferred_vblank_template,
+ TP_PROTO(int crtc),
+ TP_ARGS(crtc),
+ TP_STRUCT__entry(
+ __field(int, crtc)
+ ),
+ TP_fast_assign(
+ __entry->crtc = crtc;
+ ),
+ TP_printk(
+ "crtc=%d",
+ __entry->crtc
+ )
+);
+
+DEFINE_EVENT(drm_deferred_vblank_template, drm_deferred_vblank_enable_queued,
+ TP_PROTO(int crtc),
+ TP_ARGS(crtc));
+
+DEFINE_EVENT(drm_deferred_vblank_template, drm_deferred_vblank_enable,
+ TP_PROTO(int crtc),
+ TP_ARGS(crtc));
+
+TRACE_EVENT(drm_deferred_vblank_disable_queued,
+ TP_PROTO(int crtc, int delay_ms),
+ TP_ARGS(crtc, delay_ms),
+ TP_STRUCT__entry(
+ __field(int, crtc)
+ __field(int, delay_ms)
+ ),
+ TP_fast_assign(
+ __entry->crtc = crtc;
+ __entry->delay_ms = delay_ms;
+ ),
+ TP_printk(
+ "crtc=%d, delay_ms=%d",
+ __entry->crtc,
+ __entry->delay_ms
+ )
+);
+
+DEFINE_EVENT(drm_deferred_vblank_template, drm_deferred_vblank_disable,
+ TP_PROTO(int crtc),
+ TP_ARGS(crtc));
+
+DEFINE_EVENT(drm_deferred_vblank_template,
+ drm_deferred_vblank_wait_enable_start,
+ TP_PROTO(int crtc),
+ TP_ARGS(crtc));
+
+DEFINE_EVENT(drm_deferred_vblank_template,
+ drm_deferred_vblank_wait_enable_end,
+ TP_PROTO(int crtc),
+ TP_ARGS(crtc));
+
#endif /* _DRM_TRACE_H_ */
/* This part must be outside protection */
diff --git a/drivers/gpu/drm/drm_vblank.c b/drivers/gpu/drm/drm_vblank.c
index db17800f58e03..afa918c508bef 100644
--- a/drivers/gpu/drm/drm_vblank.c
+++ b/drivers/gpu/drm/drm_vblank.c
@@ -1265,6 +1265,8 @@ static void drm_vblank_deferred_enable_worker(struct
work_struct *work)
if (drm_WARN_ON(dev, !crtc))
return;
+ trace_drm_deferred_vblank_enable(crtc->index);
+
if (crtc->funcs->pre_enable_vblank)
crtc->funcs->pre_enable_vblank(crtc);
@@ -1294,6 +1296,8 @@ static void drm_vblank_deferred_disable_worker(struct
work_struct *work)
if (drm_WARN_ON(dev, !crtc))
return;
+ trace_drm_deferred_vblank_disable(crtc->index);
+
if (crtc->funcs->pre_disable_vblank)
crtc->funcs->pre_disable_vblank(crtc);
@@ -1323,10 +1327,14 @@ void drm_crtc_vblank_wait_deferred_enable(struct
drm_crtc *crtc)
if (!drm_crtc_needs_deferred_vblank(crtc))
return;
+ trace_drm_deferred_vblank_wait_enable_start(crtc->index);
+
if (!wait_for_completion_timeout(&vblank->enable_done,
msecs_to_jiffies(1000)))
drm_err(crtc->dev, "CRTC-%d: Timed out waiting for deferred
vblank enable\n",
drm_crtc_index(crtc));
+
+ trace_drm_deferred_vblank_wait_enable_end(crtc->index);
}
EXPORT_SYMBOL(drm_crtc_vblank_wait_deferred_enable);
@@ -1347,11 +1355,15 @@ int drm_vblank_get(struct drm_device *dev, unsigned int
pipe)
drm_crtc_needs_deferred_vblank(drm_crtc_from_index(dev, pipe));
spin_lock_irqsave(&dev->vbl_lock, irqflags);
+
+ trace_drm_vblank_get(pipe, atomic_read(&vblank->refcount));
+
/* Going from 0->1 means we have to enable interrupts again */
if (atomic_add_return(1, &vblank->refcount) == 1) {
if (needs_deferred_enable) {
/* Arm completion before queueing deferred enable */
reinit_completion(&vblank->enable_done);
+ trace_drm_deferred_vblank_enable_queued(pipe);
queue_work(dev->deferred_vblank_wq,
&vblank->enable_work);
} else {
ret = drm_vblank_enable(dev, pipe);
@@ -1398,6 +1410,8 @@ void drm_vblank_put(struct drm_device *dev, unsigned int
pipe)
needs_deferred_disable =
drm_crtc_needs_deferred_vblank(drm_crtc_from_index(dev, pipe));
+ trace_drm_vblank_put(pipe, atomic_read(&vblank->refcount));
+
/* Last user schedules interrupt disable */
if (!atomic_dec_and_test(&vblank->refcount))
return;
@@ -1405,18 +1419,21 @@ void drm_vblank_put(struct drm_device *dev, unsigned
int pipe)
if (!vblank_offdelay)
return;
else if (vblank_offdelay < 0) {
- if (needs_deferred_disable)
+ if (needs_deferred_disable) {
+ trace_drm_deferred_vblank_disable_queued(pipe, 0);
mod_delayed_work(dev->deferred_vblank_wq,
&vblank->disable_work,
0);
- else
+ } else
vblank_disable_fn(&vblank->disable_timer);
} else if (!vblank->config.disable_immediate) {
- if (needs_deferred_disable)
+ if (needs_deferred_disable) {
+ trace_drm_deferred_vblank_disable_queued(
+ pipe, vblank_offdelay);
mod_delayed_work(dev->deferred_vblank_wq,
&vblank->disable_work,
msecs_to_jiffies(vblank_offdelay));
- else
+ } else
mod_timer(&vblank->disable_timer,
jiffies + ((vblank_offdelay * HZ) / 1000));
}
@@ -1508,6 +1525,8 @@ void drm_crtc_vblank_off(struct drm_crtc *crtc)
spin_lock(&dev->vbl_lock);
drm_dbg_vbl(dev, "crtc %d, vblank enabled %d, inmodeset %d\n",
pipe, vblank->enabled, vblank->inmodeset);
+ trace_drm_vblank_off(pipe, atomic_read(&vblank->refcount),
+ vblank->enabled, vblank->inmodeset);
/* Avoid redundant vblank disables without previous
* drm_crtc_vblank_on(). */
@@ -1649,6 +1668,8 @@ void drm_crtc_vblank_on_config(struct drm_crtc *crtc,
spin_lock_irq(&dev->vbl_lock);
drm_dbg_vbl(dev, "crtc %d, vblank enabled %d, inmodeset %d\n",
pipe, vblank->enabled, vblank->inmodeset);
+ trace_drm_vblank_on(pipe, atomic_read(&vblank->refcount),
+ vblank->enabled, vblank->inmodeset);
vblank->config = *config;
@@ -2123,11 +2144,12 @@ bool drm_handle_vblank(struct drm_device *dev, unsigned
int pipe)
spin_unlock_irqrestore(&dev->event_lock, irqflags);
if (disable_irq) {
- if (drm_crtc_needs_deferred_vblank(drm_crtc_from_index(dev,
pipe)))
+ if (drm_crtc_needs_deferred_vblank(drm_crtc_from_index(dev,
pipe))) {
+ trace_drm_deferred_vblank_disable_queued(pipe, 0);
mod_delayed_work(dev->deferred_vblank_wq,
&vblank->disable_work,
0);
- else
+ } else
vblank_disable_fn(&vblank->disable_timer);
}
--
2.52.0
