[weston,v2,2/2] compositor: Implement JSON-timeline logging

Submitted by Pekka Paalanen on Dec. 2, 2014, 1:45 p.m.

Details

Message ID 1417527946-13413-2-git-send-email-ppaalanen@gmail.com
State Superseded
Headers show

Not browsing as part of any series.

Commit Message

Pekka Paalanen Dec. 2, 2014, 1:45 p.m.
From: Pekka Paalanen <pekka.paalanen@collabora.co.uk>

Logging is activated and deactivated with the debug key binding 't'.
When activated, it creates a new log file, where it records the events.
The log file contains events and detailed object information entries in
JSON format, and is meant to be parsed in sequence from beginning to the
end.

The emitted events are mostly related to the output repaint cycle, like
when repaint begins, is submitted to GPU, and when it completes on a
vblank. This is recorded per-output. Also some per-surface events are
recorded, including when surface damage is flushed.

To reduce the log size, events refer to objects like outputs and
surfaces by id numbers. Detailed object information is emitted only as
needed: on the first object occurrence, and afterwards only if
weston_timeline_object::force_refresh asks for it.

The detailed information for surfaces includes the string returned by
weston_surface::get_label. Therefore it is important to set
weston_timeline_object::force_refresh = 1 whenever the string would
change, so that the new details get recorded.

A rudimentary parser and SVG generator can be found at:
https://github.com/ppaalanen/wesgr

The timeline logs can answer questions including:
- How does the compositor repaint cycle work timing-wise?
- When was the vblank deadline missed?
- What is the latency from surface commit to showing the new content on
  screen?
- How long does it take to process the scenegraph?

v2: weston_surface::get_description renamed to get_label.

Signed-off-by: Pekka Paalanen <pekka.paalanen@collabora.co.uk>
---
 Makefile.am           |   4 +
 desktop-shell/shell.c |  28 +++--
 src/compositor.c      |  40 +++++++
 src/compositor.h      |   5 +
 src/timeline-object.h |  52 +++++++++
 src/timeline.c        | 286 ++++++++++++++++++++++++++++++++++++++++++++++++++
 src/timeline.h        |  62 +++++++++++
 7 files changed, 468 insertions(+), 9 deletions(-)
 create mode 100644 src/timeline-object.h
 create mode 100644 src/timeline.c
 create mode 100644 src/timeline.h

Patch hide | download patch | download mbox

diff --git a/Makefile.am b/Makefile.am
index e942850..d7b909a 100644
--- a/Makefile.am
+++ b/Makefile.am
@@ -62,6 +62,9 @@  weston_SOURCES =					\
 	src/noop-renderer.c				\
 	src/pixman-renderer.c				\
 	src/pixman-renderer.h				\
+	src/timeline.c					\
+	src/timeline.h					\
+	src/timeline-object.h				\
 	shared/matrix.c					\
 	shared/matrix.h					\
 	shared/zalloc.h					\
@@ -150,6 +153,7 @@  westonincludedir = $(includedir)/weston
 westoninclude_HEADERS =				\
 	src/version.h				\
 	src/compositor.h			\
+	src/timeline-object.h			\
 	shared/matrix.h				\
 	shared/config-parser.h			\
 	shared/zalloc.h
diff --git a/desktop-shell/shell.c b/desktop-shell/shell.c
index b6f5f78..a7514f7 100644
--- a/desktop-shell/shell.c
+++ b/desktop-shell/shell.c
@@ -2244,6 +2244,14 @@  set_title(struct shell_surface *shsurf, const char *title)
 {
 	free(shsurf->title);
 	shsurf->title = strdup(title);
+	shsurf->surface->timeline.force_refresh = 1;
+}
+
+static void
+set_type(struct shell_surface *shsurf, enum shell_surface_type t)
+{
+	shsurf->type = t;
+	shsurf->surface->timeline.force_refresh = 1;
 }
 
 static void
@@ -2274,6 +2282,7 @@  shell_surface_set_class(struct wl_client *client,
 
 	free(shsurf->class);
 	shsurf->class = strdup(class);
+	shsurf->surface->timeline.force_refresh = 1;
 }
 
 static void
@@ -2440,7 +2449,7 @@  set_toplevel(struct shell_surface *shsurf)
 {
 	shell_surface_set_parent(shsurf, NULL);
 	surface_clear_next_states(shsurf);
-	shsurf->type = SHELL_SURFACE_TOPLEVEL;
+	set_type(shsurf, SHELL_SURFACE_TOPLEVEL);
 
 	/* The layer_link is updated in set_surface_type(),
 	 * called from configure. */
@@ -2471,7 +2480,7 @@  set_transient(struct shell_surface *shsurf,
 
 	shsurf->next_state.relative = true;
 	shsurf->state_changed = true;
-	shsurf->type = SHELL_SURFACE_TOPLEVEL;
+	set_type(shsurf, SHELL_SURFACE_TOPLEVEL);
 
 	/* The layer_link is updated in set_surface_type(),
 	 * called from configure. */
@@ -2497,7 +2506,7 @@  set_fullscreen(struct shell_surface *shsurf,
 	       struct weston_output *output)
 {
 	shell_surface_set_output(shsurf, output);
-	shsurf->type = SHELL_SURFACE_TOPLEVEL;
+	set_type(shsurf, SHELL_SURFACE_TOPLEVEL);
 
 	shsurf->fullscreen_output = shsurf->output;
 	shsurf->fullscreen.type = method;
@@ -2582,7 +2591,7 @@  set_popup(struct shell_surface *shsurf,
 	shsurf->popup.x = x;
 	shsurf->popup.y = y;
 
-	shsurf->type = SHELL_SURFACE_POPUP;
+	set_type(shsurf, SHELL_SURFACE_POPUP);
 }
 
 static void
@@ -2686,7 +2695,7 @@  shell_surface_set_maximized(struct wl_client *client,
 	shsurf->next_state.maximized = true;
 	shsurf->state_changed = true;
 
-	shsurf->type = SHELL_SURFACE_TOPLEVEL;
+	set_type(shsurf, SHELL_SURFACE_TOPLEVEL);
 	shell_surface_set_parent(shsurf, NULL);
 
 	if (output_resource)
@@ -2974,7 +2983,7 @@  set_xwayland(struct shell_surface *shsurf, int x, int y, uint32_t flags)
 
 	shell_surface_set_parent(shsurf, NULL);
 
-	shsurf->type = SHELL_SURFACE_XWAYLAND;
+	set_type(shsurf, SHELL_SURFACE_XWAYLAND);
 	shsurf->state_changed = true;
 }
 
@@ -3576,7 +3585,7 @@  create_common_surface(struct shell_client *owner, void *shell,
 	wl_list_init(&shsurf->children_list);
 	shsurf->parent = NULL;
 
-	shsurf->type = SHELL_SURFACE_NONE;
+	set_type(shsurf, SHELL_SURFACE_NONE);
 
 	shsurf->client = client;
 
@@ -3703,6 +3712,7 @@  xdg_surface_set_app_id(struct wl_client *client,
 
 	free(shsurf->class);
 	shsurf->class = strdup(app_id);
+	shsurf->surface->timeline.force_refresh = 1;
 }
 
 static void
@@ -3932,7 +3942,7 @@  create_xdg_surface(struct shell_client *owner, void *shell,
 	if (!shsurf)
 		return NULL;
 
-	shsurf->type = SHELL_SURFACE_TOPLEVEL;
+	set_type(shsurf, SHELL_SURFACE_TOPLEVEL);
 
 	return shsurf;
 }
@@ -4014,7 +4024,7 @@  create_xdg_popup(struct shell_client *owner, void *shell,
 	if (!shsurf)
 		return NULL;
 
-	shsurf->type = SHELL_SURFACE_POPUP;
+	set_type(shsurf, SHELL_SURFACE_POPUP);
 	shsurf->popup.shseat = seat;
 	shsurf->popup.serial = serial;
 	shsurf->popup.x = x;
diff --git a/src/compositor.c b/src/compositor.c
index af9022c..420e825 100644
--- a/src/compositor.c
+++ b/src/compositor.c
@@ -53,6 +53,8 @@ 
 #include <libunwind.h>
 #endif
 
+#include "timeline.h"
+
 #include "compositor.h"
 #include "scaler-server-protocol.h"
 #include "presentation_timing-server-protocol.h"
@@ -1778,6 +1780,11 @@  surface_flush_damage(struct weston_surface *surface)
 	    wl_shm_buffer_get(surface->buffer_ref.buffer->resource))
 		surface->compositor->renderer->flush_damage(surface);
 
+	if (weston_timeline_enabled_ &&
+	    pixman_region32_not_empty(&surface->damage))
+		TL_POINT("core_flush_damage", TLP_SURFACE(surface),
+			 TLP_OUTPUT(surface->output), TLP_END);
+
 	pixman_region32_clear(&surface->damage);
 }
 
@@ -2002,6 +2009,8 @@  weston_output_repaint(struct weston_output *output)
 	if (output->destroying)
 		return 0;
 
+	TL_POINT("core_repaint_begin", TLP_OUTPUT(output), TLP_END);
+
 	/* Rebuild the surface list and update surface transforms up front. */
 	weston_compositor_build_view_list(ec);
 
@@ -2057,6 +2066,8 @@  weston_output_repaint(struct weston_output *output)
 		animation->frame(animation, output, output->frame_time);
 	}
 
+	TL_POINT("core_repaint_posted", TLP_OUTPUT(output), TLP_END);
+
 	return r;
 }
 
@@ -2080,6 +2091,9 @@  weston_output_finish_frame(struct weston_output *output,
 	int fd, r;
 	uint32_t refresh_nsec;
 
+	TL_POINT("core_repaint_finished", TLP_OUTPUT(output),
+		 TLP_VBLANK(stamp), TLP_END);
+
 	refresh_nsec = 1000000000000UL / output->current_mode->refresh;
 	weston_presentation_feedback_present_list(&output->feedback_list,
 						  output, refresh_nsec, stamp,
@@ -2096,6 +2110,8 @@  weston_output_finish_frame(struct weston_output *output,
 	}
 
 	output->repaint_scheduled = 0;
+	TL_POINT("core_repaint_exit_loop", TLP_OUTPUT(output), TLP_END);
+
 	if (compositor->input_loop_source)
 		return;
 
@@ -2172,6 +2188,9 @@  weston_output_schedule_repaint(struct weston_output *output)
 	    compositor->state == WESTON_COMPOSITOR_OFFSCREEN)
 		return;
 
+	if (!output->repaint_needed)
+		TL_POINT("core_repaint_req", TLP_OUTPUT(output), TLP_END);
+
 	loop = wl_display_get_event_loop(compositor->wl_display);
 	output->repaint_needed = 1;
 	if (output->repaint_scheduled)
@@ -2179,6 +2198,8 @@  weston_output_schedule_repaint(struct weston_output *output)
 
 	wl_event_loop_add_idle(loop, idle_repaint, output);
 	output->repaint_scheduled = 1;
+	TL_POINT("core_repaint_enter_loop", TLP_OUTPUT(output), TLP_END);
+
 
 	if (compositor->input_loop_source) {
 		wl_event_source_remove(compositor->input_loop_source);
@@ -2350,6 +2371,9 @@  weston_surface_commit_state(struct weston_surface *surface,
 	state->buffer_viewport.changed = 0;
 
 	/* wl_surface.damage */
+	if (weston_timeline_enabled_ &&
+	    pixman_region32_not_empty(&state->damage))
+		TL_POINT("core_commit_damage", TLP_SURFACE(surface), TLP_END);
 	pixman_region32_union(&surface->damage, &surface->damage,
 			      &state->damage);
 	pixman_region32_intersect_rect(&surface->damage, &surface->damage,
@@ -2819,6 +2843,7 @@  weston_surface_set_label_func(struct weston_surface *surface,
 					  char *, size_t))
 {
 	surface->get_label = desc;
+	surface->timeline.force_refresh = 1;
 }
 
 static void
@@ -4024,6 +4049,18 @@  weston_environment_get_fd(const char *env)
 	return fd;
 }
 
+static void
+timeline_key_binding_handler(struct weston_seat *seat, uint32_t time,
+			     uint32_t key, void *data)
+{
+	struct weston_compositor *compositor = data;
+
+	if (weston_timeline_enabled_)
+		weston_timeline_close();
+	else
+		weston_timeline_open(compositor);
+}
+
 WL_EXPORT int
 weston_compositor_init(struct weston_compositor *ec,
 		       struct wl_display *display,
@@ -4121,6 +4158,9 @@  weston_compositor_init(struct weston_compositor *ec,
 	weston_layer_init(&ec->fade_layer, &ec->layer_list);
 	weston_layer_init(&ec->cursor_layer, &ec->fade_layer.link);
 
+	weston_compositor_add_debug_binding(ec, KEY_T,
+					    timeline_key_binding_handler, ec);
+
 	weston_compositor_schedule_repaint(ec);
 
 	return 0;
diff --git a/src/compositor.h b/src/compositor.h
index d2574af..3f7ed4a 100644
--- a/src/compositor.h
+++ b/src/compositor.h
@@ -40,6 +40,7 @@  extern "C" {
 #include "matrix.h"
 #include "config-parser.h"
 #include "zalloc.h"
+#include "timeline-object.h"
 
 #ifndef MIN
 #define MIN(x,y) (((x) < (y)) ? (x) : (y))
@@ -234,6 +235,8 @@  struct weston_output {
 			  uint16_t *r,
 			  uint16_t *g,
 			  uint16_t *b);
+
+	struct weston_timeline_object timeline;
 };
 
 struct weston_pointer_grab;
@@ -915,6 +918,8 @@  struct weston_surface {
 	 * and replace role_name with configure.
 	 */
 	const char *role_name;
+
+	struct weston_timeline_object timeline;
 };
 
 struct weston_subsurface {
diff --git a/src/timeline-object.h b/src/timeline-object.h
new file mode 100644
index 0000000..3716b04
--- /dev/null
+++ b/src/timeline-object.h
@@ -0,0 +1,52 @@ 
+/*
+ * Copyright © 2014 Pekka Paalanen <pq@iki.fi>
+ * Copyright © 2014 Collabora, Ltd.
+ *
+ * Permission to use, copy, modify, distribute, and sell this software and
+ * its documentation for any purpose is hereby granted without fee, provided
+ * that the above copyright notice appear in all copies and that both that
+ * copyright notice and this permission notice appear in supporting
+ * documentation, and that the name of the copyright holders not be used in
+ * advertising or publicity pertaining to distribution of the software
+ * without specific, written prior permission.  The copyright holders make
+ * no representations about the suitability of this software for any
+ * purpose.  It is provided "as is" without express or implied warranty.
+ *
+ * THE COPYRIGHT HOLDERS DISCLAIM ALL WARRANTIES WITH REGARD TO THIS
+ * SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND
+ * FITNESS, IN NO EVENT SHALL THE COPYRIGHT HOLDERS BE LIABLE FOR ANY
+ * SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER
+ * RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF
+ * CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN
+ * CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
+ */
+
+#ifndef WESTON_TIMELINE_OBJECT_H
+#define WESTON_TIMELINE_OBJECT_H
+
+/*
+ * This struct can be embedded in objects related to timeline output.
+ * It must be initialized to all-zero. Afterwards, the timeline code
+ * will handle it alone. No clean-up is necessary.
+ */
+struct weston_timeline_object {
+	/*
+	 * Timeline series gets bumped every time a new log is opened.
+	 * This triggers id allocation and object info emission.
+	 * 0 is an invalid series value.
+	 */
+	unsigned series;
+
+	/* Object id in the timeline JSON output. 0 is invalid. */
+	unsigned id;
+
+	/*
+	 * If non-zero, forces a re-emission of object description.
+	 * Should be set to non-zero, when changing long-lived
+	 * object state that is not emitted on normal timeline
+	 * events.
+	 */
+	unsigned force_refresh;
+};
+
+#endif /* WESTON_TIMELINE_OBJECT_H */
diff --git a/src/timeline.c b/src/timeline.c
new file mode 100644
index 0000000..4116158
--- /dev/null
+++ b/src/timeline.c
@@ -0,0 +1,286 @@ 
+/*
+ * Copyright © 2014 Pekka Paalanen <pq@iki.fi>
+ * Copyright © 2014 Collabora, Ltd.
+ *
+ * Permission to use, copy, modify, distribute, and sell this software and
+ * its documentation for any purpose is hereby granted without fee, provided
+ * that the above copyright notice appear in all copies and that both that
+ * copyright notice and this permission notice appear in supporting
+ * documentation, and that the name of the copyright holders not be used in
+ * advertising or publicity pertaining to distribution of the software
+ * without specific, written prior permission.  The copyright holders make
+ * no representations about the suitability of this software for any
+ * purpose.  It is provided "as is" without express or implied warranty.
+ *
+ * THE COPYRIGHT HOLDERS DISCLAIM ALL WARRANTIES WITH REGARD TO THIS
+ * SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND
+ * FITNESS, IN NO EVENT SHALL THE COPYRIGHT HOLDERS BE LIABLE FOR ANY
+ * SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER
+ * RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF
+ * CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN
+ * CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
+ */
+
+#include "config.h"
+
+#include <stdio.h>
+#include <errno.h>
+#include <string.h>
+#include <time.h>
+#include <assert.h>
+
+#include "timeline.h"
+#include "compositor.h"
+
+struct timeline_log {
+	clock_t clk_id;
+	FILE *file;
+	unsigned series;
+	struct wl_listener compositor_destroy_listener;
+};
+
+WL_EXPORT int weston_timeline_enabled_;
+static struct timeline_log timeline_ = { CLOCK_MONOTONIC, NULL, 0 };
+
+static int
+weston_timeline_do_open(void)
+{
+	time_t t;
+	struct tm *tmp;
+	char fname[1000];
+	int ret;
+
+	t = time(NULL);
+	tmp = localtime(&t);
+	if (!tmp) {
+		weston_log("Conversion to local time failed, "
+			   "cannot open timeline log file.\n");
+		return -1;
+	}
+
+	ret = strftime(fname, sizeof(fname),
+		       "weston-timeline-%F_%H-%M-%S.log", tmp);
+	if (ret == 0) {
+		weston_log("Time formatting failed, "
+			   "cannot open timeline log file.\n");
+		return -1;
+	}
+
+	timeline_.file = fopen(fname, "w");
+	if (!timeline_.file) {
+		weston_log("Cannot open '%s' for writing: %s\n",
+			   fname, strerror(errno));
+		return -1;
+	}
+
+	weston_log("Opened timeline file '%s'\n", fname);
+
+	return 0;
+}
+
+static void
+timeline_notify_destroy(struct wl_listener *listener, void *data)
+{
+	weston_timeline_close();
+}
+
+void
+weston_timeline_open(struct weston_compositor *compositor)
+{
+	if (weston_timeline_enabled_)
+		return;
+
+	if (weston_timeline_do_open() < 0)
+		return;
+
+	timeline_.compositor_destroy_listener.notify = timeline_notify_destroy;
+	wl_signal_add(&compositor->destroy_signal,
+		      &timeline_.compositor_destroy_listener);
+
+	if (++timeline_.series == 0)
+		++timeline_.series;
+
+	weston_timeline_enabled_ = 1;
+}
+
+void
+weston_timeline_close(void)
+{
+	if (!weston_timeline_enabled_)
+		return;
+
+	weston_timeline_enabled_ = 0;
+
+	wl_list_remove(&timeline_.compositor_destroy_listener.link);
+
+	fclose(timeline_.file);
+	timeline_.file = NULL;
+	weston_log("Timeline log file closed.\n");
+}
+
+struct timeline_emit_context {
+	FILE *cur;
+	FILE *out;
+	unsigned series;
+};
+
+static unsigned
+timeline_new_id(void)
+{
+	static unsigned idc;
+
+	if (++idc == 0)
+		++idc;
+
+	return idc;
+}
+
+static int
+check_series(struct timeline_emit_context *ctx,
+	     struct weston_timeline_object *to)
+{
+	if (to->series == 0 || to->series != ctx->series) {
+		to->series = ctx->series;
+		to->id = timeline_new_id();
+		return 1;
+	}
+
+	if (to->force_refresh) {
+		to->force_refresh = 0;
+		return 1;
+	}
+
+	return 0;
+}
+
+static int
+emit_weston_output(struct timeline_emit_context *ctx, void *obj)
+{
+	struct weston_output *o = obj;
+
+	if (check_series(ctx, &o->timeline))
+		fprintf(ctx->out, "{ \"id\":%u, "
+			"\"type\":\"weston_output\", "
+			"\"name\":%s%s%s }\n",
+			o->timeline.id,
+			o->name ? "\"" : "", o->name ?: "null",
+			o->name ? "\"" : "");
+
+	fprintf(ctx->cur, "\"wo\":%u", o->timeline.id);
+
+	return 1;
+}
+
+static void
+check_weston_surface_description(struct timeline_emit_context *ctx,
+				 struct weston_surface *s)
+{
+	struct weston_surface *mains;
+	const char *q = "\"";
+	char d[512];
+	char mainstr[32];
+
+	if (!check_series(ctx, &s->timeline))
+		return;
+
+	mains = weston_surface_get_main_surface(s);
+	if (mains != s) {
+		check_weston_surface_description(ctx, mains);
+		if (snprintf(mainstr, sizeof(mainstr),
+			     ", \"main_surface\":%u", mains->timeline.id) < 0)
+			mainstr[0] = '\0';
+	} else {
+		mainstr[0] = '\0';
+	}
+
+	if (!s->get_label || s->get_label(s, d, sizeof(d)) < 0) {
+		d[0] = '\0';
+		q = "";
+	}
+
+	fprintf(ctx->out, "{ \"id\":%u, "
+		"\"type\":\"weston_surface\", "
+		"\"desc\":%s%s%s%s }\n",
+		s->timeline.id, q, d[0] ? d : "null", q, mainstr);
+}
+
+static int
+emit_weston_surface(struct timeline_emit_context *ctx, void *obj)
+{
+	struct weston_surface *s = obj;
+
+	check_weston_surface_description(ctx, s);
+	fprintf(ctx->cur, "\"ws\":%u", s->timeline.id);
+
+	return 1;
+}
+
+static int
+emit_vblank_timestamp(struct timeline_emit_context *ctx, void *obj)
+{
+	struct timespec *ts = obj;
+
+	fprintf(ctx->cur, "\"vblank\":[%" PRId64 ", %ld]",
+		(int64_t)ts->tv_sec, ts->tv_nsec);
+
+	return 1;
+}
+
+typedef int (*type_func)(struct timeline_emit_context *ctx, void *obj);
+
+static const type_func type_dispatch[] = {
+	[TLT_OUTPUT] = emit_weston_output,
+	[TLT_SURFACE] = emit_weston_surface,
+	[TLT_VBLANK] = emit_vblank_timestamp,
+};
+
+WL_EXPORT void
+weston_timeline_point(const char *name, ...)
+{
+	va_list argp;
+	struct timespec ts;
+	enum timeline_type otype;
+	void *obj;
+	char buf[512];
+	struct timeline_emit_context ctx;
+
+	clock_gettime(timeline_.clk_id, &ts);
+
+	ctx.out = timeline_.file;
+	ctx.cur = fmemopen(buf, sizeof(buf), "w");
+	ctx.series = timeline_.series;
+
+	if (!ctx.cur) {
+		weston_log("Timeline error in fmemopen, closing.\n");
+		weston_timeline_close();
+		return;
+	}
+
+	fprintf(ctx.cur, "{ \"T\":[%" PRId64 ", %ld], \"N\":\"%s\"",
+		(int64_t)ts.tv_sec, ts.tv_nsec, name);
+
+	va_start(argp, name);
+	while (1) {
+		otype = va_arg(argp, enum timeline_type);
+		if (otype == TLT_END)
+			break;
+
+		obj = va_arg(argp, void *);
+		if (type_dispatch[otype]) {
+			fprintf(ctx.cur, ", ");
+			type_dispatch[otype](&ctx, obj);
+		}
+	}
+	va_end(argp);
+
+	fprintf(ctx.cur, " }\n");
+	fflush(ctx.cur);
+	if (ferror(ctx.cur)) {
+		weston_log("Timeline error in constructing entry, closing.\n");
+		weston_timeline_close();
+	} else {
+		fprintf(ctx.out, "%s", buf);
+	}
+
+	fclose(ctx.cur);
+}
diff --git a/src/timeline.h b/src/timeline.h
new file mode 100644
index 0000000..6a6911d
--- /dev/null
+++ b/src/timeline.h
@@ -0,0 +1,62 @@ 
+/*
+ * Copyright © 2014 Pekka Paalanen <pq@iki.fi>
+ * Copyright © 2014 Collabora, Ltd.
+ *
+ * Permission to use, copy, modify, distribute, and sell this software and
+ * its documentation for any purpose is hereby granted without fee, provided
+ * that the above copyright notice appear in all copies and that both that
+ * copyright notice and this permission notice appear in supporting
+ * documentation, and that the name of the copyright holders not be used in
+ * advertising or publicity pertaining to distribution of the software
+ * without specific, written prior permission.  The copyright holders make
+ * no representations about the suitability of this software for any
+ * purpose.  It is provided "as is" without express or implied warranty.
+ *
+ * THE COPYRIGHT HOLDERS DISCLAIM ALL WARRANTIES WITH REGARD TO THIS
+ * SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND
+ * FITNESS, IN NO EVENT SHALL THE COPYRIGHT HOLDERS BE LIABLE FOR ANY
+ * SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER
+ * RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF
+ * CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN
+ * CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
+ */
+
+#ifndef WESTON_TIMELINE_H
+#define WESTON_TIMELINE_H
+
+extern int weston_timeline_enabled_;
+
+struct weston_compositor;
+
+void
+weston_timeline_open(struct weston_compositor *compositor);
+
+void
+weston_timeline_close(void);
+
+enum timeline_type {
+	TLT_END = 0,
+	TLT_OUTPUT,
+	TLT_SURFACE,
+	TLT_VBLANK,
+};
+
+#define TYPEVERIFY(type, arg) ({			\
+	typeof(arg) tmp___ = (arg);		\
+	(void)((type)0 == tmp___);		\
+	tmp___; })
+
+#define TLP_END TLT_END, NULL
+#define TLP_OUTPUT(o) TLT_OUTPUT, TYPEVERIFY(struct weston_output *, (o))
+#define TLP_SURFACE(s) TLT_SURFACE, TYPEVERIFY(struct weston_surface *, (s))
+#define TLP_VBLANK(t) TLT_VBLANK, TYPEVERIFY(const struct timespec *, (t))
+
+#define TL_POINT(...) do { \
+	if (weston_timeline_enabled_) \
+		weston_timeline_point(__VA_ARGS__); \
+} while (0)
+
+void
+weston_timeline_point(const char *name, ...);
+
+#endif /* WESTON_TIMELINE_H */

Comments

On 12/02/2014 05:45 AM, Pekka Paalanen wrote:
> From: Pekka Paalanen <pekka.paalanen@collabora.co.uk>

> +	if (!s->get_label || s->get_label(s, d, sizeof(d)) < 0) {
> +		d[0] = '\0';
> +		q = "";
> +	}
> +
> +	fprintf(ctx->out, "{ \"id\":%u, "
> +		"\"type\":\"weston_surface\", "
> +		"\"desc\":%s%s%s%s }\n",
> +		s->timeline.id, q, d[0] ? d : "null", q, mainstr);

I think you should make an emit(FILE*, const char*) function that prints 
a quoted string or null, instead of doing this repeatedly. Such a 
function could also convert non-printable characters to escape sequences.

I think also you should ignore strict JSON and not put quotes around the 
keywords. It makes the output a lot easier to read and most libraries 
handle it.
On Tue, 02 Dec 2014 12:12:28 -0800
Bill Spitzak <spitzak@gmail.com> wrote:

> On 12/02/2014 05:45 AM, Pekka Paalanen wrote:
> > From: Pekka Paalanen <pekka.paalanen@collabora.co.uk>
> 
> > +	if (!s->get_label || s->get_label(s, d, sizeof(d)) < 0) {
> > +		d[0] = '\0';
> > +		q = "";
> > +	}
> > +
> > +	fprintf(ctx->out, "{ \"id\":%u, "
> > +		"\"type\":\"weston_surface\", "
> > +		"\"desc\":%s%s%s%s }\n",
> > +		s->timeline.id, q, d[0] ? d : "null", q, mainstr);
> 
> I think you should make an emit(FILE*, const char*) function that prints 
> a quoted string or null, instead of doing this repeatedly. Such a 
> function could also convert non-printable characters to escape sequences.

Yeah, not a bad idea.

> I think also you should ignore strict JSON and not put quotes around the 
> keywords. It makes the output a lot easier to read and most libraries 
> handle it.

Oh, I did hate those quotes, but assumed they were necessary as per
http://www.json.org/ . OTOH, I'm not so sure my outmost JSON structure
is that valid either, since I'm emitting multiple separate objects
instead of a huge array enclosing it or something.


Thanks,
pq
On 2014-12-04 12:23, Pekka Paalanen wrote:
> On Tue, 02 Dec 2014 12:12:28 -0800
> Bill Spitzak <spitzak@gmail.com> wrote:
>> I think you should make an emit(FILE*, const char*) function that prints
>> a quoted string or null, instead of doing this repeatedly. Such a
>> function could also convert non-printable characters to escape sequences.
>
> Yeah, not a bad idea.

I think you better use a streaming JSON library (yajl is quite good at 
that). If this feature is for debugging, there is no harm making it 
optional with a little dependency. Even better, could it be a private 
debug protocol (always there) with a demo client outputting JSON? This 
way, we could see graphical clients providing graphs in real time, which 
would be nice too.


>> I think also you should ignore strict JSON and not put quotes around the
>> keywords. It makes the output a lot easier to read and most libraries
>> handle it.
>
> Oh, I did hate those quotes, but assumed they were necessary as per
> <http://www.json.org/>.

They are necessary. The fact that the format is stricter than parsers is 
just for robustness (and for JavaScript too probably, where these quotes 
are optional). If you want to output JSON, please output real JSON.


 > OTOH, I'm not so sure my outmost JSON structure
> is that valid either, since I'm emitting multiple separate objects
> instead of a huge array enclosing it or something.

You can define that you are printing objects one after another, without 
any relation between them. In this case, you can use a parser with 
“ignore trailing garbage” option (think of it as e.g. the endptr of strtol).
If you want to be able to parse the whole thing in one go, you should 
put them in a big array. You can end your array with an empty object so 
that you can always put a comma after each object. You will get 
something like this (using "{…}" for complete objects):

[
{…},
{…},
{…},
{}]

Or you can use a JSON library that will manage it for you.
On Thu, 04 Dec 2014 12:46:33 +0100
sardemff7+wayland@sardemff7.net wrote:

> On 2014-12-04 12:23, Pekka Paalanen wrote:
> > On Tue, 02 Dec 2014 12:12:28 -0800
> > Bill Spitzak <spitzak@gmail.com> wrote:
> >> I think you should make an emit(FILE*, const char*) function that prints
> >> a quoted string or null, instead of doing this repeatedly. Such a
> >> function could also convert non-printable characters to escape sequences.
> >
> > Yeah, not a bad idea.
> 
> I think you better use a streaming JSON library (yajl is quite good at 
> that). If this feature is for debugging, there is no harm making it 
> optional with a little dependency. Even better, could it be a private 
> debug protocol (always there) with a demo client outputting JSON? This 
> way, we could see graphical clients providing graphs in real time, which 
> would be nice too.

I'm not going to add a library dependency for something this simple.
The main work is to gather the data, after that it's just printf(). I
can't see what a library would help there by replacing a few printf
calls. Stdio already does caching, too, so if the caching is off, I
think we should just adjust stdio parameters.

I'm also not going put this debug stream through Wayland, because it is
on a performance-critical path, may (in the future) produce huge loads
of data, and so clog a socket before the Weston event loop spins again.

For real-time inspection, we need a different transport completely, and
that is out of scope at the moment. Sure, we can convert this JSON
logging to that later if it seems good. Real-time inspection also has
another issue: you don't want to view it on the same machine where you
run Weston, otherwise the viewing will affect the results.

While this is a debugging feature, it is also something that I imagine
is nice to build in in all cases. When not active, the impact should be
totally insignificant. But when a user hits a performance problem, we
could tell him to hit a magic key or change weston.ini or something,
and get a clue on what is the culprit.

Ideally, we would not have this as JSON like this at all, but integrated
with some system-wide profiling tool like perf with custom well-known
events defined in Weston sources, ready to be enabled at runtime. I
just could not find how to do that, so I decided to start with this.

My personal goal with these patches is just to be able to demonstrate
the effects of changing Weston's repaint loop scheduling in later
patches. This is just prerequisite work to justify further work.

> >> I think also you should ignore strict JSON and not put quotes around the
> >> keywords. It makes the output a lot easier to read and most libraries
> >> handle it.
> >
> > Oh, I did hate those quotes, but assumed they were necessary as per
> > <http://www.json.org/>.
> 
> They are necessary. The fact that the format is stricter than parsers is 
> just for robustness (and for JavaScript too probably, where these quotes 
> are optional). If you want to output JSON, please output real JSON.

Very well.

>  > OTOH, I'm not so sure my outmost JSON structure
> > is that valid either, since I'm emitting multiple separate objects
> > instead of a huge array enclosing it or something.
> 
> You can define that you are printing objects one after another, without 
> any relation between them. In this case, you can use a parser with 
> “ignore trailing garbage” option (think of it as e.g. the endptr of strtol).
> If you want to be able to parse the whole thing in one go, you should 
> put them in a big array. You can end your array with an empty object so 
> that you can always put a comma after each object. You will get 
> something like this (using "{…}" for complete objects):
> 
> [
> {…},
> {…},
> {…},
> {}]
> 
> Or you can use a JSON library that will manage it for you.

I prefer individual objects, since I meant this as streamed data. A log
could be hundreds of megabytes or more, in which case I'm wary of
requiring to read it all in at once and parse it all into memory.

OTOH, this format does require reading everything starting from the
beginning to the event of interest, to get all the information about an
object like weston_surface. It's not nice for random access, but I
chose that over repeating the same info over and over again, to make
the logs smaller and avoid needing to cache that data in Weston (e.g.
the surface labels which are not costless to get).


Thanks,
pq
On Thu, 4 Dec 2014 13:23:57 +0200
Pekka Paalanen <ppaalanen@gmail.com> wrote:

> On Tue, 02 Dec 2014 12:12:28 -0800
> Bill Spitzak <spitzak@gmail.com> wrote:
> 
> > On 12/02/2014 05:45 AM, Pekka Paalanen wrote:
> > > From: Pekka Paalanen <pekka.paalanen@collabora.co.uk>
> > 
> > > +	if (!s->get_label || s->get_label(s, d, sizeof(d)) < 0) {
> > > +		d[0] = '\0';
> > > +		q = "";
> > > +	}
> > > +
> > > +	fprintf(ctx->out, "{ \"id\":%u, "
> > > +		"\"type\":\"weston_surface\", "
> > > +		"\"desc\":%s%s%s%s }\n",
> > > +		s->timeline.id, q, d[0] ? d : "null", q, mainstr);
> > 
> > I think you should make an emit(FILE*, const char*) function that prints 
> > a quoted string or null, instead of doing this repeatedly. Such a 
> > function could also convert non-printable characters to escape sequences.
> 
> Yeah, not a bad idea.

Just did the simplification, and pushed these two patches. It will
break the JSON data if a window title contains unexpected characters,
but that can be fixed later if it turns out to be a problem.

Thanks,
pq