kms: Add some basic debug logging

Enabled using MUTTER_DEBUG=kms or via
Meta.add_verbose_topic(Meta.DebugTopic.KMS) in looking glass.

Part-of: <https://gitlab.gnome.org/GNOME/mutter/-/merge_requests/1488>

src/backends/native/meta-kms-device.c

@@ -285,6 +285,9 @@ meta_create_kms_impl_device (MetaKmsDevice  *device,
       driver_description = g_strdup ("Unknown");
     }
 
+  g_message ("Adding device '%s' (%s) using non-atomic mode setting.",
+             path, driver_name);
+
   return g_initable_new (META_TYPE_KMS_IMPL_DEVICE_SIMPLE, NULL, error,
                          "device", device,
                          "impl", impl,

src/backends/native/meta-kms-impl-device-simple.c

@@ -118,6 +118,13 @@ process_connector_update (MetaKmsImplDevice  *impl_device,
 
   if (connector_update->dpms.has_update)
     {
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Setting DPMS on connector %u (%s) to %"
+                  G_GUINT64_FORMAT,
+                  meta_kms_connector_get_id (connector),
+                  meta_kms_impl_device_get_path (impl_device),
+                  connector_update->dpms.state);
+
       if (!set_connector_property (impl_device,
                                    connector,
                                    META_KMS_CONNECTOR_PROP_DPMS,
@@ -129,6 +136,14 @@ process_connector_update (MetaKmsImplDevice  *impl_device,
   if (connector_update->underscanning.has_update &&
       connector_update->underscanning.is_active)
     {
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Setting underscanning on connector %u (%s) to "
+                  "%" G_GUINT64_FORMAT "x%" G_GUINT64_FORMAT,
+                  meta_kms_connector_get_id (connector),
+                  meta_kms_impl_device_get_path (impl_device),
+                  connector_update->underscanning.hborder,
+                  connector_update->underscanning.vborder);
+
       if (!set_connector_property (impl_device,
                                    connector,
                                    META_KMS_CONNECTOR_PROP_UNDERSCAN,
@@ -150,6 +165,11 @@ process_connector_update (MetaKmsImplDevice  *impl_device,
     }
   else if (connector_update->underscanning.has_update)
     {
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Unsetting underscanning on connector %u (%s)",
+                  meta_kms_connector_get_id (connector),
+                  meta_kms_impl_device_get_path (impl_device));
+
       if (!set_connector_property (impl_device,
                                    connector,
                                    META_KMS_CONNECTOR_PROP_UNDERSCAN,
@@ -217,6 +237,13 @@ set_plane_rotation (MetaKmsImplDevice  *impl_device,
 
   rotation_prop_id = meta_kms_plane_get_prop_id (plane,
                                                  META_KMS_PLANE_PROP_ROTATION);
+
+  meta_topic (META_DEBUG_KMS,
+              "[simple] Setting plane %u (%s) rotation to %" G_GUINT64_FORMAT,
+              meta_kms_plane_get_id (plane),
+              meta_kms_impl_device_get_path (impl_device),
+              rotation);
+
   ret = drmModeObjectSetProperty (fd,
                                   meta_kms_plane_get_id (plane),
                                   DRM_MODE_OBJECT_PLANE,
@@ -293,6 +320,12 @@ process_mode_set (MetaKmsImplDevice  *impl_device,
 
       buffer = plane_assignment->buffer;
       fb_id = meta_drm_buffer_get_fb_id (buffer);
+
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Setting mode of CRTC %u (%s) to %s",
+                  meta_kms_crtc_get_id (crtc),
+                  meta_kms_impl_device_get_path (impl_device),
+                  drm_mode->name);
     }
   else
     {
@@ -301,6 +334,11 @@ process_mode_set (MetaKmsImplDevice  *impl_device,
       n_connectors = 0;
       connectors = NULL;
       fb_id = 0;
+
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Unsetting mode of CRTC %u (%s)",
+                  meta_kms_crtc_get_id (crtc),
+                  meta_kms_impl_device_get_path (impl_device));
     }
 
   fd = meta_kms_impl_device_get_fd (impl_device);
@@ -346,6 +384,12 @@ process_crtc_gamma (MetaKmsImplDevice  *impl_device,
   int fd;
   int ret;
 
+  meta_topic (META_DEBUG_KMS,
+              "[simple] Setting CRTC %u (%s) gamma, size: %d",
+              meta_kms_crtc_get_id (crtc),
+              meta_kms_impl_device_get_path (impl_device),
+              gamma->size);
+
   fd = meta_kms_impl_device_get_fd (impl_device);
   ret = drmModeCrtcSetGamma (fd, meta_kms_crtc_get_id (crtc),
                              gamma->size,
@@ -447,11 +491,21 @@ retry_page_flips (gpointer user_data)
       custom_page_flip_func = retry_page_flip_data->custom_page_flip_func;
       if (custom_page_flip_func)
         {
+          meta_topic (META_DEBUG_KMS,
+                      "[simple] Retrying custom page flip on CRTC %u (%s)",
+                      meta_kms_crtc_get_id (crtc),
+                      meta_kms_impl_device_get_path (impl_device));
           ret = custom_page_flip_func (retry_page_flip_data->custom_page_flip_user_data,
                                        retry_page_flip_data->page_flip_data);
         }
       else
         {
+          meta_topic (META_DEBUG_KMS,
+                      "[simple] Retrying page flip on CRTC %u (%s) with %u",
+                      meta_kms_crtc_get_id (crtc),
+                      meta_kms_impl_device_get_path (impl_device),
+                      retry_page_flip_data->fb_id);
+
           fd = meta_kms_impl_device_get_fd (impl_device);
           ret = drmModePageFlip (fd,
                                  meta_kms_crtc_get_id (crtc),
@@ -464,6 +518,11 @@ retry_page_flips (gpointer user_data)
         {
           float refresh_rate;
 
+          meta_topic (META_DEBUG_KMS,
+                      "[simple] Rescheduling page flip retry on CRTC %u (%s)",
+                      meta_kms_crtc_get_id (crtc),
+                      meta_kms_impl_device_get_path (impl_device));
+
           refresh_rate =
             get_cached_crtc_refresh_rate (impl_device_simple, crtc);
           retry_page_flip_data->retry_time_us +=
@@ -727,6 +786,10 @@ dispatch_page_flip (MetaKmsImplDevice    *impl_device,
                                              &custom_page_flip_user_data);
   if (custom_page_flip_func)
     {
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Invoking custom page flip on CRTC %u (%s)",
+                  meta_kms_crtc_get_id (crtc),
+                  meta_kms_impl_device_get_path (impl_device));
       ret = custom_page_flip_func (custom_page_flip_user_data,
                                    meta_kms_page_flip_data_ref (page_flip_data));
     }
@@ -735,6 +798,14 @@ dispatch_page_flip (MetaKmsImplDevice    *impl_device,
       uint32_t fb_id;
 
       fb_id = meta_drm_buffer_get_fb_id (plane_assignment->buffer);
+
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Page flipping CRTC %u (%s) with %u, data: %p",
+                  meta_kms_crtc_get_id (crtc),
+                  meta_kms_impl_device_get_path (impl_device),
+                  fb_id,
+                  page_flip_data);
+
       ret = drmModePageFlip (fd,
                              meta_kms_crtc_get_id (crtc),
                              fb_id,
@@ -749,6 +820,11 @@ dispatch_page_flip (MetaKmsImplDevice    *impl_device,
     {
       CachedModeSet *cached_mode_set;
 
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Scheduling page flip retry on CRTC %u (%s)",
+                  meta_kms_crtc_get_id (crtc),
+                  meta_kms_impl_device_get_path (impl_device));
+
       cached_mode_set = get_cached_mode_set (impl_device_simple, crtc);
       if (cached_mode_set)
         {
@@ -781,6 +857,11 @@ dispatch_page_flip (MetaKmsImplDevice    *impl_device,
     }
   else if (ret == -EINVAL)
     {
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Falling back to mode set on CRTC %u (%s)",
+                  meta_kms_crtc_get_id (crtc),
+                  meta_kms_impl_device_get_path (impl_device));
+
       if (!mode_set_fallback (impl_device_simple,
                               update,
                               plane_assignment,
@@ -952,6 +1033,16 @@ process_cursor_plane_assignment (MetaKmsImplDevice       *impl_device,
           handle_u32 = 0;
         }
 
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Setting HW cursor of CRTC %u (%s) to %u "
+                  "(size: %dx%d, hot: (%d, %d))",
+                  crtc_id,
+                  meta_kms_impl_device_get_path (impl_device),
+                  handle_u32,
+                  width, height,
+                  plane_assignment->cursor_hotspot.x,
+                  plane_assignment->cursor_hotspot.y);
+
       if (plane_assignment->cursor_hotspot.is_valid)
         {
           ret = drmModeSetCursor2 (fd,
@@ -977,6 +1068,13 @@ process_cursor_plane_assignment (MetaKmsImplDevice       *impl_device,
         }
     }
 
+  meta_topic (META_DEBUG_KMS,
+              "[simple] Moving HW cursor of CRTC %u (%s) to (%d, %d)",
+              crtc_id,
+              meta_kms_impl_device_get_path (impl_device),
+              plane_assignment->dst_rect.x,
+              plane_assignment->dst_rect.y);
+
   drmModeMoveCursor (fd,
                      crtc_id,
                      plane_assignment->dst_rect.x,
@@ -1081,11 +1179,20 @@ page_flip_handler (int           fd,
 {
   MetaKmsPageFlipData *page_flip_data = user_data;
   MetaKmsImplDevice *impl_device;
+  MetaKmsCrtc *crtc;
 
   meta_kms_page_flip_data_set_timings_in_impl (page_flip_data,
                                                sequence, tv_sec, tv_usec);
 
   impl_device = meta_kms_page_flip_data_get_impl_device (page_flip_data);
+  crtc = meta_kms_page_flip_data_get_crtc (page_flip_data);
+
+  meta_topic (META_DEBUG_KMS,
+              "[simple] Handling page flip callback from %s, data: %p, CRTC: %u",
+              meta_kms_impl_device_get_path (impl_device),
+              page_flip_data,
+              meta_kms_crtc_get_id (crtc));
+
   meta_kms_impl_device_handle_page_flip_callback (impl_device, page_flip_data);
 }
 
@@ -1104,6 +1211,10 @@ meta_kms_impl_device_simple_process_update (MetaKmsImplDevice *impl_device,
   GError *error = NULL;
   GList *failed_planes = NULL;
 
+  meta_topic (META_DEBUG_KMS,
+              "[simple] Processing update %" G_GUINT64_FORMAT,
+              meta_kms_update_get_sequence_number (update));
+
   if (!process_entries (impl_device,
                         update,
                         meta_kms_update_get_connector_updates (update),
@@ -1186,6 +1297,14 @@ meta_kms_impl_device_simple_discard_pending_page_flips (MetaKmsImplDevice *impl_
       MetaKmsPageFlipData *page_flip_data;
 
       page_flip_data = g_steal_pointer (&retry_page_flip_data->page_flip_data);
+
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Discarding page flip retry for CRTC %u (%s)",
+                  meta_kms_crtc_get_id (
+                    meta_kms_page_flip_data_get_crtc (page_flip_data)),
+                  meta_kms_impl_device_get_path (
+                    meta_kms_page_flip_data_get_impl_device (page_flip_data)));
+
       meta_kms_page_flip_data_discard_in_impl (page_flip_data, NULL);
       retry_page_flip_data_free (retry_page_flip_data);
     }
@@ -1244,6 +1363,11 @@ meta_kms_impl_device_simple_initable_init (GInitable     *initable,
       if (plane)
         continue;
 
+      meta_topic (META_DEBUG_KMS,
+                  "[simple] Adding fake cursor plane for CRTC %u (%s)",
+                  meta_kms_crtc_get_id (crtc),
+                  meta_kms_impl_device_get_path (impl_device));
+
       meta_kms_device_add_fake_plane_in_impl (device,
                                               META_KMS_PLANE_TYPE_CURSOR,
                                               crtc);

src/backends/native/meta-kms-update-private.h

@@ -116,6 +116,8 @@ void meta_kms_update_unlock (MetaKmsUpdate *update);
 
 gboolean meta_kms_update_is_locked (MetaKmsUpdate *update);
 
+uint64_t meta_kms_update_get_sequence_number (MetaKmsUpdate *update);
+
 MetaKmsDevice * meta_kms_update_get_device (MetaKmsUpdate *update);
 
 void meta_kms_plane_assignment_set_rotation (MetaKmsPlaneAssignment *plane_assignment,

src/backends/native/meta-kms-update.c

@@ -33,6 +33,7 @@ struct _MetaKmsUpdate
   MetaKmsDevice *device;
 
   gboolean is_locked;
+  uint64_t sequence_number;
 
   MetaPowerSave power_save;
   GList *mode_sets;
@@ -535,13 +536,21 @@ meta_kms_update_get_custom_page_flip_func (MetaKmsUpdate             *update,
   *custom_page_flip_user_data = update->custom_page_flip_user_data;
 }
 
+uint64_t
+meta_kms_update_get_sequence_number (MetaKmsUpdate *update)
+{
+  return update->sequence_number;
+}
+
 MetaKmsUpdate *
 meta_kms_update_new (MetaKmsDevice *device)
 {
   MetaKmsUpdate *update;
+  static uint64_t sequence_number = 0;
 
   update = g_new0 (MetaKmsUpdate, 1);
   update->device = device;
+  update->sequence_number = sequence_number++;
 
   return update;
 }

src/backends/native/meta-renderer-native.c

@@ -1870,6 +1870,8 @@ unset_disabled_crtcs (MetaBackend *backend,
 {
   GList *l;
 
+  meta_topic (META_DEBUG_KMS, "Disabling all disabled CRTCs");
+
   for (l = meta_backend_get_gpus (backend); l; l = l->next)
     {
       MetaGpu *gpu = l->data;
@@ -2012,6 +2014,11 @@ meta_onscreen_native_swap_buffers_with_damage (CoglOnscreen  *onscreen,
   kms_crtc = meta_crtc_kms_get_kms_crtc (META_CRTC_KMS (onscreen_native->crtc));
   kms_device = meta_kms_crtc_get_device (kms_crtc);
 
+  meta_topic (META_DEBUG_KMS,
+              "Posting primary plane composite update for CRTC %u (%s)",
+              meta_kms_crtc_get_id (kms_crtc),
+              meta_kms_device_get_path (kms_device));
+
   flags = META_KMS_UPDATE_FLAG_NONE;
   kms_feedback = meta_kms_post_pending_update_sync (kms, kms_device, flags);
   if (meta_kms_feedback_get_result (kms_feedback) != META_KMS_FEEDBACK_PASSED)
@@ -2208,6 +2215,11 @@ meta_onscreen_native_direct_scanout (CoglOnscreen   *onscreen,
   kms_crtc = meta_crtc_kms_get_kms_crtc (META_CRTC_KMS (onscreen_native->crtc));
   kms_device = meta_kms_crtc_get_device (kms_crtc);
 
+  meta_topic (META_DEBUG_KMS,
+              "Posting direct scanout update for CRTC %u (%s)",
+              meta_kms_crtc_get_id (kms_crtc),
+              meta_kms_device_get_path (kms_device));
+
   flags = META_KMS_UPDATE_FLAG_PRESERVE_ON_ERROR;
   kms_feedback = meta_kms_post_pending_update_sync (kms, kms_device, flags);
   if (meta_kms_feedback_get_result (kms_feedback) != META_KMS_FEEDBACK_PASSED)
@@ -2685,6 +2697,8 @@ meta_renderer_native_queue_modes_reset (MetaRendererNative *renderer_native)
       onscreen_native->pending_set_crtc = TRUE;
     }
 
+  meta_topic (META_DEBUG_KMS, "Queue mode set");
+
   renderer_native->pending_unset_disabled_crtcs = TRUE;
 }
 

src/core/main.c

@@ -120,6 +120,7 @@ static const GDebugKey meta_debug_keys[] = {
   { "dbus", META_DEBUG_DBUS },
   { "input", META_DEBUG_INPUT },
   { "wayland", META_DEBUG_WAYLAND },
+  { "kms", META_DEBUG_KMS },
 };
 
 /*

src/core/util.c

@@ -276,6 +276,8 @@ topic_name (MetaDebugTopic topic)
       return "DBUS";
     case META_DEBUG_INPUT:
       return "INPUT";
+    case META_DEBUG_KMS:
+      return "KMS";
     case META_DEBUG_VERBOSE:
       return "VERBOSE";
     case META_DEBUG_WAYLAND:

src/meta/util.h

@@ -76,6 +76,7 @@ void meta_fatal      (const char *format,
  * @META_DEBUG_SHAPES: shapes
  * @META_DEBUG_EDGE_RESISTANCE: edge resistance
  * @META_DEBUG_WAYLAND: Wayland
+ * @META_DEBUG_KMS: kernel mode setting
  */
 typedef enum
 {
@@ -101,6 +102,7 @@ typedef enum
   META_DEBUG_DBUS            = 1 << 18,
   META_DEBUG_INPUT           = 1 << 19,
   META_DEBUG_WAYLAND         = 1 << 20,
+  META_DEBUG_KMS             = 1 << 21,
 } MetaDebugTopic;
 
 /**