diff --git a/libweston/input.c b/libweston/input.c index 25d3e75c5..bfd3763e5 100644 --- a/libweston/input.c +++ b/libweston/input.c @@ -51,6 +51,7 @@ #include "pointer-constraints-unstable-v1-server-protocol.h" #include "input-timestamps-unstable-v1-server-protocol.h" #include "tablet-unstable-v2-server-protocol.h" +#include "weston-trace.h" enum pointer_constraint_type { POINTER_CONSTRAINT_TYPE_LOCK, @@ -603,6 +604,10 @@ pointer_send_motion(struct weston_pointer *pointer, if (!pointer->focus_client) return; + WESTON_TRACE_ANNOTATE_PRINTF("pointer motion", "focus: %s, x: %.4f, y: %.4f", + pointer->focus->surface->label, + wl_fixed_to_double(sx), wl_fixed_to_double(sy)); + resource_list = &pointer->focus_client->pointer_resources; msecs = timespec_to_msec(time); wl_resource_for_each(resource, resource_list) { @@ -702,6 +707,9 @@ weston_pointer_send_button(struct weston_pointer *pointer, if (!weston_pointer_has_focus_resource(pointer)) return; + WESTON_TRACE_ANNOTATE_PRINTF("pointer button", "focus: %s, button: %.4d, state: %.4d", + pointer->focus->surface->label, button, state); + resource_list = &pointer->focus_client->pointer_resources; serial = wl_display_next_serial(display); msecs = timespec_to_msec(time); @@ -755,6 +763,11 @@ weston_pointer_send_axis(struct weston_pointer *pointer, if (!weston_pointer_has_focus_resource(pointer)) return; + WESTON_TRACE_ANNOTATE_PRINTF("pointer send axis", "focus: %s, axis: %d", + "has_discrete: %d, discrete: %d, value: %f", + pointer->focus->surface->label, event->axis, + event->has_discrete, event->discrete, event->value); + resource_list = &pointer->focus_client->pointer_resources; msecs = timespec_to_msec(time); wl_resource_for_each(resource, resource_list) { @@ -924,6 +937,10 @@ weston_touch_send_down(struct weston_touch *touch, const struct timespec *time, surf_pos = weston_coord_global_to_surface(touch->focus, pos); + WESTON_TRACE_ANNOTATE_PRINTF("touch send down", "focus: %s, id: %d " + "x: %.4f, y: %.4f", touch->focus->surface->label, + touch_id, surf_pos.c.x, surf_pos.c.y); + resource_list = &touch->focus_resource_list; serial = wl_display_next_serial(display); msecs = timespec_to_msec(time); @@ -970,6 +987,9 @@ weston_touch_send_up(struct weston_touch *touch, const struct timespec *time, if (!weston_touch_has_focus_resource(touch)) return; + WESTON_TRACE_ANNOTATE_PRINTF("touch send up", "focus: %s, id: %d", + touch->focus->surface->label, touch_id); + resource_list = &touch->focus_resource_list; serial = wl_display_next_serial(display); msecs = timespec_to_msec(time); @@ -1016,6 +1036,10 @@ weston_touch_send_motion(struct weston_touch *touch, surf_pos = weston_coord_global_to_surface(touch->focus, pos); + WESTON_TRACE_ANNOTATE_PRINTF("touch send motion", "focus: %s, id: %d, " + "x: %.4f, y: %.4f", touch->focus->surface->label, + touch_id, surf_pos.c.x, surf_pos.c.y); + resource_list = &touch->focus_resource_list; msecs = timespec_to_msec(time); wl_resource_for_each(resource, resource_list) { @@ -1118,6 +1142,10 @@ weston_keyboard_send_key(struct weston_keyboard *keyboard, if (!weston_keyboard_has_focus_resource(keyboard)) return; + WESTON_TRACE_ANNOTATE_PRINTF("keyboard event", "focus: %s, " + "code: %.4d, state: %.4d", + keyboard->focus->label, key, state); + resource_list = &keyboard->focus_resource_list; serial = wl_display_next_serial(display); msecs = timespec_to_msec(time); diff --git a/libweston/perfetto/u_perfetto.cc b/libweston/perfetto/u_perfetto.cc index 9d0a2eb99..eb425f901 100644 --- a/libweston/perfetto/u_perfetto.cc +++ b/libweston/perfetto/u_perfetto.cc @@ -32,6 +32,7 @@ #include "u_perfetto.h" #include +#include /* perfetto requires string literals */ #define UTIL_PERFETTO_CATEGORY_DEFAULT_STR "weston.default" @@ -80,6 +81,28 @@ util_perfetto_trace_begin(const char *name) [&](perfetto::EventContext ctx) { ctx.event()->set_name(name); }); } +void +util_perfetto_trace_begin_int(const char *name, const char *key, uint64_t value) +{ + TRACE_EVENT_BEGIN(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, nullptr, + [&](perfetto::EventContext ctx) { ctx.event()->set_name(name); + auto *annotation = ctx.event()->add_debug_annotations(); + annotation->set_name(key); + annotation->set_int_value(value); + }); +} + +void +util_perfetto_trace_begin_str(const char *name, const char *key, const char *value) +{ + TRACE_EVENT_BEGIN(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, nullptr, + [&](perfetto::EventContext ctx) { ctx.event()->set_name(name); + auto *annotation = ctx.event()->add_debug_annotations(); + annotation->set_name(key); + annotation->set_string_value(value); + }); +} + void util_perfetto_trace_end(void) { @@ -96,6 +119,79 @@ util_perfetto_trace_begin_flow(const char *fname, uint64_t id) [&](perfetto::EventContext ctx) { ctx.event()->set_name(fname); }); } +void +util_perfetto_trace_begin_flow_int(const char *fname, uint64_t id, + const char *key, uint64_t value) +{ + TRACE_EVENT_BEGIN(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, nullptr, + perfetto::Flow::ProcessScoped(id), + [&](perfetto::EventContext ctx) { ctx.event()->set_name(fname); + auto *annotation = ctx.event()->add_debug_annotations(); + annotation->set_name(key); + annotation->set_int_value(value); + }); +} + +void +util_perfetto_trace_begin_flow_str(const char *fname, uint64_t id, + const char *key, const char *value) +{ + TRACE_EVENT_BEGIN(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, nullptr, + perfetto::Flow::ProcessScoped(id), + [&](perfetto::EventContext ctx) { ctx.event()->set_name(fname); + auto *annotation = ctx.event()->add_debug_annotations(); + annotation->set_name(key); + annotation->set_string_value(value); + }); +} + +void +util_perfetto_trace_instant_add_int(const char *name, const char *key, uint64_t value) +{ + TRACE_EVENT_INSTANT(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, nullptr, + [&](perfetto::EventContext ctx) { ctx.event()->set_name(name); + auto *annotation = ctx.event()->add_debug_annotations(); + annotation->set_name(key); + annotation->set_int_value(value); + }); +} + + +void +util_perfetto_trace_instant_add_str(const char *name, const char *key, const char* value) +{ + TRACE_EVENT_BEGIN(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, nullptr, + [&](perfetto::EventContext ctx) { ctx.event()->set_name(name); + auto *annotation = ctx.event()->add_debug_annotations(); + annotation->set_name(key); + annotation->set_string_value(value); + }); +} + +void +util_perfetto_trace_instant_add_int_flow(const char *name, uint64_t id, const char *key, uint64_t value) +{ + TRACE_EVENT_INSTANT(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, nullptr, + perfetto::Flow::ProcessScoped(id), + [&](perfetto::EventContext ctx) { ctx.event()->set_name(name); + auto *annotation = ctx.event()->add_debug_annotations(); + annotation->set_name(key); + annotation->set_int_value(value); + }); +} + +void +util_perfetto_trace_instant_add_str_flow(const char *name, uint64_t id, const char *key, const char *value) +{ + TRACE_EVENT_INSTANT(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, nullptr, + perfetto::Flow::ProcessScoped(id), + [&](perfetto::EventContext ctx) { ctx.event()->set_name(name); + auto *annotation = ctx.event()->add_debug_annotations(); + annotation->set_name(key); + annotation->set_string_value(value); + }); +} + void util_perfetto_trace_full_begin(const char *fname, uint64_t track_id, uint64_t id, clockid_t clock, uint64_t timestamp) { @@ -109,11 +205,58 @@ util_perfetto_trace_full_begin(const char *fname, uint64_t track_id, uint64_t id return; } - TRACE_EVENT_BEGIN(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, - nullptr, - perfetto::Track(track_id), - perfetto::TraceTimestamp{clockid_to_perfetto_clock(clock), timestamp}, - [&](perfetto::EventContext ctx) { ctx.event()->set_name(fname); }); + TRACE_EVENT_BEGIN(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, + nullptr, + perfetto::Track(track_id), + perfetto::TraceTimestamp{clockid_to_perfetto_clock(clock), timestamp}, + [&](perfetto::EventContext ctx) { ctx.event()->set_name(fname); }); +} + +void +util_perfetto_trace_instant_printf(const char *name, const char *key, + const char *fmt, va_list args) +{ + int ret; + char tmp_buffer[512]; + size_t max_buff_len = sizeof(tmp_buffer); + char *msg = &tmp_buffer[0]; + + ret = vsnprintf(msg, max_buff_len, fmt, args); + if (ret < 0) + snprintf(msg, max_buff_len, "[printf format error]"); + if (ret > (int) max_buff_len) + snprintf(msg, max_buff_len, "[buffer too small to print]"); + + TRACE_EVENT_INSTANT(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, nullptr, + [&](perfetto::EventContext ctx) { ctx.event()->set_name(name); + + auto *annotation = ctx.event()->add_debug_annotations(); + annotation->set_name(key); + annotation->set_string_value(msg);}); +} + +void +util_perfetto_trace_instant_printf_flow(const char *name, uint64_t id, + const char *key, const char *fmt, va_list args) +{ + int ret; + char tmp_buffer[512]; + size_t max_buff_len = sizeof(tmp_buffer); + char *msg = &tmp_buffer[0]; + + ret = vsnprintf(msg, max_buff_len, fmt, args); + if (ret < 0) + snprintf(msg, max_buff_len, "[printf format error]"); + if (ret > (int) max_buff_len) + snprintf(msg, max_buff_len, "[buffer too small to print]"); + + TRACE_EVENT_INSTANT(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, nullptr, + perfetto::Flow::ProcessScoped(id), + [&](perfetto::EventContext ctx) { ctx.event()->set_name(name); + + auto *annotation = ctx.event()->add_debug_annotations(); + annotation->set_name(key); + annotation->set_string_value(msg);}); } uint64_t diff --git a/libweston/perfetto/u_perfetto.h b/libweston/perfetto/u_perfetto.h index 576348fce..63d9d0885 100644 --- a/libweston/perfetto/u_perfetto.h +++ b/libweston/perfetto/u_perfetto.h @@ -32,6 +32,7 @@ #include "stdint.h" #include +#include #include "u_atomic.h" @@ -53,10 +54,17 @@ util_perfetto_is_tracing_enabled(void) void util_perfetto_trace_begin(const char *name); +void util_perfetto_trace_begin_int(const char *name, const char *key, uint64_t value); +void util_perfetto_trace_begin_str(const char *name, const char *key, const char *value); + void util_perfetto_trace_end(void); void util_perfetto_trace_begin_flow(const char *fname, uint64_t id); +void util_perfetto_trace_begin_flow_int(const char *fname, uint64_t id, const char *key, uint64_t value); + +void util_perfetto_trace_begin_flow_str(const char *fname, uint64_t id, const char *key, const char *value); + void util_perfetto_counter_set(const char *name, double value); void util_perfetto_trace_full_begin(const char *name, uint64_t track_id, uint64_t id, clockid_t clock, uint64_t timestamp); @@ -67,6 +75,18 @@ uint64_t util_perfetto_next_id(void); uint64_t util_perfetto_new_track(const char *name); +void util_perfetto_trace_instant_add_int(const char *name, const char *key, uint64_t value); + +void util_perfetto_trace_instant_add_int_flow(const char *name, uint64_t id, const char *key, uint64_t value); + +void util_perfetto_trace_instant_add_str(const char *name, const char *key, const char* value); + +void util_perfetto_trace_instant_add_str_flow(const char *name, uint64_t id, const char *key, const char *value); + +void util_perfetto_trace_instant_printf(const char *name, const char *key, const char *fmt, va_list args); + +void util_perfetto_trace_instant_printf_flow(const char *name, uint64_t id, const char *key, const char *fmt, va_list args); + #else /* HAVE_PERFETTO */ static inline void diff --git a/libweston/renderer-gl/gl-renderer-internal.h b/libweston/renderer-gl/gl-renderer-internal.h index bc3845b3a..1eec1ee69 100644 --- a/libweston/renderer-gl/gl-renderer-internal.h +++ b/libweston/renderer-gl/gl-renderer-internal.h @@ -743,7 +743,7 @@ void gl_renderer_garbage_collect_programs(struct gl_renderer *gr); bool -gl_renderer_use_program(struct gl_renderer *gr, +gl_renderer_use_program(struct gl_renderer *gr, struct weston_paint_node *pnode, const struct gl_shader_config *sconf); struct weston_log_scope * diff --git a/libweston/renderer-gl/gl-renderer.c b/libweston/renderer-gl/gl-renderer.c index 00d72740f..e7930d000 100644 --- a/libweston/renderer-gl/gl-renderer.c +++ b/libweston/renderer-gl/gl-renderer.c @@ -68,6 +68,7 @@ #include "shared/weston-drm-fourcc.h" #include "shared/weston-egl-ext.h" #include "shared/xalloc.h" +#include "weston-trace.h" #define BUFFER_DAMAGE_COUNT 2 @@ -402,19 +403,20 @@ gl_log_paint_node_start(struct gl_renderer *gr, struct weston_paint_node *pnode) } static void -gl_log_paint_node_bbox_and_region(struct gl_renderer *gr, const char *str, +gl_log_paint_node_bbox_and_region(struct gl_renderer *gr, uint64_t perfetto_flow_id, const char *str, pixman_region32_t *damage) { pixman_box32_t *box; int32_t box_x, box_y; uint32_t box_width, box_height; int n_rects = 0; - const pixman_box32_t *rects = - pixman_region32_rectangles(damage, &n_rects); + const pixman_box32_t *rects = NULL; - if (!weston_log_scope_is_enabled(gr->paint_node_scope)) + if (!weston_log_scope_is_enabled(gr->paint_node_scope) && + !util_perfetto_is_tracing_enabled()) return; + rects = pixman_region32_rectangles(damage, &n_rects); box = pixman_region32_extents(damage); box_x = box->x1; @@ -422,10 +424,16 @@ gl_log_paint_node_bbox_and_region(struct gl_renderer *gr, const char *str, box_width = box->x2 - box->x1; box_height = box->y2 - box->y1; + WESTON_TRACE_ANNOTATE_PRINTF_FLOW(&perfetto_flow_id, "bounding box", + "%s, x: %5d, y: %5d, width: %d, height: %d", + str, box_x, box_y, box_width, box_height); + + if (!weston_log_scope_is_enabled(gr->paint_node_scope)) + return; + weston_log_scope_printf(gr->paint_node_scope, "\t\t%s bounding box: ", str); weston_log_scope_printf(gr->paint_node_scope, "x: %5d, y: %5d, width: " "%d, height: %d\n", box_x, box_y, box_width, box_height); - weston_log_scope_printf(gr->paint_node_scope, "\t\t%s has %d rectangles\n", str, n_rects); @@ -720,12 +728,12 @@ timeline_render_point_handler(int fd, uint32_t mask, void *data) TLP_GPU(&end), TLP_OUTPUT(trp->output), TLP_END); weston_log_scope_printf(gr->paint_node_scope, - "\tGPU Timeline:\n\t\tbegin: %" PRId64 ".%09ld" - " - end: %" PRId64 ".%09ld - elapsed: %.2f us\n", + "\tGPU activity:\n\t\tbegin: %" PRId64 ".%09ld" + " - end: %" PRId64 ".%09ld - active: %.2f us\n", (int64_t) begin.tv_sec, end.tv_nsec, (int64_t) begin.tv_sec, end.tv_nsec, (float) (elapsed / 1000)); - + WESTON_TRACE_SET_COUNTER("GPU active (us)", elapsed / 1000); } @@ -2154,18 +2162,24 @@ set_debug_mode(struct gl_renderer *gr, } static void -set_blend_state(struct gl_renderer *gr, - bool state) +set_blend_state(struct gl_renderer *gr, struct weston_paint_node *pnode, bool state) { + uint64_t p_id = 0; if (gr->blend_state == state) return; + if (pnode && pnode->surface) + p_id = pnode->surface->flow_id; + + (void) p_id; if (state) { glEnable(GL_BLEND); gl_log_paint_node(gr, "\t\tblending enabled\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&p_id, "blending", "enabled"); } else { glDisable(GL_BLEND); gl_log_paint_node(gr, "\t\tblending disabled\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&p_id, "blending", "enabled"); } gr->blend_state = state; } @@ -2180,13 +2194,14 @@ draw_mesh(struct gl_renderer *gr, int nidx, bool opaque) { + WESTON_TRACE_FUNC_FLOW(&pnode->surface->flow_id); struct gl_surface_state *gs = get_surface_state(pnode->surface); struct gl_buffer_state *gb = gs->buffer; GLint swizzle_a; assert(nidx > 0); - set_blend_state(gr, !opaque || pnode->view->alpha < 1.0); + set_blend_state(gr, pnode, !opaque || pnode->view->alpha < 1.0); /* Prevent translucent surfaces from punching holes through the * renderbuffer. */ @@ -2202,7 +2217,7 @@ draw_mesh(struct gl_renderer *gr, set_debug_mode(gr, sconf, barycentrics, opaque); gl_log_paint_node(gr, "\t\tdrawing paint node mesh\n"); - if (!gl_renderer_use_program(gr, sconf)) + if (!gl_renderer_use_program(gr, pnode, sconf)) gl_renderer_send_shader_error(pnode); /* Use fallback shader. */ glVertexAttribPointer(SHADER_ATTRIB_LOC_POSITION, 2, GL_FLOAT, GL_FALSE, @@ -2314,9 +2329,11 @@ weston_output_cvd_type_to_str(struct weston_cvd_correction cvd) } static void -apply_color_effect(struct gl_renderer *gr, struct weston_output *output, +apply_color_effect(struct gl_renderer *gr, struct weston_paint_node *pnode, + struct weston_output *output, float *r, float *g, float *b, const float a) { + WESTON_TRACE_FUNC_FLOW(&pnode->surface->flow_id); struct weston_compositor *compositor = output->compositor; struct weston_output_color_effect *effect = output->color_effect; struct weston_vec3f input = WESTON_VEC3F(*r, *g, *b); @@ -2339,12 +2356,16 @@ apply_color_effect(struct gl_renderer *gr, struct weston_output *output, *g = 1.0f - *g; *b = 1.0f - *b; gl_log_paint_node(gr, "\t\tcolor effect: inversion\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&pnode->surface->flow_id, + "color effect", "inversion"); return; case WESTON_OUTPUT_COLOR_EFFECT_TYPE_GRAYSCALE: *r = 0.2126f * (*r) + 0.7152f * (*g) + 0.0722f * (*b); *g = *r; *b = *r; gl_log_paint_node(gr, "\t\tcolor effect: grayscale\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&pnode->surface->flow_id, + "color effect", "greyscale"); return; case WESTON_OUTPUT_COLOR_EFFECT_TYPE_CVD_CORRECTION: /** @@ -2358,6 +2379,8 @@ apply_color_effect(struct gl_renderer *gr, struct weston_output *output, weston_log_scope_printf(gr->paint_node_scope, "\t\tcolor effect: cvd - %s\n", weston_output_cvd_type_to_str(effect->u.cvd)); + WESTON_TRACE_ANNOTATE_PRINTF_FLOW(&pnode->surface->flow_id, "color effect", "cvd - %s", + weston_output_cvd_type_to_str(effect->u.cvd)); return; }; weston_assert_not_reached(compositor, "unknown color effect type"); @@ -2381,13 +2404,13 @@ clear_region(struct gl_renderer *gr, struct weston_paint_node *pnode, /* We must be either fully transparent - punching a hole for an * underlay - or fully opaque, to use clear rather than blending. */ assert(pnode->solid.a == 0.0f || pnode->solid.a == 1.0f); - set_blend_state(gr, false); + set_blend_state(gr, pnode, false); r = pnode->solid.r; g = pnode->solid.g; b = pnode->solid.b; a = pnode->solid.a; - apply_color_effect(gr, output, &r, &g, &b, a); + apply_color_effect(gr, pnode, output, &r, &g, &b, a); glClearColor(r, g, b, a); glEnable(GL_SCISSOR_TEST); @@ -2404,6 +2427,7 @@ static void draw_paint_node(struct weston_paint_node *pnode, pixman_region32_t *damage /* in global coordinates */) { + WESTON_TRACE_FUNC_FLOW(&pnode->surface->flow_id); struct gl_renderer *gr = get_renderer(pnode->surface->compositor); struct gl_surface_state *gs = get_surface_state(pnode->surface); /* repaint bounding region in global coordinates: */ @@ -2420,14 +2444,20 @@ draw_paint_node(struct weston_paint_node *pnode, pixman_region32_intersect(&repaint, &pnode->visible, damage); gl_log_paint_node_start(gr, pnode); + WESTON_TRACE_ANNOTATE_PRINTF_FLOW(&pnode->surface->flow_id, "label", "%s #%d", + pnode->surface->label, pnode->surface->s_id); if (!pixman_region32_not_empty(&repaint)) { gl_log_paint_node(gr, "\t\tskipped repaint: repaint region empty\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&pnode->surface->flow_id, "skipped repaint", + "repaint region empty"); goto out; } if (pnode->is_fully_transparent) { gl_log_paint_node(gr, "\t\tskipped repaint: paint node transparent\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&pnode->surface->flow_id, "skipped repaint", + "paint node transparent"); gs->used_in_output_repaint = true; /* sort of */ goto out; } @@ -2436,18 +2466,24 @@ draw_paint_node(struct weston_paint_node *pnode, pnode->valid_transform && (pnode->surf_xform_valid && !pnode->surf_xform.transform)) { gl_log_paint_node(gr, "\t\toptimize: using glClear\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&pnode->surface->flow_id, "optimized", + "using glClear"); clear_region(gr, pnode, &repaint); gs->used_in_output_repaint = true; goto out; } if (ensure_surface_buffer_is_ready(gr, gs, pnode) < 0) { - gl_log_paint_node(gr, "\t\tskip repaint: buffer not ready\n"); + gl_log_paint_node(gr, "\t\tskipped repaint: buffer not ready\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&pnode->surface->flow_id, "skipped repaint", + "buffer not ready"); goto out; } if (!gl_shader_config_init_for_paint_node(&sconf, pnode)) { - gl_log_paint_node(gr, "\t\tskip repaint: shader config failure\n"); + gl_log_paint_node(gr, "\t\tskipped repaint: shader config failure\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&pnode->surface->flow_id, "skipped repaint", + "shared config failured"); goto out; } @@ -2474,11 +2510,13 @@ draw_paint_node(struct weston_paint_node *pnode, pixman_region32_subtract(&surface_blend, &surface_blend, &surface_opaque); - gl_log_paint_node_bbox_and_region(gr, "repaint region", &repaint); + gl_log_paint_node_bbox_and_region(gr, pnode->surface->flow_id, + "repaint region", &repaint); if (pixman_region32_not_empty(&surface_opaque)) { transform_damage(pnode, &repaint, &quads, &nquads); - gl_log_paint_node_bbox_and_region(gr, "opaque region", &surface_opaque); + gl_log_paint_node_bbox_and_region(gr, pnode->surface->flow_id, + "opaque region", &surface_opaque); repaint_region(gr, pnode, quads, nquads, &surface_opaque, &sconf, true); gs->used_in_output_repaint = true; @@ -2486,7 +2524,8 @@ draw_paint_node(struct weston_paint_node *pnode, if (pixman_region32_not_empty(&surface_blend)) { transform_damage(pnode, &repaint, &quads, &nquads); - gl_log_paint_node_bbox_and_region(gr, "blended region", &surface_blend); + gl_log_paint_node_bbox_and_region(gr, pnode->surface->flow_id, + "blended region", &surface_blend); repaint_region(gr, pnode, quads, nquads, &surface_blend, &sconf, false); gs->used_in_output_repaint = true; @@ -2706,7 +2745,7 @@ draw_output_border_texture(struct gl_renderer *gr, sconf->input_num = 1; gl_log_paint_node(gr, "\t\tdrawing output border texture\n"); - gl_renderer_use_program(gr, sconf); + gl_renderer_use_program(gr, NULL, sconf); GLfloat texcoord[] = { 0.0f, 0.0f, @@ -2755,7 +2794,7 @@ draw_output_borders(struct weston_output *output, return; } - set_blend_state(gr, false); + set_blend_state(gr, NULL, false); glViewport(0, 0, fb->width, fb->height); weston_matrix_init(&sconf.projection); @@ -2827,8 +2866,8 @@ blit_shadow_to_output(struct weston_output *output, pixman_region32_init(&translated_damage); gl_log_paint_node(gr, "\t\tdrawing shadow output\n"); - gl_renderer_use_program(gr, &sconf); - set_blend_state(gr, false); + gl_renderer_use_program(gr, NULL, &sconf); + set_blend_state(gr, NULL, false); /* output_damage is in global coordinates */ pixman_region32_intersect(&translated_damage, output_damage, @@ -4308,7 +4347,7 @@ gl_renderer_surface_copy_content(struct weston_surface *surface, } glViewport(0, 0, cw, ch); - set_blend_state(gr, false); + set_blend_state(gr, NULL, false); if (buffer->buffer_origin == ORIGIN_TOP_LEFT) ARRAY_COPY(sconf.projection.M.colmaj, projmat_normal); else @@ -4317,7 +4356,7 @@ gl_renderer_surface_copy_content(struct weston_surface *surface, WESTON_MATRIX_TRANSFORM_TRANSLATE; gl_log_paint_node(gr, "\t\tcopying surface\n"); - if (!gl_renderer_use_program(gr, &sconf)) + if (!gl_renderer_use_program(gr, NULL, &sconf)) goto use_program_error; glEnableVertexAttribArray(SHADER_ATTRIB_LOC_POSITION); diff --git a/libweston/renderer-gl/gl-shaders.c b/libweston/renderer-gl/gl-shaders.c index 1eab6d89e..22c411939 100644 --- a/libweston/renderer-gl/gl-shaders.c +++ b/libweston/renderer-gl/gl-shaders.c @@ -46,6 +46,7 @@ #include "shared/helpers.h" #include "shared/timespec-util.h" #include "shared/weston-assert.h" +#include "weston-trace.h" /* static const char vertex_shader[]; vertex.glsl */ #include "vertex-shader.h" @@ -813,7 +814,7 @@ gl_shader_texture_variant_get_target(enum gl_shader_texture_variant v) } static void -gl_shader_load_config(struct gl_renderer *gr, +gl_shader_load_config(struct gl_renderer *gr, uint64_t flow_id, struct gl_shader *shader, const struct gl_shader_config *sconf) { @@ -835,6 +836,10 @@ gl_shader_load_config(struct gl_renderer *gr, "\t\tcolor: r: %.2f, g: %.2f, b: %.2f, a: %.2f\n", sconf->unicolor[0], sconf->unicolor[1], sconf->unicolor[2], sconf->unicolor[3]); + WESTON_TRACE_ANNOTATE_PRINTF_FLOW(&flow_id, "color", + "r: %.2f, g: %.2f, b: %.2f, a: %.2f", + sconf->unicolor[0], sconf->unicolor[1], + sconf->unicolor[2], sconf->unicolor[3]); glUniform4fv(shader->color_uniform, 1, sconf->unicolor); } if (shader->tint_uniform != -1) { @@ -842,10 +847,15 @@ gl_shader_load_config(struct gl_renderer *gr, "\t\ttint: r: %.2f, g: %.2f, b: %.2f, a: %.2f\n", sconf->tint[0], sconf->tint[1], sconf->tint[2], sconf->tint[3]); + WESTON_TRACE_ANNOTATE_PRINTF_FLOW(&flow_id, "tint", + "r: %.2f, g: %.2f, b: %.2f, a: %.2f", + sconf->tint[0], sconf->tint[1], + sconf->tint[2], sconf->tint[3]); glUniform4fv(shader->tint_uniform, 1, sconf->tint); } weston_log_scope_printf(gr->paint_node_scope, "\t\talpha: %.2f\n", sconf->view_alpha); + WESTON_TRACE_ANNOTATE_PRINTF_FLOW(&flow_id, "alpha", "%.2f", sconf->view_alpha); glUniform1f(shader->view_alpha_uniform, sconf->view_alpha); assert(sconf->input_num <= SHADER_INPUT_TEX_MAX); @@ -890,14 +900,18 @@ gl_shader_load_config(struct gl_renderer *gr, break; case SHADER_COLOR_EFFECT_INVERSION: weston_log_scope_printf(gr->paint_node_scope, "\t\tcolor effect: inversion\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&flow_id, "color effect", "inversion"); break; case SHADER_COLOR_EFFECT_GRAYSCALE: weston_log_scope_printf(gr->paint_node_scope, "\t\tcolor effect: grayscale\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&flow_id, "color effect", "greyscale"); break; case SHADER_COLOR_EFFECT_CVD_CORRECTION: weston_assert_int_ne(gr->compositor, shader->cvd_correction_uniform, -1); weston_log_scope_printf(gr->paint_node_scope, "\t\tcolor effect: cvd - %s\n", weston_output_cvd_type_to_str(sconf->color_effect.cvd)); + WESTON_TRACE_ANNOTATE_PRINTF_FLOW(&flow_id, "color effect", "cvd - %s", + weston_output_cvd_type_to_str(sconf->color_effect.cvd)); glUniformMatrix3fv(shader->cvd_correction_uniform, 1, GL_FALSE, sconf->color_effect.cvd.correction.colmaj); @@ -923,11 +937,17 @@ gl_shader_load_config(struct gl_renderer *gr, } bool -gl_renderer_use_program(struct gl_renderer *gr, +gl_renderer_use_program(struct gl_renderer *gr, struct weston_paint_node *pnode, const struct gl_shader_config *sconf) { static const GLfloat fallback_shader_color[4] = { 0.2, 0.1, 0.0, 1.0 }; struct gl_shader *shader; + uint64_t p_flow_id = 0; + + if (pnode && pnode->surface) + p_flow_id = pnode->surface->flow_id; + + WESTON_TRACE_FUNC_FLOW(&p_flow_id); shader = gl_renderer_get_program(gr, &sconf->req); if (!shader) { @@ -948,6 +968,9 @@ gl_renderer_use_program(struct gl_renderer *gr, glUniform1f(shader->view_alpha_uniform, 1.0f); weston_log_scope_printf(gr->paint_node_scope, "\t\tFailed to generate shader program. " "Using the fallback shader\n"); + WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(&p_flow_id, + "Failed to generate shader program", + "Using fallback shader"); return false; } @@ -965,7 +988,7 @@ gl_renderer_use_program(struct gl_renderer *gr, weston_log_scope_printf(gr->paint_node_scope, "\t\t\tshader id: %d\n", gr->current_shader->program); - gl_shader_load_config(gr, shader, sconf); + gl_shader_load_config(gr, p_flow_id, shader, sconf); return true; } diff --git a/libweston/surface-state.c b/libweston/surface-state.c index 3c31a0aad..4d7bd88a1 100644 --- a/libweston/surface-state.c +++ b/libweston/surface-state.c @@ -204,6 +204,14 @@ weston_surface_attach(struct weston_surface *surface, struct weston_buffer *buffer = state->buffer_ref.buffer; struct weston_buffer *old_buffer = surface->buffer_ref.buffer; + if (buffer) { + WESTON_TRACE_ANNOTATE_PRINTF_FLOW(&surface->flow_id, "buffer information", + "format: %s, modifier: %s, size: %dx%d", + buffer->pixel_format->drm_format_name, + buffer->format_modifier_name, + buffer->width, buffer->height); + } + if (!buffer) { if (weston_surface_is_mapped(surface)) { weston_surface_unmap(surface); diff --git a/libweston/weston-trace.h b/libweston/weston-trace.h index 154663157..ac79322ba 100644 --- a/libweston/weston-trace.h +++ b/libweston/weston-trace.h @@ -37,12 +37,60 @@ util_perfetto_trace_begin(name); \ } while (0) +#define _WESTON_TRACE_BEGIN_INT(name, key, value) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_begin_int(name, key, value); \ + } while (0) + +#define _WESTON_TRACE_BEGIN_STR(name, key, value) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_begin_str(name, key, value); \ + } while (0) + #define _WESTON_TRACE_FLOW_BEGIN(name, id) \ do { \ if (unlikely(util_perfetto_is_tracing_enabled())) \ util_perfetto_trace_begin_flow(name, id); \ } while (0) +#define _WESTON_TRACE_FLOW_BEGIN_INT(name, id, key, value) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_begin_flow_int(name, id, key, value); \ + } while (0) + +#define _WESTON_TRACE_FLOW_BEGIN_STR(name, id, key, value) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_begin_flow_str(name, id, key, value); \ + } while (0) + +#define _WESTON_TRACE_INSTANT_ADD_INT(name, key, value) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_instant_add_int(name, key, value); \ + } while (0) + +#define _WESTON_TRACE_INSTANT_ADD_STR(name, key, value) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_instant_add_str(name, key, value); \ + } while (0) + +#define _WESTON_TRACE_INSTANT_ADD_INT_FLOW(name, id, key, value) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_instant_add_int_flow(name, id, key, value); \ + } while (0) + +#define _WESTON_TRACE_INSTANT_ADD_STR_FLOW(name, id, key, value) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_instant_add_str_flow(name, id, key, value); \ + } while (0) + #define _WESTON_TRACE_END() \ do { \ if (unlikely(util_perfetto_is_tracing_enabled())) \ @@ -69,6 +117,18 @@ clock, timestamp); \ } while (0) +#define _WESTON_TRACE_INSTANT_PRINTF(name, key, fmt, ...) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_instant_printf(name, key, fmt, ##__VA_ARGS__); \ + } while (0) + +#define _WESTON_TRACE_INSTANT_PRINTF_FLOW(name, id, key, fmt, valist) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_instant_printf_flow(name, id, key, fmt, valist); \ + } while (0) + #if __has_attribute(cleanup) && __has_attribute(unused) #define _WESTON_TRACE_SCOPE_VAR_CONCAT(name, suffix) name##suffix @@ -92,6 +152,44 @@ __attribute__((cleanup(_weston_trace_scope_end), unused)) = \ _weston_trace_scope_flow_begin(name, id) +#define _WESTON_TRACE_ANNOTATE_INT(name, key, value) \ + int _WESTON_TRACE_SCOPE_VAR(__LINE__) \ + __attribute__((cleanup(_weston_trace_scope_end), unused)) = \ + _weston_trace_scope_begin_int(name, key, value) + +#define _WESTON_TRACE_ANNOTATE_STR(name, key, value) \ + int _WESTON_TRACE_SCOPE_VAR(__LINE__) \ + __attribute__((cleanup(_weston_trace_scope_end), unused)) = \ + _weston_trace_scope_begin_str(name, key, value) + +#define _WESTON_TRACE_ANNOTATE_INT_FLOW(name, id, key, value) \ + int _WESTON_TRACE_SCOPE_VAR(__LINE__) \ + __attribute__((cleanup(_weston_trace_scope_end), unused)) = \ + _weston_trace_scope_flow_begin_int(name, id, key, value) + +#define _WESTON_TRACE_ANNOTATE_STR_FLOW(name, id, key, value) \ + int _WESTON_TRACE_SCOPE_VAR(__LINE__) \ + __attribute__((cleanup(_weston_trace_scope_end), unused)) = \ + _weston_trace_scope_flow_begin_str(name, id, key, value) + +#define _WESTON_TRACE_ANNOTATE_ADD_INT(name, key, value) \ + _weston_trace_scope_instant_add_int(name, key, value) + +#define _WESTON_TRACE_ANNOTATE_ADD_STR(name, key, value) \ + _weston_trace_scope_instant_add_str(name, key, value) + +#define _WESTON_TRACE_ANNOTATE_ADD_INT_FLOW(name, id, key, value) \ + _weston_trace_scope_instant_add_int_flow(name, id, key, value) + +#define _WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(name, id, key, value) \ + _weston_trace_scope_instant_add_str_flow(name, id, key, value) + +#define _WESTON_TRACE_ANNOTATE_PRINTF(name, key, fmt, ...) \ + _weston_trace_scope_instant_printf(name, key, fmt, ##__VA_ARGS__) + +#define _WESTON_TRACE_ANNOTATE_PRINTF_FLOW(name, id, key, fmt, ...) \ + _weston_trace_scope_instant_printf_flow(name, id, key, fmt, ##__VA_ARGS__) + static inline int _weston_trace_scope_begin(const char *name) { @@ -99,6 +197,54 @@ _weston_trace_scope_begin(const char *name) return 0; } +static inline int +_weston_trace_scope_instant_add_int(const char *name, const char *key, uint64_t value) +{ + _WESTON_TRACE_INSTANT_ADD_INT(name, key, value); + return 0; +} + +static inline int +_weston_trace_scope_instant_add_int_flow(const char *name, uint64_t *id, const char *key, uint64_t value) +{ + if (*id == 0) + *id = util_perfetto_next_id(); + + _WESTON_TRACE_INSTANT_ADD_INT_FLOW(name, *id, key, value); + return 0; +} + +static inline int +_weston_trace_scope_instant_add_str(const char *name, const char *key, const char *value) +{ + _WESTON_TRACE_INSTANT_ADD_STR(name, key, value); + return 0; +} + +static inline int +_weston_trace_scope_instant_add_str_flow(const char *name, uint64_t *id, + const char *key, const char *value) +{ + if (*id == 0) + *id = util_perfetto_next_id(); + _WESTON_TRACE_INSTANT_ADD_STR_FLOW(name, *id, key, value); + return 0; +} + +static inline int +_weston_trace_scope_begin_int(const char *name, const char *key, uint64_t value) +{ + _WESTON_TRACE_BEGIN_INT(name, key, value); + return 0; +} + +static inline int +_weston_trace_scope_begin_str(const char *name, const char *key, const char *value) +{ + _WESTON_TRACE_BEGIN_STR(name, key, value); + return 0; +} + static inline int _weston_trace_scope_flow_begin(const char *name, uint64_t *id) { @@ -108,6 +254,51 @@ _weston_trace_scope_flow_begin(const char *name, uint64_t *id) return 0; } +static inline int +_weston_trace_scope_flow_begin_int(const char *name, uint64_t *id, const char *key, uint64_t value) +{ + if (*id == 0) + *id = util_perfetto_next_id(); + _WESTON_TRACE_FLOW_BEGIN_INT(name, *id, key, value); + return 0; +} + +static inline int +_weston_trace_scope_flow_begin_str(const char *name, uint64_t *id, const char *key, const char *value) +{ + if (*id == 0) + *id = util_perfetto_next_id(); + _WESTON_TRACE_FLOW_BEGIN_STR(name, *id, key, value); + return 0; +} + +static inline int +_weston_trace_scope_instant_printf(const char *name, const char *key, const char *fmt, ...) +{ + va_list args; + va_start(args, fmt); + + _WESTON_TRACE_INSTANT_PRINTF(name, key, fmt, args); + + va_end(args); + return 0; +} + +static inline int +_weston_trace_scope_instant_printf_flow(const char *name, uint64_t *id, const char *key, const char *fmt, ...) +{ + va_list args; + va_start(args, fmt); + + if (*id == 0) + *id = util_perfetto_next_id(); + + _WESTON_TRACE_INSTANT_PRINTF_FLOW(name, *id, key, fmt, args); + + va_end(args); + return 0; +} + static inline void _weston_trace_scope_end(int *scope) { @@ -130,6 +321,21 @@ _weston_trace_scope_end(int *scope) #define _WESTON_TRACE_TIMESTAMP_BEGIN(name, track_id, flow_id, clock, timestamp) #define _WESTON_TRACE_TIMESTAMP_END(name, track_id, clock, timestamp) +#define _WESTON_TRACE_ANNOTATE_INT(name, key, value) +#define _WESTON_TRACE_ANNOTATE_STR(name, key, value) + +#define _WESTON_TRACE_ANNOTATE_INT_FLOW(name, id, key, value) +#define _WESTON_TRACE_ANNOTATE_STR_FLOW(name, id, key, value) + +#define _WESTON_TRACE_ANNOTATE_ADD_INT(name, key, value) +#define _WESTON_TRACE_ANNOTATE_ADD_STR(name, key, value) + +#define _WESTON_TRACE_ANNOTATE_ADD_INT_FLOW(name, id, key, value) +#define _WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(name, id, key, value) + +#define _WESTON_TRACE_ANNOTATE_PRINTF(name, key, fmt, ...) +#define _WESTON_TRACE_ANNOTATE_PRINTF_FLOW(name, id, key, fmt, ...) + #endif /* HAVE_PERFETTO */ #define WESTON_TRACE_SCOPE(name) _WESTON_TRACE_SCOPE(name) @@ -142,4 +348,34 @@ _weston_trace_scope_end(int *scope) #define WESTON_TRACE_TIMESTAMP_END(name, track_id, clock, timestamp) \ _WESTON_TRACE_TIMESTAMP_END(name, track_id, clock, timestamp) +/* these assume you haven't started WESTON_TRACE_FUNC() */ +#define WESTON_TRACE_ANNOTATE_INT(key, value) \ + _WESTON_TRACE_ANNOTATE_INT(__func__, key, value) +#define WESTON_TRACE_ANNOTATE_STR(key, value) \ + _WESTON_TRACE_ANNOTATE_STR(__func__, key, value) + +/* these assume you haven't started with WESTON_TRACE_FUNC() */ +#define WESTON_TRACE_ANNOTATE_INT_FLOW(id, key, value) \ + _WESTON_TRACE_ANNOTATE_INT_FLOW(__func__, id, key, value) +#define WESTON_TRACE_ANNOTATE_STR_FLOW(id, key, value) \ + _WESTON_TRACE_ANNOTATE_STR_FLOW(__func__, id, key, value) + +/* these assume you've started with WESTON_TRACE_FUNC() */ +#define WESTON_TRACE_ANNOTATE_ADD_INT(key, value) \ + _WESTON_TRACE_ANNOTATE_ADD_INT(__func__, key, value) +#define WESTON_TRACE_ANNOTATE_ADD_STR(key, value) \ + _WESTON_TRACE_ANNOTATE_ADD_STR(__func__, key, value) + +/* these assume you've started with WESTON_TRACE_FUNC() */ +#define WESTON_TRACE_ANNOTATE_ADD_INT_FLOW(id, key, value) \ + _WESTON_TRACE_ANNOTATE_ADD_INT_FLOW(__func__, id, key, value) +#define WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(id, key, value) \ + _WESTON_TRACE_ANNOTATE_ADD_STR_FLOW(__func__, id, key, value) + +/* these assume you've started with WESTON_TRACE_FUNC() */ +#define WESTON_TRACE_ANNOTATE_PRINTF(key, fmt, ...) \ + _WESTON_TRACE_ANNOTATE_PRINTF(__func__, key, fmt, ##__VA_ARGS__) +#define WESTON_TRACE_ANNOTATE_PRINTF_FLOW(id, key, fmt, ...) \ + _WESTON_TRACE_ANNOTATE_PRINTF_FLOW(__func__, id, key, fmt, ##__VA_ARGS__) + #endif /* WESTON_TRACE_H */