[PATCH v2 5/5] drm/vblank: Add some debugging trace events

[<sunpeng.li@amd.com>]

From: Leo Li <sunpeng.li@amd.com>

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 <sunpeng.li@amd.com>
---
 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 4b73ccde35425..3a010ee1a6596 100644
--- a/drivers/gpu/drm/drm_vblank.c
+++ b/drivers/gpu/drm/drm_vblank.c
@@ -1266,6 +1266,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);
 
@@ -1295,6 +1297,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);
 
@@ -1324,10 +1328,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);
 
@@ -1348,11 +1356,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);
@@ -1408,6 +1420,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;
@@ -1415,18 +1429,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));
 	}
@@ -1518,6 +1535,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(). */
@@ -1659,6 +1678,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;
 
@@ -2135,11 +2156,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.53.0