include/libweston/libweston.h

@@ -44,6 +44,15 @@ extern "C" {
 #include <libweston/matrix.h>
 #include <libweston/zalloc.h>
 
+struct weston_log_pacer {
+	/** This must be set to zero before first use */
+	bool initialized;
+	struct timespec burst_start;
+	unsigned int event_count;
+	unsigned int max_burst;
+	unsigned int reset_ms;
+};
+
 struct weston_geometry {
 	int32_t x, y;
 	int32_t width, height;
@@ -510,6 +519,9 @@ struct weston_output {
 	enum weston_hdcp_protection current_protection;
 	bool allow_protection;
 
+	struct weston_log_pacer repaint_delay_pacer;
+	struct weston_log_pacer pixman_overdraw_pacer;
+
 	int (*start_repaint_loop)(struct weston_output *output);
 	int (*repaint)(struct weston_output *output, pixman_region32_t *damage);
 	void (*destroy)(struct weston_output *output);
@@ -1314,9 +1326,8 @@ struct weston_compositor {
 
 	struct content_protection *content_protection;
 
-	/* One-time warning about a view appearing in the layer list when it
-	 * or its surface are not mapped. */
-	bool warned_about_unmapped_surface_or_view;
+	struct weston_log_pacer unmapped_surface_or_view_pacer;
+	struct weston_log_pacer presentation_clock_failure_pacer;
 };
 
 struct weston_solid_buffer_values {
@@ -2082,6 +2093,11 @@ int
 weston_log_continue(const char *fmt, ...)
 	__attribute__ ((format (printf, 1, 2)));
 
+void
+weston_log_paced(struct weston_log_pacer *pacer, unsigned int max_burst,
+		 unsigned int reset_ms, const char *fmt, ...)
+	__attribute__ ((format (printf, 4, 5)));
+
 enum weston_screenshooter_outcome {
 	WESTON_SCREENSHOOTER_SUCCESS,
 	WESTON_SCREENSHOOTER_NO_MEMORY,

libweston/compositor.c

@@ -2877,11 +2877,10 @@ view_list_add(struct weston_compositor *compositor,
 	if (!weston_surface_is_mapped(view->surface) ||
 	    !weston_view_is_mapped(view) ||
 	    !weston_surface_has_content(view->surface)) {
-		if (!compositor->warned_about_unmapped_surface_or_view) {
-			weston_log("Detected an unmapped surface or view in "
-				   "the layer list, which should not occur.\n");
-			compositor->warned_about_unmapped_surface_or_view = true;
-		}
+		weston_log_paced(&compositor->unmapped_surface_or_view_pacer,
+				 1, 0,
+				 "Detected an unmapped surface or view in "
+				 "the layer list, which should not occur.\n");
 
 		pnode = weston_view_find_paint_node(view, output);
 		if (pnode)
@@ -3308,12 +3307,11 @@ weston_output_finish_frame(struct weston_output *output,
 	msec_rel = timespec_sub_to_msec(&output->next_repaint, &now);
 
 	if (msec_rel < -1000 || msec_rel > 1000) {
-		static bool warned;
-
-		if (!warned)
-			weston_log("Warning: computed repaint delay is "
-				   "insane: %lld msec\n", (long long) msec_rel);
-		warned = true;
+		weston_log_paced(&output->repaint_delay_pacer,
+				 5, 60 * 60 * 1000,
+				 "Warning: computed repaint delay for output "
+				 "[%s] is abnormal: %lld msec\n",
+				 output->name, (long long) msec_rel);
 
 		output->next_repaint = now;
 	}
@@ -8393,10 +8391,9 @@ weston_compositor_set_presentation_clock_software(
  */
 WL_EXPORT void
 weston_compositor_read_presentation_clock(
-			const struct weston_compositor *compositor,
+			struct weston_compositor *compositor,
 			struct timespec *ts)
 {
-	static bool warned;
 	int ret;
 
 	ret = clock_gettime(compositor->presentation_clock, ts);
@@ -8404,12 +8401,12 @@ weston_compositor_read_presentation_clock(
 		ts->tv_sec = 0;
 		ts->tv_nsec = 0;
 
-		if (!warned)
-			weston_log("Error: failure to read "
-				   "the presentation clock %#x: '%s' (%d)\n",
-				   compositor->presentation_clock,
-				   strerror(errno), errno);
-		warned = true;
+		weston_log_paced(&compositor->presentation_clock_failure_pacer,
+				 1, 0,
+				 "Error: failure to read "
+				 "the presentation clock %#x: '%s' (%d)\n",
+				 compositor->presentation_clock,
+				 strerror(errno), errno);
 	}
 }
 

libweston/libinput-device.c

@@ -248,7 +248,6 @@ static bool
 handle_pointer_axis(struct libinput_device *libinput_device,
 		    struct libinput_event_pointer *pointer_event)
 {
-	static int warned;
 	struct evdev_device *device =
 		libinput_device_get_user_data(libinput_device);
 	double vert, horiz;
@@ -282,10 +281,8 @@ handle_pointer_axis(struct libinput_device *libinput_device,
 		wl_axis_source = WL_POINTER_AXIS_SOURCE_CONTINUOUS;
 		break;
 	default:
-		if (warned < 5) {
-			weston_log("Unknown scroll source %d.\n", source);
-			warned++;
-		}
+		weston_log_paced(&device->unknown_scroll_pacer, 5, 0,
+				 "Unknown scroll source %d.\n", source);
 		return false;
 	}
 

libweston/libinput-device.h

@@ -52,6 +52,7 @@ struct evdev_device {
 	char *output_name;
 	int fd;
 	bool override_wl_calibration;
+	struct weston_log_pacer unknown_scroll_pacer;
 };
 
 void

libweston/libweston-internal.h

@@ -156,7 +156,7 @@ weston_compositor_print_scene_graph(struct weston_compositor *ec);
 
 void
 weston_compositor_read_presentation_clock(
-			const struct weston_compositor *compositor,
+			struct weston_compositor *compositor,
 			struct timespec *ts);
 
 int

libweston/log.c

@@ -34,6 +34,7 @@
 
 #include <wayland-util.h>
 
+#include "shared/timespec-util.h"
 #include <libweston/libweston.h>
 #include "weston-log-internal.h"
 
@@ -129,6 +130,103 @@ weston_log(const char *fmt, ...)
 	return l;
 }
 
+/** weston logger with throttling
+ *
+ * Throttled logger that will suppress a message after a fixed number of
+ * prints, and optionally reset the counter reset_ms miliseconds after
+ * the first message in a burst.
+ *
+ * On the first new message printed with this pacer after the timeout
+ * expires, a count of suppressed messages will also be printed.
+ *
+ * Note that the "initialized" member of struct weston_log_pacer must be
+ * set to 0 before first call.
+ *
+ * \param pacer The pacer instance
+ * \param max_burst Number of messages to allow before throttling - must
+ * not be zero.
+ * \param reset_ms Duration from burst start before the count is reset, or
+ * zero to never reset.
+ * \param fmt The format string
+ *
+ * \ingroup wlog
+ */
+WL_EXPORT void
+weston_log_paced(struct weston_log_pacer *pacer,
+		 unsigned int max_burst,
+		 unsigned int reset_ms,
+		 const char *fmt, ...)
+{
+	va_list argp;
+	struct timespec now;
+	int64_t since_burst_start;
+	int64_t suppressed = 0;
+
+	assert(max_burst != 0);
+
+	/* If CLOCK_MONOTONIC fails we silently give up on ever
+	 * reseting the timer. */
+	if (clock_gettime(CLOCK_MONOTONIC, &now) != 0) {
+		now.tv_sec = 0;
+		now.tv_nsec = 0;
+		pacer->burst_start = now;
+	}
+
+	if (!pacer->initialized) {
+		pacer->initialized = true;
+		pacer->burst_start = now;
+		pacer->max_burst = max_burst;
+		pacer->reset_ms = reset_ms;
+	} else {
+		assert(pacer->max_burst == max_burst);
+		assert(pacer->reset_ms == reset_ms);
+	}
+	since_burst_start = timespec_sub_to_msec(&now, &pacer->burst_start);
+
+	if (pacer->reset_ms && since_burst_start > pacer->reset_ms) {
+		if (pacer->event_count > pacer->max_burst) {
+			suppressed = pacer->event_count -
+				     pacer->max_burst;
+		}
+		pacer->event_count = 0;
+	}
+
+	if (pacer->event_count == 0) {
+		pacer->burst_start = now;
+		since_burst_start = 0;
+	}
+
+	pacer->event_count++;
+	if (pacer->event_count > pacer->max_burst)
+		return;
+
+	va_start(argp, fmt);
+	weston_vlog(fmt, argp);
+	va_end(argp);
+
+	if (suppressed) {
+		weston_log_continue(STAMP_SPACE "Warning: %" PRId64 " similar "
+				    "messages previously suppressed\n",
+				    suppressed);
+	}
+
+	/* If we're not going to throttle next time, return immediately,
+	 * otherwise print a little more information */
+	if (pacer->event_count != pacer->max_burst)
+		return;
+
+	if (pacer->reset_ms) {
+		int64_t next_reset = pacer->reset_ms - since_burst_start;
+
+		weston_log_continue(STAMP_SPACE "Warning: the above message "
+				    "will be suppresssed for the next %"
+				    PRId64 " ms.\n", next_reset);
+	} else {
+		weston_log_continue(STAMP_SPACE "Warning: the above message "
+				    "will not be printed again.\n");
+	}
+}
+
 /** weston_vlog_continue calls log_continue_handler
  *
  * \ingroup wlog

libweston/pixman-renderer.c

@@ -234,7 +234,8 @@ composite_whole(pixman_op_t op,
 }
 
 static void
-composite_clipped(pixman_image_t *src,
+composite_clipped(struct weston_output *output,
+		  pixman_image_t *src,
 		  pixman_image_t *mask,
 		  pixman_image_t *dest,
 		  const pixman_transform_t *transform,
@@ -303,12 +304,9 @@ composite_clipped(pixman_image_t *src,
 	}
 
 	if (n_box > 1) {
-		static bool warned = false;
-
-		if (!warned)
-			weston_log("Pixman-renderer warning: %dx overdraw\n",
-				   n_box);
-		warned = true;
+		weston_log_paced(&output->pixman_overdraw_pacer, 1, 0,
+				 "Pixman-renderer warning: %dx overdraw\n",
+				 n_box);
 	}
 }
 
@@ -364,7 +362,7 @@ repaint_region(struct weston_view *ev, struct weston_output *output,
 	}
 
 	if (source_clip)
-		composite_clipped(ps->image, mask_image, target_image,
+		composite_clipped(output, ps->image, mask_image, target_image,
 				  &transform, filter, source_clip);
 	else
 		composite_whole(pixman_op, ps->image, mask_image,