Improve debug log

alloc.c

@@ -589,7 +589,7 @@ bool liftoff_output_apply(struct liftoff_output *output, drmModeAtomicReq *req)
 	struct liftoff_layer *layer;
 	struct alloc_result result;
 	struct alloc_step step;
-	size_t i;
+	size_t i, j;
 	bool compatible;
 
 	device = output->device;
@@ -602,6 +602,7 @@ bool liftoff_output_apply(struct liftoff_output *output, drmModeAtomicReq *req)
 	}
 	log_no_reuse(output);
 
+	output_log_planes(output);
 	output_log_layers(output);
 
 	/* Unset all existing plane and layer mappings. */
@@ -616,8 +617,6 @@ bool liftoff_output_apply(struct liftoff_output *output, drmModeAtomicReq *req)
 	   to hit bandwidth limits because too many planes are enabled. */
 	liftoff_list_for_each(plane, &device->planes, link) {
 		if (plane->layer == NULL) {
-			liftoff_log(LIFTOFF_DEBUG,
-				    "Disabling plane %"PRIu32, plane->id);
 			if (!plane_apply(plane, NULL, req, &compatible)) {
 				return false;
 			}
@@ -662,22 +661,27 @@ bool liftoff_output_apply(struct liftoff_output *output, drmModeAtomicReq *req)
 		    "score=%d:", (void *)output, result.best_score);
 
 	/* Apply the best allocation */
-	i = 0;
+	liftoff_log(LIFTOFF_DEBUG, "Final assignment of layers to planes:");
+	i = j = 0;
 	liftoff_list_for_each(plane, &device->planes, link) {
 		layer = result.best[i];
 		i++;
 		if (layer == NULL) {
 			continue;
 		}
 
-		liftoff_log(LIFTOFF_DEBUG, "  Layer %p -> plane %"PRIu32,
-			    (void *)layer, plane->id);
+		j++;
+		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");
 
 		assert(plane->layer == NULL);
 		assert(layer->plane == NULL);
 		plane->layer = layer;
 		layer->plane = plane;
 	}
+	liftoff_log(LIFTOFF_DEBUG, "%s", i > 0 ? " " : "  No planes assigned!");
 
 	if (!apply_current(device, req)) {
 		return false;

include/log.h

@@ -15,4 +15,14 @@ void liftoff_log(enum liftoff_log_importance verbosity,
 		 const char *format, ...) _LIFTOFF_ATTRIB_PRINTF(2, 3);
 void liftoff_log_errno(enum liftoff_log_importance verbosity, const char *msg);
 
+struct liftoff_log_buffer {
+	char *data;
+	size_t len, cap;
+};
+
+void liftoff_log_buffer_append(struct liftoff_log_buffer *buf,
+							   const char *fmt, ...);
+void liftoff_log_buffer_flush(struct liftoff_log_buffer *buf,
+							  enum liftoff_log_importance verbosity);
+
 #endif

include/private.h

@@ -98,6 +98,7 @@ struct liftoff_plane_property *plane_get_property(struct liftoff_plane *plane,
 bool plane_apply(struct liftoff_plane *plane, struct liftoff_layer *layer,
 		 drmModeAtomicReq *req, bool *compatible);
 
+void output_log_planes(struct liftoff_output *output);
 void output_log_layers(struct liftoff_output *output);
 
 #endif

log.c

@@ -1,5 +1,6 @@
 #include <errno.h>
 #include <stdio.h>
+#include <stdlib.h>
 #include <string.h>
 #include "log.h"
 
@@ -45,3 +46,68 @@ void liftoff_log_errno(enum liftoff_log_importance verbosity, const char *msg)
 {
 	liftoff_log(verbosity, "%s: %s", msg, strerror(errno));
 }
+
+void liftoff_log_buffer_append(struct liftoff_log_buffer *buf,
+							   const char *fmt, ...)
+{
+	if (!buf) {
+		return;
+	}
+
+	va_list args;
+	va_start(args, fmt);
+
+	if (buf->data == NULL) {
+		buf->data = malloc(4096);
+		if (buf->data == NULL) {
+			liftoff_log_errno(LIFTOFF_ERROR, "malloc");
+			goto cleanup_out;
+		}
+		buf->len = 4096 / sizeof(char);
+	}
+
+	do {
+		size_t max_len = buf->len - buf->cap;
+		int ret;
+
+		ret = vsnprintf(buf->data + buf->cap, max_len, fmt, args);
+		if (ret < 0) {
+			goto cleanup_out;
+		}
+
+		if (ret - (int)max_len > 0) {
+			buf->cap = buf->len;
+			buf->len *= 2;
+
+			if (realloc(buf->data, buf->len) == NULL) {
+				liftoff_log_errno(LIFTOFF_ERROR, "realloc");
+				goto cleanup_out;
+			}
+		} else {
+			buf->cap += ret;
+			goto final_out;
+		}
+	} while (1);
+
+cleanup_out:
+	free(buf->data);
+	buf->data = NULL;
+	buf->cap = 0;
+	buf->len = 0;
+
+final_out:
+	va_end(args);
+}
+
+void liftoff_log_buffer_flush(struct liftoff_log_buffer *buf,
+							  enum liftoff_log_importance verbosity)
+{
+	if (!buf || !buf->data || buf->len == 0) {
+		return;
+	}
+	liftoff_log(verbosity, "%s\n", buf->data);
+	free(buf->data);
+	buf->data = NULL;
+	buf->cap = 0;
+	buf->len = 0;
+}

output.c

@@ -55,6 +55,99 @@ void liftoff_output_set_composition_layer(struct liftoff_output *output,
 	output->composition_layer = layer;
 }
 
+void output_log_planes(struct liftoff_output *output)
+{
+	struct liftoff_device *device;
+	struct liftoff_plane *plane;
+	drmModeObjectProperties *drm_props;
+	drmModePropertyRes *drm_prop;
+	size_t i;
+	int per_line, max_per_line;
+
+	device = output->device;
+
+	if (!log_has(LIFTOFF_DEBUG)) {
+		return;
+	}
+
+	liftoff_log(LIFTOFF_DEBUG, "Planes on CRTC %"PRIu32":", output->crtc_id);
+
+	liftoff_list_for_each(plane, &device->planes, link) {
+		bool active = false;
+
+		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;
+			}
+		}
+
+		struct liftoff_log_buffer log_buf = {0};
+		liftoff_log_buffer_append(&log_buf, "  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_buffer_append(&log_buf, "\n   ");
+				per_line = 0;
+			}
+
+			drm_prop = drmModeGetProperty(device->drm_fd,
+				drm_props->props[i]);
+			if (drm_prop == NULL) {
+				liftoff_log_buffer_append(&log_buf, "ERR!");
+				continue;
+			}
+
+			name = drm_prop->name;
+
+			if (strcmp(name, "type") == 0) {
+				liftoff_log_buffer_append(&log_buf, " %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_buffer_append(&log_buf, " %s: %"PRIi32, name,
+					(int32_t)value);
+				continue;
+			}
+
+			if (strcmp(name, "SRC_W") == 0 || strcmp(name, "SRC_H") == 0) {
+				value = value >> 16;
+			}
+			liftoff_log_buffer_append(&log_buf, " %s: %"PRIu64, name, value);
+		}
+		liftoff_log_buffer_flush(&log_buf, LIFTOFF_DEBUG);
+	}
+}
+
 void output_log_layers(struct liftoff_output *output) {
 	struct liftoff_layer *layer;
 	size_t i;
@@ -63,7 +156,7 @@ void output_log_layers(struct liftoff_output *output) {
 		return;
 	}
 
-	liftoff_log(LIFTOFF_DEBUG, "Layers on CRTC %"PRIu32":", output->crtc_id);
+	liftoff_log(LIFTOFF_DEBUG, "Available layers:");
 	liftoff_list_for_each(layer, &output->layers, link) {
 		if (layer->force_composition) {
 			liftoff_log(LIFTOFF_DEBUG, "  Layer %p "