From 2f8a598582bd2473d8449d7a7e549a43c6e55243 Mon Sep 17 00:00:00 2001 From: Daniel van Vugt Date: Tue, 12 Sep 2023 17:35:14 +0800 Subject: [PATCH] kms/impl-device: Add debug logging for deadline dispatch lateness And also "completion" time to measure when the commit returned. This is structured so as to measure all timestamps first before logging anything. That way our results shouldn't be (don't seem to be) affected by the logging itself. Part-of: --- src/backends/native/meta-kms-impl-device.c | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/src/backends/native/meta-kms-impl-device.c b/src/backends/native/meta-kms-impl-device.c index ee0c2f7c1..1bff6be33 100644 --- a/src/backends/native/meta-kms-impl-device.c +++ b/src/backends/native/meta-kms-impl-device.c @@ -1397,6 +1397,10 @@ crtc_frame_deadline_dispatch (MetaThreadImpl *thread_impl, g_autoptr (MetaKmsFeedback) feedback = NULL; uint64_t timer_value; ssize_t ret; + int64_t dispatch_time_us = 0; + + if (meta_is_topic_enabled (META_DEBUG_KMS_DEADLINE)) + dispatch_time_us = g_get_monotonic_time (); ret = read (crtc_frame->deadline.timer_fd, &timer_value, @@ -1418,6 +1422,23 @@ crtc_frame_deadline_dispatch (MetaThreadImpl *thread_impl, crtc_frame->crtc, g_steal_pointer (&crtc_frame->pending_update), META_KMS_UPDATE_FLAG_NONE); + + if (meta_is_topic_enabled (META_DEBUG_KMS_DEADLINE)) + { + int64_t lateness_us, duration_us; + + lateness_us = dispatch_time_us - + crtc_frame->deadline.expected_deadline_time_us; + duration_us = g_get_monotonic_time () - dispatch_time_us; + + meta_topic (META_DEBUG_KMS_DEADLINE, + "Deadline dispatch started %3"G_GINT64_FORMAT "µs %s and " + "completed %3"G_GINT64_FORMAT "µs after that.", + ABS (lateness_us), + lateness_us >= 0 ? "late" : "early", + duration_us); + } + if (meta_kms_feedback_did_pass (feedback)) crtc_frame->deadline.is_deadline_page_flip = TRUE; disarm_crtc_frame_deadline_timer (crtc_frame);