From 8e661b3c933680efcce86bb17a4fc6e65d796416 Mon Sep 17 00:00:00 2001
From: Derek Foreman <derek.foreman@collabora.com>
Date: Fri, 16 Sep 2022 11:17:20 -0500
Subject: [PATCH] libweston: Add weston_log_paced()

We have a few places where we log messages only the first time they occur.
Provide a log throttling implementation so we don't have to open code this
in all the places that need it.

Instead of just logging a single time, allow some finer control. We allow
logging of a specified number of events. Additionally, we have an optional
timeout after which the event count is reset so we can log at most N
events in M ms.

The first new event printed after the timeout expires will also include a
count of suppressed events.

Signed-off-by: Derek Foreman <derek.foreman@collabora.com>
---
 include/libweston/libweston.h | 14 +++++
 libweston/log.c               | 98 +++++++++++++++++++++++++++++++++++
 2 files changed, 112 insertions(+)

diff --git a/include/libweston/libweston.h b/include/libweston/libweston.h
index ec2bb86a..31eecccb 100644
--- a/include/libweston/libweston.h
+++ b/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;
@@ -2082,6 +2091,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,
diff --git a/libweston/log.c b/libweston/log.c
index 911feae4..a949da4e 100644
--- a/libweston/log.c
+++ b/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