diff --git a/src/box/iproto.cc b/src/box/iproto.cc
index cb1cceb5ccd32261a16daa86d345700f51262092..223469f22c63b4b6f08087443f4a1b63ecff84dd 100644
--- a/src/box/iproto.cc
+++ b/src/box/iproto.cc
@@ -539,8 +539,9 @@ iproto_connection_is_idle(struct iproto_connection *con)
static inline void
iproto_connection_stop_readahead_limit(struct iproto_connection *con)
{
- say_warn("stopping input on connection %s, readahead limit is reached",
- sio_socketname(con->input.fd));
+ say_warn_ratelimited("stopping input on connection %s, "
+ "readahead limit is reached",
+ sio_socketname(con->input.fd));
assert(rlist_empty(&con->in_stop_list));
ev_io_stop(con->loop, &con->input);
}
@@ -550,8 +551,9 @@ iproto_connection_stop_msg_max_limit(struct iproto_connection *con)
{
assert(rlist_empty(&con->in_stop_list));
- say_warn("stopping input on connection %s, net_msg_max limit is reached",
- sio_socketname(con->input.fd));
+ say_warn_ratelimited("stopping input on connection %s, "
+ "net_msg_max limit is reached",
+ sio_socketname(con->input.fd));
ev_io_stop(con->loop, &con->input);
/*
* Important to add to tail and fetch from head to ensure
diff --git a/src/box/txn.c b/src/box/txn.c
index e47853a8bf467a7a7b81fb25ee9ccb5e017564d6..7f4e85b4786a9bf6d1eac36fab7870d4743ea15e 100644
--- a/src/box/txn.c
+++ b/src/box/txn.c
@@ -296,8 +296,9 @@ txn_write_to_wal(struct txn *txn)
diag_set(ClientError, ER_WAL_IO);
diag_log();
} else if (stop - start > too_long_threshold) {
- say_warn("too long WAL write: %d rows at LSN %lld: %.3f sec",
- txn->n_rows, res - txn->n_rows + 1, stop - start);
+ say_warn_ratelimited("too long WAL write: %d rows at "
+ "LSN %lld: %.3f sec", txn->n_rows,
+ res - txn->n_rows + 1, stop - start);
}
/*
* Use vclock_sum() from WAL writer as transaction signature.
diff --git a/src/box/vy_point_lookup.c b/src/box/vy_point_lookup.c
index 7b704b849015c01c5df7f5f769f22f09b20ee1b9..ddbc2d46fad29bc5d0a156ce8ca921885090e5d2 100644
--- a/src/box/vy_point_lookup.c
+++ b/src/box/vy_point_lookup.c
@@ -287,9 +287,10 @@ vy_point_lookup(struct vy_lsm *lsm, struct vy_tx *tx,
latency_collect(&lsm->stat.latency, latency);
if (latency > lsm->env->too_long_threshold) {
- say_warn("%s: get(%s) => %s took too long: %.3f sec",
- vy_lsm_name(lsm), tuple_str(key),
- vy_stmt_str(*ret), latency);
+ say_warn_ratelimited("%s: get(%s) => %s "
+ "took too long: %.3f sec",
+ vy_lsm_name(lsm), tuple_str(key),
+ vy_stmt_str(*ret), latency);
}
return 0;
}
diff --git a/src/box/vy_quota.c b/src/box/vy_quota.c
index 161ab4c7e6603c721aedc44e2be867b004e7a7b2..07cd58563da2132a3b6579bc8a91037ff835c412 100644
--- a/src/box/vy_quota.c
+++ b/src/box/vy_quota.c
@@ -241,8 +241,9 @@ vy_quota_use(struct vy_quota *q, size_t size, double timeout)
double wait_time = ev_monotonic_now(loop()) - wait_start;
if (wait_time > q->too_long_threshold) {
- say_warn("waited for %zu bytes of vinyl memory quota "
- "for too long: %.3f sec", size, wait_time);
+ say_warn_ratelimited("waited for %zu bytes of vinyl memory "
+ "quota for too long: %.3f sec", size,
+ wait_time);
}
vy_quota_do_use(q, size);
diff --git a/src/box/vy_read_iterator.c b/src/box/vy_read_iterator.c
index 954fc0df6a8ca84cc04de44eba1439caeba5fad4..06860cbc46c1ad472fbe8b1b5a553447d50ea9fa 100644
--- a/src/box/vy_read_iterator.c
+++ b/src/box/vy_read_iterator.c
@@ -887,10 +887,11 @@ vy_read_iterator_next(struct vy_read_iterator *itr, struct tuple **result)
latency_collect(&lsm->stat.latency, latency);
if (latency > lsm->env->too_long_threshold) {
- say_warn("%s: select(%s, %s) => %s took too long: %.3f sec",
- vy_lsm_name(lsm), tuple_str(itr->key),
- iterator_type_strs[itr->iterator_type],
- vy_stmt_str(stmt), latency);
+ say_warn_ratelimited("%s: select(%s, %s) => %s "
+ "took too long: %.3f sec",
+ vy_lsm_name(lsm), tuple_str(itr->key),
+ iterator_type_strs[itr->iterator_type],
+ vy_stmt_str(stmt), latency);
}
*result = stmt;
diff --git a/src/say.h b/src/say.h
index 3cff02e96e9e627d93604d28e161b480f9dfd72f..26db95133c913655cec356f621aa59f3019bc4e4 100644
--- a/src/say.h
+++ b/src/say.h
@@ -39,6 +39,7 @@
#include <tarantool_ev.h>
#include "small/rlist.h"
#include "fiber_cond.h"
+#include "ratelimit.h"
#if defined(__cplusplus)
extern "C" {
@@ -327,6 +328,43 @@ CFORMAT(printf, 5, 0) extern sayfunc_t _say;
#define panic(...) panic_status(EXIT_FAILURE, __VA_ARGS__)
#define panic_syserror(...) ({ say(S_FATAL, strerror(errno), __VA_ARGS__); exit(EXIT_FAILURE); })
+enum {
+ /* 10 messages per 5 seconds. */
+ SAY_RATELIMIT_INTERVAL = 5,
+ SAY_RATELIMIT_BURST = 10,
+};
+
+/**
+ * Wrapper around ratelimit_check() that prints a warning if some
+ * messages are suppressed. It uses ev_monotonic_now() as a time
+ * source.
+ */
+#define say_ratelimit_check(rl) ({ \
+ int suppressed = 0; \
+ bool ret = ratelimit_check((rl), ev_monotonic_now(loop()), \
+ &suppressed); \
+ if (suppressed > 0) \
+ say_warn("%d messages suppressed", suppressed); \
+ ret; \
+})
+
+/**
+ * Same as say(), but rate limited. If this function is called more
+ * often than SAY_RATELIMIT_BURST times per SAY_RATELIMIT_INTERVAL
+ * seconds, extra messages are suppressed and a warning is printed
+ * to the log.
+ */
+#define say_ratelimited(level, error, format, ...) ({ \
+ static struct ratelimit rl = \
+ RATELIMIT_INITIALIZER(SAY_RATELIMIT_INTERVAL, \
+ SAY_RATELIMIT_BURST); \
+ if (say_ratelimit_check(&rl)) \
+ say(level, error, format, ##__VA_ARGS__); \
+})
+
+#define say_warn_ratelimited(format, ...) \
+ say_ratelimited(S_WARN, NULL, format, ##__VA_ARGS__)
+
/**
* Format and print a message to Tarantool log file.
*