From 1cbe1f952de2b22539e163c0055fa3dcbb2e2d54 Mon Sep 17 00:00:00 2001 From: Daniel Stone Date: Fri, 20 Jul 2018 10:21:28 +0100 Subject: [PATCH 18/46] compositor-drm: Add drm-backend log debug scope Add a 'drm-debug' scope which prints verbose information about the DRM backend's repaint cycle, including the decision tree on how views are assigned (or not) to planes. Signed-off-by: Daniel Stone --- libweston/compositor-drm.c | 285 ++++++++++++++++++++++++++++++++++++++++----- 1 file changed, 258 insertions(+), 27 deletions(-) diff --git a/libweston/compositor-drm.c b/libweston/compositor-drm.c index 612e6a8f..b21793e5 100644 --- a/libweston/compositor-drm.c +++ b/libweston/compositor-drm.c @@ -51,6 +51,7 @@ #include "compositor.h" #include "compositor-drm.h" +#include "weston-debug.h" #include "shared/helpers.h" #include "shared/timespec-util.h" #include "gl-renderer.h" @@ -73,6 +74,42 @@ #define GBM_BO_USE_CURSOR GBM_BO_USE_CURSOR_64X64 #endif +/** + * A small wrapper to print information into the 'drm-backend' debug scope. + * + * The following conventions are used to print variables: + * + * - fixed uint32_t values, including Weston object IDs such as weston_output + * IDs, DRM object IDs such as CRTCs or properties, and GBM/DRM formats: + * "%lu (0x%lx)" (unsigned long) value, (unsigned long) value + * + * - fixed uint64_t values, such as DRM property values (including object IDs + * when used as a value): + * "%llu (0x%llx)" (unsigned long long) value, (unsigned long long) value + * + * - non-fixed-width signed int: + * "%d" value + * + * - non-fixed-width unsigned int: + * "%u (0x%x)" value, value + * + * - non-fixed-width unsigned long: + * "%lu (0x%lx)" value, value + * + * Either the integer or hexadecimal forms may be omitted if it is known that + * one representation is not useful (e.g. width/height in hex are rarely what + * you want). + * + * This is to avoid implicit widening or narrowing when we use fixed-size + * types: uint32_t can be resolved by either unsigned int or unsigned long + * on a 32-bit system but only unsigned int on a 64-bit system, with uint64_t + * being unsigned long long on a 32-bit system and unsigned long on a 64-bit + * system. To avoid confusing side effects, we explicitly cast to the widest + * possible type and use a matching format specifier. + */ +#define drm_debug(b, ...) \ + weston_debug_scope_printf((b)->debug, __VA_ARGS__) + #define MAX_CLONED_CONNECTORS 4 /** @@ -302,6 +339,8 @@ struct drm_backend { bool shutting_down; bool aspect_ratio_supported; + + struct weston_debug_scope *debug; }; struct drm_mode { @@ -2357,6 +2396,10 @@ crtc_add_prop(drmModeAtomicReq *req, struct drm_output *output, ret = drmModeAtomicAddProperty(req, output->crtc_id, info->prop_id, val); + drm_debug(output->backend, "\t\t\t[CRTC:%lu] %lu (%s) -> %llu (0x%llx)\n", + (unsigned long) output->crtc_id, + (unsigned long) info->prop_id, info->name, + (unsigned long long) val, (unsigned long long) val); return (ret <= 0) ? -1 : 0; } @@ -2372,6 +2415,10 @@ connector_add_prop(drmModeAtomicReq *req, struct drm_head *head, ret = drmModeAtomicAddProperty(req, head->connector_id, info->prop_id, val); + drm_debug(head->backend, "\t\t\t[CONN:%lu] %lu (%s) -> %llu (0x%llx)\n", + (unsigned long) head->connector_id, + (unsigned long) info->prop_id, info->name, + (unsigned long long) val, (unsigned long long) val); return (ret <= 0) ? -1 : 0; } @@ -2387,6 +2434,10 @@ plane_add_prop(drmModeAtomicReq *req, struct drm_plane *plane, ret = drmModeAtomicAddProperty(req, plane->plane_id, info->prop_id, val); + drm_debug(plane->backend, "\t\t\t[PLANE:%lu] %lu (%s) -> %llu (0x%llx)\n", + (unsigned long) plane->plane_id, + (unsigned long) info->prop_id, info->name, + (unsigned long long) val, (unsigned long long) val); return (ret <= 0) ? -1 : 0; } @@ -2405,6 +2456,9 @@ drm_mode_ensure_blob(struct drm_backend *backend, struct drm_mode *mode) if (ret != 0) weston_log("failed to create mode property blob: %m\n"); + drm_debug(backend, "\t\t\t[atomic] created new mode blob %lu for %s", + (unsigned long) mode->blob_id, mode->mode_info.name); + return ret; } @@ -2414,17 +2468,23 @@ drm_output_apply_state_atomic(struct drm_output_state *state, uint32_t *flags) { struct drm_output *output = state->output; - struct drm_backend *backend = to_drm_backend(output->base.compositor); + struct drm_backend *b = to_drm_backend(output->base.compositor); struct drm_plane_state *plane_state; struct drm_mode *current_mode = to_drm_mode(output->base.current_mode); struct drm_head *head; int ret = 0; - if (state->dpms != output->state_cur->dpms) + drm_debug(b, "\t\t[atomic] %s output %lu (%s) state\n", + (*flags & DRM_MODE_ATOMIC_TEST_ONLY) ? "testing" : "applying", + (unsigned long) output->base.id, output->base.name); + + if (state->dpms != output->state_cur->dpms) { + drm_debug(b, "\t\t\t[atomic] DPMS state differs, modeset OK\n"); *flags |= DRM_MODE_ATOMIC_ALLOW_MODESET; + } if (state->dpms == WESTON_DPMS_ON) { - ret = drm_mode_ensure_blob(backend, current_mode); + ret = drm_mode_ensure_blob(b, current_mode); if (ret != 0) return ret; @@ -2522,6 +2582,9 @@ drm_pending_state_apply_atomic(struct drm_pending_state *pending_state, uint32_t *unused; int err; + drm_debug(b, "\t\t[atomic] previous state invalid; " + "starting with fresh state\n"); + /* If we need to reset all our state (e.g. because we've * just started, or just been VT-switched in), explicitly * disable all the CRTCs and connectors we aren't using. */ @@ -2534,9 +2597,16 @@ drm_pending_state_apply_atomic(struct drm_pending_state *pending_state, head = to_drm_head(head_base); + drm_debug(b, "\t\t[atomic] disabling inactive head %s\n", + head_base->name); + info = &head->props_conn[WDRM_CONNECTOR_CRTC_ID]; err = drmModeAtomicAddProperty(req, head->connector_id, info->prop_id, 0); + drm_debug(b, "\t\t\t[CONN:%lu] %lu (%s) -> 0\n", + (unsigned long) head->connector_id, + (unsigned long) info->prop_id, + info->name); if (err <= 0) ret = -1; } @@ -2573,12 +2643,21 @@ drm_pending_state_apply_atomic(struct drm_pending_state *pending_state, continue; } + drm_debug(b, "\t\t[atomic] disabling unused CRTC %lu\n", + (unsigned long) *unused); + + drm_debug(b, "\t\t\t[CRTC:%lu] %lu (%s) -> 0\n", + (unsigned long) *unused, + (unsigned long) info->prop_id, info->name); err = drmModeAtomicAddProperty(req, *unused, info->prop_id, 0); if (err <= 0) ret = -1; info = &infos[WDRM_CRTC_MODE_ID]; + drm_debug(b, "\t\t\t[CRTC:%lu] %lu (%s) -> 0\n", + (unsigned long) *unused, + (unsigned long) info->prop_id, info->name); err = drmModeAtomicAddProperty(req, *unused, info->prop_id, 0); if (err <= 0) @@ -2590,6 +2669,8 @@ drm_pending_state_apply_atomic(struct drm_pending_state *pending_state, /* Disable all the planes; planes which are being used will * override this state in the output-state application. */ wl_list_for_each(plane, &b->plane_list, link) { + drm_debug(b, "\t\t[atomic] starting with plane %lu disabled\n", + (unsigned long) plane->plane_id); plane_add_prop(req, plane, WDRM_PLANE_CRTC_ID, 0); plane_add_prop(req, plane, WDRM_PLANE_FB_ID, 0); } @@ -2972,6 +3053,14 @@ drm_repaint_begin(struct weston_compositor *compositor) ret = drm_pending_state_alloc(b); b->repaint_data = ret; + if (weston_debug_scope_is_enabled(b->debug)) { + char *dbg = weston_compositor_print_scene_graph(compositor); + drm_debug(b, "[repaint] Beginning repaint; pending_state %p\n", + ret); + drm_debug(b, "%s", dbg); + free(dbg); + } + return ret; } @@ -2991,6 +3080,7 @@ drm_repaint_flush(struct weston_compositor *compositor, void *repaint_data) struct drm_pending_state *pending_state = repaint_data; drm_pending_state_apply(pending_state); + drm_debug(b, "[repaint] flushed pending_state %p\n", pending_state); b->repaint_data = NULL; } @@ -3007,6 +3097,7 @@ drm_repaint_cancel(struct weston_compositor *compositor, void *repaint_data) struct drm_pending_state *pending_state = repaint_data; drm_pending_state_free(pending_state); + drm_debug(b, "[repaint] cancel pending_state %p\n", pending_state); b->repaint_data = NULL; } @@ -3050,12 +3141,21 @@ drm_output_prepare_overlay_view(struct drm_output_state *output_state, struct drm_fb *fb; unsigned int i; int ret; + enum { + NO_PLANES, + NO_PLANES_WITH_FORMAT, + NO_PLANES_ACCEPTED, + PLACED_ON_PLANE, + } availability = NO_PLANES; assert(!b->sprites_are_broken); fb = drm_fb_get_from_view(output_state, ev); - if (!fb) + if (!fb) { + drm_debug(b, "\t\t\t\t[overlay] not placing view %p on overlay: " + " couldn't get fb\n", ev); return NULL; + } wl_list_for_each(p, &b->plane_list, link) { if (p->type != WDRM_PLANE_TYPE_OVERLAY) @@ -3064,6 +3164,15 @@ drm_output_prepare_overlay_view(struct drm_output_state *output_state, if (!drm_plane_is_available(p, output)) continue; + state = drm_output_state_get_plane(output_state, p); + if (state->fb) { + state = NULL; + continue; + } + + if (availability == NO_PLANES) + availability = NO_PLANES_WITH_FORMAT; + /* Check whether the format is supported */ for (i = 0; i < p->count_formats; i++) { unsigned int j; @@ -3084,15 +3193,14 @@ drm_output_prepare_overlay_view(struct drm_output_state *output_state, if (i == p->count_formats) continue; - state = drm_output_state_get_plane(output_state, p); - if (state->fb) { - state = NULL; - continue; - } + if (availability == NO_PLANES_WITH_FORMAT) + availability = NO_PLANES_ACCEPTED; state->ev = ev; state->output = output; if (!drm_plane_state_coords_for_view(state, ev)) { + drm_debug(b, "\t\t\t\t[overlay] not placing view %p on overlay: " + "unsuitable transform\n", ev); drm_plane_state_put_back(state); state = NULL; continue; @@ -3100,6 +3208,8 @@ drm_output_prepare_overlay_view(struct drm_output_state *output_state, if (!b->atomic_modeset && (state->src_w != state->dest_w << 16 || state->src_h != state->dest_h << 16)) { + drm_debug(b, "\t\t\t\t[overlay] not placing view %p on overlay: " + "no scaling without atomic\n", ev); drm_plane_state_put_back(state); state = NULL; continue; @@ -3113,17 +3223,48 @@ drm_output_prepare_overlay_view(struct drm_output_state *output_state, /* In planes-only mode, we don't have an incremental state to * test against, so we just hope it'll work. */ - if (mode == DRM_OUTPUT_PROPOSE_STATE_PLANES_ONLY) + if (mode == DRM_OUTPUT_PROPOSE_STATE_PLANES_ONLY) { + drm_debug(b, "\t\t\t\t[overlay] provisionally placing " + "view %p on overlay %lu in planes-only mode\n", + ev, (unsigned long) p->plane_id); + availability = PLACED_ON_PLANE; goto out; + } ret = drm_pending_state_test(output_state->pending_state); - if (ret == 0) + if (ret == 0) { + drm_debug(b, "\t\t\t\t[overlay] provisionally placing " + "view %p on overlay %d in mixed mode\n", + ev, p->plane_id); + availability = PLACED_ON_PLANE; goto out; + } + + drm_debug(b, "\t\t\t\t[overlay] not placing view %p on overlay %lu " + "in mixed mode: kernel test failed\n", + ev, (unsigned long) p->plane_id); drm_plane_state_put_back(state); state = NULL; } + switch (availability) { + case NO_PLANES: + drm_debug(b, "\t\t\t\t[overlay] not placing view %p on overlay: " + "no free overlay planes\n", ev); + break; + case NO_PLANES_WITH_FORMAT: + drm_debug(b, "\t\t\t\t[overlay] not placing view %p on overlay: " + "no free overlay planes matching format 0x%lx, " + "modifier 0x%llx\n", + ev, (unsigned long) fb->format, + (unsigned long long) fb->modifier); + break; + case NO_PLANES_ACCEPTED: + case PLACED_ON_PLANE: + break; + } + out: drm_fb_unref(fb); return state; @@ -3192,13 +3333,23 @@ drm_output_prepare_cursor_view(struct drm_output_state *output_state, if (b->gbm == NULL) return NULL; - if (ev->surface->buffer_ref.buffer == NULL) + if (ev->surface->buffer_ref.buffer == NULL) { + drm_debug(b, "\t\t\t\t[cursor] not assigning view %p to cursor plane " + "(no buffer available)\n", ev); return NULL; + } shmbuf = wl_shm_buffer_get(ev->surface->buffer_ref.buffer->resource); - if (!shmbuf) + if (!shmbuf) { + drm_debug(b, "\t\t\t\t[cursor] not assigning view %p to cursor plane " + "(buffer isn't SHM)\n", ev); return NULL; - if (wl_shm_buffer_get_format(shmbuf) != WL_SHM_FORMAT_ARGB8888) + } + if (wl_shm_buffer_get_format(shmbuf) != WL_SHM_FORMAT_ARGB8888) { + drm_debug(b, "\t\t\t\t[cursor] not assigning view %p to cursor plane " + "(format 0x%lx unsuitable)\n", + ev, (unsigned long) wl_shm_buffer_get_format(shmbuf)); return NULL; + } plane_state = drm_output_state_get_plane(output_state, output->cursor_plane); @@ -3216,8 +3367,11 @@ drm_output_prepare_cursor_view(struct drm_output_state *output_state, plane_state->src_w > (unsigned) b->cursor_width << 16 || plane_state->src_h > (unsigned) b->cursor_height << 16 || plane_state->src_w != plane_state->dest_w << 16 || - plane_state->src_h != plane_state->dest_h << 16) + plane_state->src_h != plane_state->dest_h << 16) { + drm_debug(b, "\t\t\t\t[cursor] not assigning view %p to cursor plane " + "(positioning requires cropping or scaling)\n", ev); goto err; + } /* Since we're setting plane state up front, we need to work out * whether or not we need to upload a new cursor. We can't use the @@ -3240,8 +3394,10 @@ drm_output_prepare_cursor_view(struct drm_output_state *output_state, plane_state->fb = drm_fb_ref(output->gbm_cursor_fb[output->current_cursor]); - if (needs_update) + if (needs_update) { + drm_debug(b, "\t\t\t\t[cursor] copying new content to cursor BO\n"); cursor_bo_update(plane_state, ev); + } /* The cursor API is somewhat special: in cursor_bo_update(), we upload * a buffer which is always cursor_width x cursor_height, even if the @@ -3252,6 +3408,9 @@ drm_output_prepare_cursor_view(struct drm_output_state *output_state, plane_state->dest_w = b->cursor_width; plane_state->dest_h = b->cursor_height; + drm_debug(b, "\t\t\t\t[cursor] provisionally assigned view %p to cursor\n", + ev); + return plane_state; err: @@ -3347,18 +3506,32 @@ drm_output_propose_state(struct weston_output *output_base, if (!scanout_fb || (scanout_fb->type != BUFFER_GBM_SURFACE && scanout_fb->type != BUFFER_PIXMAN_DUMB)) { + drm_debug(b, "\t\t[state] cannot propose mixed mode: " + "for output %s (%lu): no previous renderer " + "fb\n", + output->base.name, + (unsigned long) output->base.id); drm_output_state_free(state); return NULL; } if (scanout_fb->width != output_base->current_mode->width || scanout_fb->height != output_base->current_mode->height) { + drm_debug(b, "\t\t[state] cannot propose mixed mode " + "for output %s (%lu): previous fb has " + "different size\n", + output->base.name, + (unsigned long) output->base.id); drm_output_state_free(state); return NULL; } scanout_state = drm_plane_state_duplicate(state, plane->state_cur); + drm_debug(b, "\t\t[state] using renderer FB ID %lu for mixed " + "mode for output %s (%lu)\n", + (unsigned long) scanout_fb->fb_id, output->base.name, + (unsigned long) output->base.id); } /* @@ -3384,18 +3557,32 @@ drm_output_propose_state(struct weston_output *output_base, bool totally_occluded = false; bool overlay_occluded = false; + drm_debug(b, "\t\t\t[view] evaluating view %p for " + "output %s (%lu)\n", + ev, output->base.name, + (unsigned long) output->base.id); + /* If this view doesn't touch our output at all, there's no * reason to do anything with it. */ - if (!(ev->output_mask & (1u << output->base.id))) + if (!(ev->output_mask & (1u << output->base.id))) { + drm_debug(b, "\t\t\t\t[view] ignoring view %p " + "(not on our output)\n", ev); continue; + } /* We only assign planes to views which are exclusively present * on our output. */ - if (ev->output_mask != (1u << output->base.id)) + if (ev->output_mask != (1u << output->base.id)) { + drm_debug(b, "\t\t\t\t[view] not assigning view %p to plane " + "(on multiple outputs)\n", ev); force_renderer = true; + } - if (!ev->surface->buffer_ref.buffer) + if (!ev->surface->buffer_ref.buffer) { + drm_debug(b, "\t\t\t\t[view] not assigning view %p to plane " + "(no buffer available)\n", ev); force_renderer = true; + } /* Ignore views we know to be totally occluded. */ pixman_region32_init(&clipped_view); @@ -3408,6 +3595,8 @@ drm_output_propose_state(struct weston_output *output_base, &occluded_region); totally_occluded = !pixman_region32_not_empty(&surface_overlap); if (totally_occluded) { + drm_debug(b, "\t\t\t\t[view] ignoring view %p " + "(occluded on our output)\n", ev); pixman_region32_fini(&surface_overlap); pixman_region32_fini(&clipped_view); continue; @@ -3418,8 +3607,11 @@ drm_output_propose_state(struct weston_output *output_base, * be part of, or occluded by, it, and cannot go on a plane. */ pixman_region32_intersect(&surface_overlap, &renderer_region, &clipped_view); - if (pixman_region32_not_empty(&surface_overlap)) + if (pixman_region32_not_empty(&surface_overlap)) { + drm_debug(b, "\t\t\t\t[view] not assigning view %p to plane " + "(occluded by renderer views)\n", ev); force_renderer = true; + } /* We do not control the stacking order of overlay planes; * the scanout plane is strictly stacked bottom and the cursor @@ -3428,8 +3620,11 @@ drm_output_propose_state(struct weston_output *output_base, * planes overlapping each other. */ pixman_region32_intersect(&surface_overlap, &occluded_region, &clipped_view); - if (pixman_region32_not_empty(&surface_overlap)) + if (pixman_region32_not_empty(&surface_overlap)) { + drm_debug(b, "\t\t\t\t[view] not assigning view %p to plane " + "(occluded by other overlay planes)\n", ev); overlay_occluded = true; + } pixman_region32_fini(&surface_overlap); /* The cursor plane is 'special' in the sense that we can still @@ -3441,10 +3636,16 @@ drm_output_propose_state(struct weston_output *output_base, /* If sprites are disabled or the view is not fully opaque, we * must put the view into the renderer - unless it has already * been placed in the cursor plane, which can handle alpha. */ - if (!ps && !planes_ok) + if (!ps && !planes_ok) { + drm_debug(b, "\t\t\t\t[view] not assigning view %p to plane " + "(precluded by mode)\n", ev); force_renderer = true; - if (!ps && !drm_view_is_opaque(ev)) + } + if (!ps && !drm_view_is_opaque(ev)) { + drm_debug(b, "\t\t\t\t[view] not assigning view %p to plane " + "(view not fully opaque)\n", ev); force_renderer = true; + } /* Only try to place scanout surfaces in planes-only mode; in * mixed mode, we have already failed to place a view on the @@ -3477,6 +3678,9 @@ drm_output_propose_state(struct weston_output *output_base, * check if this is OK, and add ourselves to the renderer * region if so. */ if (!renderer_ok) { + drm_debug(b, "\t\t[view] failing state generation: " + "placing view %p to renderer not allowed\n", + ev); pixman_region32_fini(&clipped_view); goto err_region; } @@ -3496,8 +3700,11 @@ drm_output_propose_state(struct weston_output *output_base, /* Check to see if this state will actually work. */ ret = drm_pending_state_test(state->pending_state); - if (ret != 0) + if (ret != 0) { + drm_debug(b, "\t\t[view] failing state generation: " + "atomic test not OK\n"); goto err; + } /* Counterpart to duplicating scanout state at the top of this * function: if we have taken a renderer framebuffer and placed it in @@ -3530,12 +3737,24 @@ drm_assign_planes(struct weston_output *output_base, void *repaint_data) struct weston_view *ev; struct weston_plane *primary = &output_base->compositor->primary_plane; + drm_debug(b, "\t[repaint] preparing state for output %s (%lu)\n", + output_base->name, (unsigned long) output_base->id); + if (!b->sprites_are_broken) { state = drm_output_propose_state(output_base, pending_state, DRM_OUTPUT_PROPOSE_STATE_PLANES_ONLY); - if (!state) + if (!state) { + drm_debug(b, "\t[repaint] could not build planes-only " + "state, trying mixed\n"); state = drm_output_propose_state(output_base, pending_state, DRM_OUTPUT_PROPOSE_STATE_MIXED); + } + if (!state) { + drm_debug(b, "\t[repaint] could not build mixed-mode " + "state, trying renderer-only\n"); + } + } else { + drm_debug(b, "\t[state] no overlay plane support\n"); } if (!state) @@ -3582,10 +3801,16 @@ drm_assign_planes(struct weston_output *output_base, void *repaint_data) } } - if (target_plane) + if (target_plane) { + drm_debug(b, "\t[repaint] view %p on %s plane %lu\n", + ev, plane_type_enums[target_plane->type].name, + (unsigned long) target_plane->plane_id); weston_view_move_to_plane(ev, &target_plane->base); - else + } else { + drm_debug(b, "\t[repaint] view %p using renderer " + "composition\n", ev); weston_view_move_to_plane(ev, primary); + } if (!target_plane || target_plane->type == WDRM_PLANE_TYPE_CURSOR) { @@ -6264,6 +6489,8 @@ drm_destroy(struct weston_compositor *ec) destroy_sprites(b); + weston_debug_scope_destroy(b->debug); + b->debug = NULL; weston_compositor_shutdown(ec); wl_list_for_each_safe(base, next, &ec->head_list, compositor_link) @@ -6725,6 +6952,10 @@ drm_backend_create(struct weston_compositor *compositor, b->pageflip_timeout = config->pageflip_timeout; b->use_pixman_shadow = config->use_pixman_shadow; + b->debug = weston_compositor_add_debug_scope(compositor, "drm-backend", + "Debug messages from DRM/KMS backend\n", + NULL, NULL); + compositor->backend = &b->base; if (parse_gbm_format(config->gbm_format, GBM_FORMAT_XRGB8888, &b->gbm_format) < 0) -- 2.16.2