[PATCH] HAX:drm: Logging vblank and page flip events in trace
Mohammed Khajapasha
mohammed.khajapasha at intel.com
Tue Apr 14 18:39:08 UTC 2020
Logging vblank and page flip events in trace
Test-with: 20200414183756.23625-1-mohammed.khajapasha at intel.com
Signed-off-by: Mohammed Khajapasha <mohammed.khajapasha at intel.com>
---
drivers/gpu/drm/drm_atomic_helper.c | 8 ++++
drivers/gpu/drm/drm_file.c | 32 +++++++++++++++
drivers/gpu/drm/drm_vblank.c | 42 +++++++++++++++++---
drivers/gpu/drm/i915/display/intel_display.c | 1 +
drivers/gpu/drm/i915/i915_irq.c | 3 ++
5 files changed, 81 insertions(+), 5 deletions(-)
diff --git a/drivers/gpu/drm/drm_atomic_helper.c b/drivers/gpu/drm/drm_atomic_helper.c
index 4511c2e07bb9d..deb091815537c 100644
--- a/drivers/gpu/drm/drm_atomic_helper.c
+++ b/drivers/gpu/drm/drm_atomic_helper.c
@@ -2052,12 +2052,14 @@ int drm_atomic_helper_setup_commit(struct drm_atomic_state *state,
* new CRTC state is active. Complete right away if everything
* stays off. */
if (!old_crtc_state->active && !new_crtc_state->active) {
+ trace_printk("Signaling flip_done while new/old crtc is inactive\n");
complete_all(&commit->flip_done);
continue;
}
/* Legacy cursor updates are fully unsynced. */
if (state->legacy_cursor_update) {
+ trace_printk("Signaling flip_done for legacy cursor update\n");
complete_all(&commit->flip_done);
continue;
}
@@ -2153,6 +2155,8 @@ void drm_atomic_helper_wait_for_dependencies(struct drm_atomic_state *old_state)
/* Currently no support for overwriting flips, hence
* stall for previous one to execute completely. */
+ trace_printk("Wating to complete previous flip\n");
+
ret = wait_for_completion_timeout(&commit->flip_done,
10*HZ);
if (ret == 0)
@@ -2174,6 +2178,7 @@ void drm_atomic_helper_wait_for_dependencies(struct drm_atomic_state *old_state)
/* Currently no support for overwriting flips, hence
* stall for previous one to execute completely. */
+ trace_printk("Wating to complete previous flip\n");
ret = wait_for_completion_timeout(&commit->flip_done,
10*HZ);
if (ret == 0)
@@ -2195,6 +2200,7 @@ void drm_atomic_helper_wait_for_dependencies(struct drm_atomic_state *old_state)
/* Currently no support for overwriting flips, hence
* stall for previous one to execute completely. */
+ trace_printk("Wating to complete previous flip\n");
ret = wait_for_completion_timeout(&commit->flip_done,
10*HZ);
if (ret == 0)
@@ -2234,6 +2240,8 @@ void drm_atomic_helper_fake_vblank(struct drm_atomic_state *old_state)
spin_lock_irqsave(&old_state->dev->event_lock, flags);
if (new_crtc_state->event) {
+ trace_printk("Send vblank after atomic commit at time:%lld\n",
+ ktime_get());
drm_crtc_send_vblank_event(crtc,
new_crtc_state->event);
new_crtc_state->event = NULL;
diff --git a/drivers/gpu/drm/drm_file.c b/drivers/gpu/drm/drm_file.c
index 92d16724f9495..80b1fed10dc87 100644
--- a/drivers/gpu/drm/drm_file.c
+++ b/drivers/gpu/drm/drm_file.c
@@ -43,6 +43,7 @@
#include <drm/drm_drv.h>
#include <drm/drm_file.h>
#include <drm/drm_print.h>
+#include <drm/drm_vblank.h>
#include "drm_crtc_internal.h"
#include "drm_internal.h"
@@ -611,12 +612,25 @@ int drm_event_reserve_init_locked(struct drm_device *dev,
struct drm_pending_event *p,
struct drm_event *e)
{
+ struct drm_pending_vblank_event *pvblank_event;
+
+ pvblank_event = container_of(p, struct drm_pending_vblank_event, base);
+
if (file_priv->event_space < e->length)
return -ENOMEM;
file_priv->event_space -= e->length;
p->event = e;
+
+ if (e->type == DRM_EVENT_FLIP_COMPLETE)
+ trace_printk("Adding flip complete event to pending event list seq:%llu \
+ pipe:%u\n", pvblank_event->sequence, pvblank_event->pipe);
+
+ if (e->type == DRM_EVENT_VBLANK)
+ trace_printk("Adding vblank event to pending event list seq:%llu \
+ pipe:%u\n", pvblank_event->sequence, pvblank_event->pipe);
+
list_add(&p->pending_link, &file_priv->pending_event_list);
p->file_priv = file_priv;
@@ -707,8 +721,14 @@ EXPORT_SYMBOL(drm_event_cancel_free);
*/
void drm_send_event_locked(struct drm_device *dev, struct drm_pending_event *e)
{
+ struct drm_pending_vblank_event *pvblank_event;
+ struct drm_event *evnt;
+
assert_spin_locked(&dev->event_lock);
+ pvblank_event = container_of(e, struct drm_pending_vblank_event, base);
+ evnt = e->event;
+
if (e->completion) {
complete_all(e->completion);
e->completion_release(e->completion);
@@ -726,8 +746,20 @@ void drm_send_event_locked(struct drm_device *dev, struct drm_pending_event *e)
}
list_del(&e->pending_link);
+
+ if (evnt->type == DRM_EVENT_FLIP_COMPLETE)
+ trace_printk("Moved page flip event with sequence:%llu crtc:%u to ready event_list\n", \
+ pvblank_event->sequence, pvblank_event->pipe);
+ if (evnt->type == DRM_EVENT_VBLANK)
+ trace_printk("Moved page flip event with sequence:%llu crtc:%u to ready event_list\n", \
+ pvblank_event->sequence, pvblank_event->pipe);
+
list_add_tail(&e->link,
&e->file_priv->event_list);
+
+ trace_printk("Wake up event wait queue at vblank:%llu crtc:%u\n", \
+ pvblank_event->sequence, pvblank_event->pipe);
+
wake_up_interruptible(&e->file_priv->event_wait);
}
EXPORT_SYMBOL(drm_send_event_locked);
diff --git a/drivers/gpu/drm/drm_vblank.c b/drivers/gpu/drm/drm_vblank.c
index 1659b13b178c2..f713dd2600925 100644
--- a/drivers/gpu/drm/drm_vblank.c
+++ b/drivers/gpu/drm/drm_vblank.c
@@ -167,6 +167,7 @@ static void drm_reset_vblank_timestamp(struct drm_device *dev, unsigned int pipe
* sample the current counter to avoid random jumps
* when drm_vblank_enable() applies the diff
*/
+ trace_printk("Get last vblank time stamp {%s}\n", __func__);
do {
cur_vblank = __get_vblank_counter(dev, pipe);
rc = drm_get_last_vbltimestamp(dev, pipe, &t_vblank, false);
@@ -271,9 +272,9 @@ static void drm_update_vblank_count(struct drm_device *dev, unsigned int pipe,
}
DRM_DEBUG_VBL("updating vblank count on crtc %u:"
- " current=%llu, diff=%u, hw=%u hw_last=%u\n",
+ " current=%llu, diff=%u, hw=%u hw_last=%u time=%lld\n",
pipe, atomic64_read(&vblank->count), diff,
- cur_vblank, vblank->last);
+ cur_vblank, vblank->last,t_vblank);
if (diff == 0) {
WARN_ON_ONCE(cur_vblank != vblank->last);
@@ -336,7 +337,7 @@ u64 drm_crtc_accurate_vblank_count(struct drm_crtc *crtc)
"This function requires support for accurate vblank timestamps.");
spin_lock_irqsave(&dev->vblank_time_lock, flags);
-
+ trace_printk("Update vblank count {%s}\n", __func__);
drm_update_vblank_count(dev, pipe, false);
vblank = drm_vblank_count(dev, pipe);
@@ -397,6 +398,7 @@ void drm_vblank_disable_and_save(struct drm_device *dev, unsigned int pipe)
* this time. This makes the count account for the entire time
* between drm_crtc_vblank_on() and drm_crtc_vblank_off().
*/
+ trace_printk("Update vblank count {%s}\n", __func__);
drm_update_vblank_count(dev, pipe, false);
__disable_vblank(dev, pipe);
vblank->enabled = false;
@@ -1004,6 +1006,7 @@ static int drm_vblank_enable(struct drm_device *dev, unsigned int pipe)
if (ret) {
atomic_dec(&vblank->refcount);
} else {
+ trace_printk("Update vblank count {%s}\n", __func__);
drm_update_vblank_count(dev, pipe, 0);
/* drm_update_vblank_count() includes a wmb so we just
* need to ensure that the compiler emits the write
@@ -1183,6 +1186,8 @@ void drm_crtc_vblank_off(struct drm_crtc *crtc)
if (drm_core_check_feature(dev, DRIVER_ATOMIC) || !vblank->inmodeset)
drm_vblank_disable_and_save(dev, pipe);
+ trace_printk("Waking up vblank queue before vblank off\n");
+
wake_up(&vblank->queue);
/*
@@ -1204,6 +1209,8 @@ void drm_crtc_vblank_off(struct drm_crtc *crtc)
DRM_DEBUG("Sending premature vblank event on disable: "
"wanted %llu, current %llu\n",
e->sequence, seq);
+ trace_printk("Sending premature vblank event on disable: " \
+ "wanted %llu, current %llu\n", e->sequence, seq);
list_del(&e->base.link);
drm_vblank_put(dev, pipe);
send_vblank_event(dev, e, seq, now);
@@ -1356,6 +1363,8 @@ void drm_vblank_restore(struct drm_device *dev, unsigned int pipe)
"Cannot compute missed vblanks without frame duration\n");
framedur_ns = vblank->framedur_ns;
+ trace_printk("Get last vblank time stamp {%s}\n", __func__);
+
do {
cur_vblank = __get_vblank_counter(dev, pipe);
drm_get_last_vbltimestamp(dev, pipe, &t_vblank, false);
@@ -1526,8 +1535,11 @@ static int drm_queue_vblank_event(struct drm_device *dev, unsigned int pipe,
seq = drm_vblank_count_and_time(dev, pipe, &now);
- DRM_DEBUG("event on vblank count %llu, current %llu, crtc %u\n",
- req_seq, seq, pipe);
+ DRM_DEBUG("Added pending event on vblank count %llu to pending \
+ event list, current %llu, crtc %u\n", req_seq, seq, pipe);
+
+ trace_printk("Added pending event on vblank count %llu to pending \
+ event list, current %llu, crtc %u\n", req_seq, seq, pipe);
trace_drm_vblank_event_queued(file_priv, pipe, req_seq);
@@ -1537,6 +1549,8 @@ static int drm_queue_vblank_event(struct drm_device *dev, unsigned int pipe,
send_vblank_event(dev, e, seq, now);
vblwait->reply.sequence = seq;
} else {
+ trace_printk("Added pending event on vblank count %llu to vblank \
+ event list, current %llu, crtc %u\n", req_seq, seq, pipe);
/* drm_handle_vblank_events will call drm_vblank_put */
list_add_tail(&e->base.link, &dev->vblank_event_list);
vblwait->reply.sequence = req_seq;
@@ -1669,6 +1683,9 @@ int drm_wait_vblank_ioctl(struct drm_device *dev, void *data,
}
seq = drm_vblank_count(dev, pipe);
+ trace_printk("Vblank wait current seq:%llu requested:%u\n", \
+ seq, vblwait->request.sequence);
+
switch (vblwait->request.type & _DRM_VBLANK_TYPES_MASK) {
case _DRM_VBLANK_RELATIVE:
req_seq = seq + vblwait->request.sequence;
@@ -1702,6 +1719,10 @@ int drm_wait_vblank_ioctl(struct drm_device *dev, void *data,
DRM_DEBUG("waiting on vblank count %llu, crtc %u\n",
req_seq, pipe);
+
+ trace_printk("waiting(3s) on vblank crtc wait queue for count \
+ %llu, crtc %u\n", req_seq, pipe);
+
wait = wait_event_interruptible_timeout(vblank->queue,
vblank_passed(drm_vblank_count(dev, pipe), req_seq) ||
!READ_ONCE(vblank->enabled),
@@ -1727,6 +1748,9 @@ int drm_wait_vblank_ioctl(struct drm_device *dev, void *data,
DRM_DEBUG("crtc %d returning %u to client\n",
pipe, vblwait->reply.sequence);
+
+ trace_printk("Returning to client current seq:%u crtc %d\n", \
+ vblwait->reply.sequence, pipe);
} else {
DRM_DEBUG("crtc %d vblank wait interrupted by signal\n", pipe);
}
@@ -1757,6 +1781,8 @@ static void drm_handle_vblank_events(struct drm_device *dev, unsigned int pipe)
list_del(&e->base.link);
drm_vblank_put(dev, pipe);
+ trace_printk("Send vblank event on crtc:%u seq:%llu time:%lld\n", \
+ pipe, seq, now);
send_vblank_event(dev, e, seq, now);
}
@@ -1800,11 +1826,15 @@ bool drm_handle_vblank(struct drm_device *dev, unsigned int pipe)
spin_unlock_irqrestore(&dev->event_lock, irqflags);
return false;
}
+
+ trace_printk("Update vblank count {%s}\n", __func__);
drm_update_vblank_count(dev, pipe, true);
spin_unlock(&dev->vblank_time_lock);
+ trace_printk("Waking up crtc:%u vblank queue\n", pipe);
+
wake_up(&vblank->queue);
/* With instant-off, we defer disabling the interrupt until after
@@ -2000,6 +2030,8 @@ int drm_crtc_queue_sequence_ioctl(struct drm_device *dev, void *data,
send_vblank_event(dev, e, seq, now);
queue_seq->sequence = seq;
} else {
+ trace_printk("Added pending event on vblank seq %llu to vblank \
+ event list, current %llu, crtc %u\n", req_seq, seq, pipe);
/* drm_handle_vblank_events will call drm_vblank_put */
list_add_tail(&e->base.link, &dev->vblank_event_list);
queue_seq->sequence = req_seq;
diff --git a/drivers/gpu/drm/i915/display/intel_display.c b/drivers/gpu/drm/i915/display/intel_display.c
index 136a664c03885..c179445b7e96c 100644
--- a/drivers/gpu/drm/i915/display/intel_display.c
+++ b/drivers/gpu/drm/i915/display/intel_display.c
@@ -15615,6 +15615,7 @@ static void intel_atomic_commit_tail(struct intel_atomic_state *state)
/* Complete events for now disable pipes here. */
if (modeset && !new_crtc_state->hw.active && new_crtc_state->uapi.event) {
spin_lock_irq(&dev->event_lock);
+ trace_printk("Send vblank event once commit done\n");
drm_crtc_send_vblank_event(&crtc->base,
new_crtc_state->uapi.event);
spin_unlock_irq(&dev->event_lock);
diff --git a/drivers/gpu/drm/i915/i915_irq.c b/drivers/gpu/drm/i915/i915_irq.c
index 724b0bd8b1db2..96ffe6719a0ef 100644
--- a/drivers/gpu/drm/i915/i915_irq.c
+++ b/drivers/gpu/drm/i915/i915_irq.c
@@ -867,6 +867,9 @@ bool i915_get_crtc_scanoutpos(struct drm_device *dev, unsigned int index,
vbl_start = mode->crtc_vblank_start;
vbl_end = mode->crtc_vblank_end;
+ trace_printk("CRTC:%u htotal:%d hsync_start:%d vtotal:%d vbl_start:%d \
+ vbl_end:%d\n",pipe, htotal, hsync_start, vtotal, vbl_start, vbl_end);
+
if (mode->flags & DRM_MODE_FLAG_INTERLACE) {
vbl_start = DIV_ROUND_UP(vbl_start, 2);
vbl_end /= 2;
--
2.24.1
More information about the Intel-gfx-trybot
mailing list