feat: log current planes on apply

It is helpful for debugging to know in which state the available planes on an
output are when a layout is applied that leads to a change.

For that log all planes that are compatible with the output. Currently disabled
planes have multiple properties logged per line to keep the log short.

Example:

== Apply request for output 62 ==
  Note: Reused previous plane allocation 5 times.

Available planes (on output 62):
  Plane 55:
    type: primary
    FB_ID: 93
    IN_FENCE_FD: -1
    CRTC_ID: 62
    CRTC_X: 39
    CRTC_Y: 0
    CRTC_W: 3761
    CRTC_H: 2160
    SRC_X: 0
    SRC_Y: 0
    SRC_W: 2349
    SRC_H: 1349
    COLOR_ENCODING: 0
    COLOR_RANGE: 0
  Plane 61 (inactive):
    type: cursor FB_ID: 0 IN_FENCE_FD: -1 CRTC_ID: 0
    CRTC_X: 0 CRTC_Y: 0 CRTC_W: 0 CRTC_H: 0
    SRC_X: 0 SRC_Y: 0 SRC_W: 0 SRC_H: 0
  Plane 58 (inactive):
    type: overlay FB_ID: 0 IN_FENCE_FD: -1 CRTC_ID: 0
    CRTC_X: 0 CRTC_Y: 0 CRTC_W: 0 CRTC_H: 0
    SRC_X: 0 SRC_Y: 0 SRC_W: 0 SRC_H: 0
    alpha: 65535 pixel blend mode: 0

Committed layers:
  Layer 0x561febd41260:
    FB_ID = 93
    zpos = 0
    SRC_X = 0
    SRC_Y = 0
    SRC_W = 2349
    SRC_H = 1349
    CRTC_X = 39
    CRTC_Y = 0
    CRTC_W = 3761
    CRTC_H = 2160
  Layer 0x561febd3c830:
    FB_ID = 110
    zpos = 2
    SRC_X = 0
    SRC_Y = 0
    SRC_W = 48
    SRC_H = 48
    CRTC_X = 66
    CRTC_Y = 39
    CRTC_W = 48
    CRTC_H = 48

Reset planes: 55 52 49 46 43 40 <p|c> 71 69 67 65 63 61 <c|o> 58

Performing allocation for plane 55 (1/13)
  Layer 0x561febd41260 -> plane 55: applying properties...
  Layer 0x561febd41260 -> plane 55: success
Performing allocation for plane 61 (12/13)
  Layer 0x561febd3c830 -> plane 61: applying properties...
  Layer 0x561febd3c830 -> plane 61: success
Performing allocation for plane 58 (13/13)
Found a better allocation with score=2
  Layer 0x561febd3c830 -> plane 55: applying properties...
  Layer 0x561febd3c830 -> plane 55: success
Performing allocation for plane 61 (12/13)
  Layer 0x561febd41260 -> plane 61: applying properties...
  Layer 0x561febd41260 -> plane 61: success
Performing allocation for plane 58 (13/13)
Found plane allocation for output 0x561febd3e2a0 with score=2

Final assignment of layers to planes:
  [1] Layer 0x561febd41260 -> plane 55 (primary)
  [2] Layer 0x561febd3c830 -> plane 61 (cursor)

alloc.c

@@ -568,6 +568,19 @@ static void log_reuse(struct liftoff_output *output)
 	output->alloc_reused_counter++;
 }
 
+static void log_no_reuse(struct liftoff_output *output)
+{
+	liftoff_log(LIFTOFF_DEBUG,
+				"\n== Apply request for output %"PRIu32" ==", output->crtc_id);
+
+	if (output->alloc_reused_counter != 0) {
+		liftoff_log(LIFTOFF_DEBUG,
+				"  Note: Reused previous plane allocation %d times.",
+					output->alloc_reused_counter);
+		output->alloc_reused_counter = 0;
+	}
+}
+
 static void log_plane_type_change(uint32_t base, uint32_t cmp)
 {
 	switch (base) {
@@ -589,13 +602,109 @@ static void log_plane_type_change(uint32_t base, uint32_t cmp)
 	}
 }
 
+static void log_planes(struct liftoff_device *device,
+					   struct liftoff_output *output)
+{
+	struct liftoff_plane *plane;
+	drmModeObjectProperties *drm_props;
+	drmModePropertyRes *drm_prop;
+	size_t i;
+	int per_line, max_per_line;
+
+	if (!log_has(LIFTOFF_DEBUG)) {
+		return;
+	}
+
+	liftoff_log_cnt(LIFTOFF_DEBUG, "\nAvailable planes");
+	if (output) {
+		liftoff_log(LIFTOFF_DEBUG, " (on output %"PRIu32 "):", output->crtc_id);
+	} else {
+		liftoff_log(LIFTOFF_DEBUG, ":");
+	}
+
+	liftoff_list_for_each(plane, &device->planes, link) {
+		bool active = false;
+
+		if (output) {
+			if ((plane->possible_crtcs & (1 << output->crtc_index)) == 0) {
+				continue;
+			}
+		}
+
+		drm_props = drmModeObjectGetProperties(device->drm_fd, plane->id,
+							   DRM_MODE_OBJECT_PLANE);
+		if (drm_props == NULL) {
+			liftoff_log_errno(LIFTOFF_ERROR, "drmModeObjectGetProperties");
+			continue;
+		}
+
+		for (i = 0; i < drm_props->count_props; i++) {
+			drm_prop = drmModeGetProperty(device->drm_fd,
+							  drm_props->props[i]);
+			if (drm_prop == NULL) {
+				liftoff_log_errno(LIFTOFF_ERROR, "drmModeObjectGetProperties");
+				continue;
+			}
+
+			if (strcmp(drm_prop->name, "CRTC_ID") == 0
+					&& drm_props->prop_values[i] != 0) {
+				active = true;
+				break;
+			}
+		}
+
+		liftoff_log_cnt(LIFTOFF_DEBUG, "  Plane %"PRIu32 "%s", plane->id,
+			active ? ":" : " (inactive):");
+
+		max_per_line = active ? 1 : 4;
+		per_line = max_per_line - 1;
+		for (i = 0; i < drm_props->count_props; i++) {
+			uint64_t value = drm_props->prop_values[i];
+			char *name;
+
+			if (++per_line == max_per_line) {
+				liftoff_log_cnt(LIFTOFF_DEBUG, "\n   ");
+				per_line = 0;
+			}
+
+			drm_prop = drmModeGetProperty(device->drm_fd,
+							  drm_props->props[i]);
+			if (drm_prop == NULL) {
+				liftoff_log_cnt(LIFTOFF_DEBUG, "ERR!");
+				continue;
+			}
+
+			name = drm_prop->name;
+
+			if (strcmp(name, "type") == 0) {
+				liftoff_log_cnt(LIFTOFF_DEBUG, " %s: %s", name,
+					value == DRM_PLANE_TYPE_PRIMARY ? "primary" :
+					value == DRM_PLANE_TYPE_CURSOR ? "cursor" : "overlay");
+				continue;
+			}
+
+			if (strcmp(name, "CRTC_X") == 0 || strcmp(name, "CRTC_Y") == 0
+					|| strcmp(name, "IN_FENCE_FD") == 0) {
+				liftoff_log_cnt(LIFTOFF_DEBUG, " %s: %"PRIi32, name, (int32_t)value);
+				continue;
+			}
+
+			if (strcmp(name, "SRC_W") == 0 || strcmp(name, "SRC_H") == 0) {
+				value = value >> 16;
+			}
+			liftoff_log_cnt(LIFTOFF_DEBUG, " %s: %"PRIu64, name, value);
+		}
+		liftoff_log_cnt(LIFTOFF_DEBUG, "\n");
+	}
+}
+
 static bool reset_planes(struct liftoff_device *device, drmModeAtomicReq *req)
 {
 	struct liftoff_plane *plane;
 	uint32_t debug_type = DRM_PLANE_TYPE_PRIMARY;
 	bool compatible;
 
-	liftoff_log_cnt(LIFTOFF_DEBUG, "Reset planes:");
+	liftoff_log_cnt(LIFTOFF_DEBUG, "\nReset planes:");
 
 	liftoff_list_for_each(plane, &device->planes, link) {
 		if (plane->layer != NULL) {
@@ -616,7 +725,7 @@ static bool reset_planes(struct liftoff_device *device, drmModeAtomicReq *req)
 		assert(compatible);
 	}
 
-	liftoff_log_cnt(LIFTOFF_DEBUG, "\n");
+	liftoff_log(LIFTOFF_DEBUG, "\n");
 	return true;
 }
 
@@ -638,7 +747,11 @@ bool liftoff_output_apply(struct liftoff_output *output, drmModeAtomicReq *req)
 		return true;
 	}
 
+	if (log_has(LIFTOFF_DEBUG)) {
+		log_no_reuse(output);
+		log_planes(device, output);
 		output_log_layers(output);
+	}
 
 	/* Unset all existing plane and layer mappings with this output. */
 	liftoff_list_for_each(plane, &device->planes, link) {
@@ -691,7 +804,7 @@ bool liftoff_output_apply(struct liftoff_output *output, drmModeAtomicReq *req)
 		    "score=%d:", (void *)output, result.best_score);
 
 	/* Apply the best allocation */
-	liftoff_log(LIFTOFF_DEBUG, "Final assignment of layers to planes:");
+	liftoff_log(LIFTOFF_DEBUG, "\nFinal assignment of layers to planes:");
 	i = j = 0;
 	liftoff_list_for_each(plane, &device->planes, link) {
 		layer = result.best[i];
@@ -704,7 +817,7 @@ bool liftoff_output_apply(struct liftoff_output *output, drmModeAtomicReq *req)
 		liftoff_log(LIFTOFF_DEBUG, "  [%zu] Layer %p -> plane %"PRIu32
 			" (%s)", j, (void *)layer, plane->id,
 			plane->type == DRM_PLANE_TYPE_PRIMARY ? "primary" :
-					DRM_PLANE_TYPE_OVERLAY ? "overlay" : "cursor");
+			plane->type == DRM_PLANE_TYPE_OVERLAY ? "overlay" : "cursor");
 
 		assert(plane->layer == NULL);
 		assert(layer->plane == NULL);

output.c

@@ -66,16 +66,7 @@ void output_log_layers(struct liftoff_output *output) {
 		return;
 	}
 
-	liftoff_log(LIFTOFF_DEBUG, "\n== Apply request for output %"PRIu32" ==", output->crtc_id);
+	liftoff_log(LIFTOFF_DEBUG, "\nCommitted layers:");
-
-	if (output->alloc_reused_counter != 0) {
-		liftoff_log(LIFTOFF_DEBUG,
-					"  Note: Reused previous plane allocation %d times.",
-					output->alloc_reused_counter);
-		output->alloc_reused_counter = 0;
-	}
-
-	liftoff_log(LIFTOFF_DEBUG, "Active layers:");
 
 	liftoff_list_for_each(layer, &output->layers, link) {
 		if (layer->force_composition) {