Commit 6de8868d (reconnect: Fix broken inactivity probe if there is no
other reason to wake up.) enables poll_loop to run immediately on the
next millisecond when the probe interval has expired with no receive
attempted. Its reasoning notes that "in a correctly written application
we should not fall into this case more than once in a row".
An ovsdb-server session whose peer stops reading falls into it forever,
causing the ovsdb-server process to burn CPU proportionally to the
number of sessions.
This behaviour has been observed in production, where a few
ovn-octavia-provider clients raised an exception but did not die,
keeping their backlog frozen and degrading the ovsdb-server service.
The CPU pin is recognisable by three things together:
1. a backlog reported by "ovs-appctl memory/show" stands through a whole
inactivity_probe without being probed away, and the poll rate rises
from a handful of passes a second to hundreds at the moment that
interval expires -- measured here at t+8 s with the 5 s default and
t+201 s with a 180 s probe -- and no inactivity-probe disconnect is
ever logged for that session.
2. the CPU this costs grows with the session count, because every
wake-up walks every connection: 10.5% of a core with the stalled
session alone, 21.9% alongside 50 healthy sessions, 42.3% alongside
300 -- which is what this patch gives back, taking that last figure
to under 1%.
3. killing all stalled sessions returns the poll rate and the CPU to
their baseline at once, which is what separates the pin from load.
ovsdb-server has no way to know this happened: a session with a standing
backlog does not have jsonrpc_session_recv() invoked, which blocks the
calls to reconnect_receive_attempted(), so the receive that would move
the expiration can never happen unless the peer resumes reading, which a
faulty implementation might never do.
A merely slow consumer arms the same pin. ovsdb-server sees only its
own queue shrinking, and that happens only when the kernel accepts more
data -- which depends on the peer acknowledging what it already has, not
on the peer reading each byte. A peer that does not move the queue
within a probe interval is indistinguishable from one that stopped. The
4 kB/s row below is such a peer.
The FSM is now aware of how much is queued for the peer, and while
anything is queued stops asking to be woken up to attempt that receive.
No session is probed or disconnected that was not before: no probe was
ever sent for such a session and none is now, and it is still never
disconnected -- it simply costs nothing to keep. What changes is the
deadline the FSM reports, and so how often the poll loop wakes. Once
the backlog drains the session is read again, so it can reach the probe
and answer it, and the ordinary probe interval applies.
The 'now + 1' path itself remains valid and is left alone: it is reached
only when nothing is queued, and there the receive it exists to permit
does happen, so it fires once rather than forever.
Testing. Reproduced with a simple python client that starts reading its
backlog and then purposely 1) stops; 2) reads very slowly; 3) reads a
bit faster -- the problem observed in production, plus a busy peer whose
intake is throttled. Unpatched against patched on the same tree, at the
5 s inactivity_probe TCP default; every session was held in both builds:
client unpatched patched
stops reading (0 kB/s) 903 passes/s 2.0 passes/s
reads 4 kB/s 880 passes/s 1.5 passes/s
reads 20 kB/s 2.0 passes/s 2.0 passes/s
Fixes: 6de8868d19ea ("reconnect: Fix broken inactivity probe if there is no
other reason to wake up.")
Signed-off-by: Aeliton G. Silva <[email protected]>
Assisted-by: Claude Opus 5, Claude Code
---
lib/jsonrpc.c | 6 +-
lib/reconnect.c | 18 ++++-
lib/reconnect.h | 4 +-
python/ovs/jsonrpc.py | 5 +-
python/ovs/reconnect.py | 22 ++++--
tests/reconnect.at | 144 ++++++++++++++++++++++++++++++++++++++++
tests/test-reconnect.c | 15 ++++-
tests/test-reconnect.py | 9 ++-
8 files changed, 206 insertions(+), 17 deletions(-)
diff --git a/lib/jsonrpc.c b/lib/jsonrpc.c
index f01a2e56f..7b9fb7318 100644
--- a/lib/jsonrpc.c
+++ b/lib/jsonrpc.c
@@ -1062,7 +1062,8 @@ jsonrpc_session_run(struct jsonrpc_session *s)
* which means that we can push a lot of data into a connection
* that has stalled and won't ever recover.
*/
- reconnect_activity(s->reconnect, time_msec());
+ reconnect_activity(s->reconnect, time_msec(),
+ jsonrpc_get_backlog(s->rpc));
}
error = jsonrpc_get_status(s->rpc);
@@ -1192,7 +1193,8 @@ jsonrpc_session_recv(struct jsonrpc_session *s)
* Previously we only counted receiving a full message as activity,
* but with large messages or a slow connection that policy could
* time out the session mid-message. */
- reconnect_activity(s->reconnect, now);
+ reconnect_activity(s->reconnect, now,
+ jsonrpc_get_backlog(s->rpc));
}
if (msg) {
diff --git a/lib/reconnect.c b/lib/reconnect.c
index 918ecd203..1f9bf83df 100644
--- a/lib/reconnect.c
+++ b/lib/reconnect.c
@@ -62,6 +62,7 @@ struct reconnect {
long long int last_connected;
long long int last_disconnected;
long long int last_receive_attempt;
+ size_t queued_bytes;
unsigned int max_tries;
unsigned int backoff_free_tries;
@@ -112,6 +113,7 @@ reconnect_create(long long int now)
fsm->last_connected = LLONG_MAX;
fsm->last_disconnected = LLONG_MAX;
fsm->last_receive_attempt = now;
+ fsm->queued_bytes = 0;
fsm->max_tries = UINT_MAX;
fsm->creation_time = now;
@@ -340,6 +342,7 @@ reconnect_force_reconnect(struct reconnect *fsm, long long
int now)
void
reconnect_disconnected(struct reconnect *fsm, long long int now, int error)
{
+ fsm->queued_bytes = 0;
if (!(fsm->state & (S_BACKOFF | S_VOID))) {
/* Report what happened. */
if (fsm->state & (S_ACTIVE | S_IDLE)) {
@@ -494,10 +497,17 @@ reconnect_connect_failed(struct reconnect *fsm, long long
int now, int error)
}
/* Tell 'fsm' that some activity has occurred on the connection. This resets
- * the probe interval timer, so that the connection is known not to be idle. */
+ * the probe interval timer, so that the connection is known not to be idle.
+ *
+ * 'queued_bytes' is data queued for the peer that could not be sent. While
+ * it is nonzero the FSM stops asking to be woken up to attempt a receive:
+ * the caller evidently cannot get data to this peer, so no receive it makes
+ * can settle anything, and waking to try only burns CPU. */
void
-reconnect_activity(struct reconnect *fsm, long long int now)
+reconnect_activity(struct reconnect *fsm, long long int now,
+ size_t queued_bytes)
{
+ fsm->queued_bytes = queued_bytes;
if (fsm->state == S_IDLE) {
reconnect_transition__(fsm, now, S_ACTIVE);
}
@@ -556,6 +566,10 @@ reconnect_deadline__(const struct reconnect *fsm, long
long int now)
case S_ACTIVE:
if (fsm->probe_interval) {
+ if (fsm->queued_bytes) {
+ return LLONG_MAX;
+ }
+
long long int base = MAX(fsm->last_activity, fsm->state_entered);
long long int expiration = base + fsm->probe_interval;
if (now < expiration || fsm->last_receive_attempt >= expiration) {
diff --git a/lib/reconnect.h b/lib/reconnect.h
index 40cc569c4..05f38a958 100644
--- a/lib/reconnect.h
+++ b/lib/reconnect.h
@@ -31,6 +31,7 @@
* revisited later.) */
#include <stdbool.h>
+#include <stddef.h>
struct reconnect *reconnect_create(long long int now);
void reconnect_destroy(struct reconnect *);
@@ -82,7 +83,8 @@ void reconnect_listen_error(struct reconnect *, long long int
now, int error);
void reconnect_connected(struct reconnect *, long long int now);
void reconnect_connect_failed(struct reconnect *, long long int now,
int error);
-void reconnect_activity(struct reconnect *, long long int now);
+void reconnect_activity(struct reconnect *, long long int now,
+ size_t queued_bytes);
void reconnect_receive_attempted(struct reconnect *, long long int now);
enum reconnect_action {
diff --git a/python/ovs/jsonrpc.py b/python/ovs/jsonrpc.py
index 07b454a21..c27b871a5 100644
--- a/python/ovs/jsonrpc.py
+++ b/python/ovs/jsonrpc.py
@@ -502,7 +502,8 @@ class Session(object):
# activity, because there's a lot of queuing downstream from
# us, which means that we can push a lot of data into a
# connection that has stalled and won't ever recover.
- self.reconnect.activity(ovs.timeval.msec())
+ self.reconnect.activity(ovs.timeval.msec(),
+ self.rpc.get_backlog())
error = self.rpc.get_status()
if error != 0:
@@ -573,7 +574,7 @@ class Session(object):
# Previously we only counted receiving a full message as
# activity, but with large messages or a slow connection that
# policy could time out the session mid-message.
- self.reconnect.activity(now)
+ self.reconnect.activity(now, self.rpc.get_backlog())
if not error:
if msg.type == Message.T_REQUEST and msg.method == "echo":
diff --git a/python/ovs/reconnect.py b/python/ovs/reconnect.py
index 6b8e49afd..2ff4fc6c4 100644
--- a/python/ovs/reconnect.py
+++ b/python/ovs/reconnect.py
@@ -94,6 +94,9 @@ class Reconnect(object):
@staticmethod
def deadline(fsm, now):
if fsm.probe_interval:
+ if fsm.queued_bytes:
+ return None
+
base = max(fsm.last_activity, fsm.state_entered)
expiration = base + fsm.probe_interval
if (now < expiration or
@@ -140,7 +143,7 @@ class Reconnect(object):
def run(fsm, now):
vlog.err("%s: no response to inactivity probe after %.3g "
"seconds, disconnecting"
- % (fsm.name, (now - fsm.state_entered) / 1000.0))
+ % (fsm.name, (now - fsm.state_entered) / 1000.0))
return DISCONNECT
class Reconnect(object):
@@ -174,6 +177,7 @@ class Reconnect(object):
self.last_connected = None
self.last_disconnected = None
self.last_receive_attempt = now
+ self.queued_bytes = 0
self.max_tries = None
self.backoff_free_tries = 0
@@ -347,6 +351,7 @@ class Reconnect(object):
error.
The FSM will back off, then reconnect."""
+ self.queued_bytes = 0
if self.state not in (Reconnect.Backoff, Reconnect.Void):
# Report what happened
if self.state in (Reconnect.Active, Reconnect.Idle):
@@ -485,10 +490,17 @@ class Reconnect(object):
self.connecting(now)
self.disconnected(now, error)
- def activity(self, now):
- """Tell this FSM that some activity occurred on the connection. This
- resets the probe interval timer, so that the connection is known not to
- be idle."""
+ def activity(self, now, queued_bytes):
+ """Tell this FSM that some activity has occurred on the connection.
+ This resets the probe interval timer, so that the connection is known
+ not to be idle.
+
+ 'queued_bytes' is data queued for the peer that could not be sent.
+ While it is nonzero the FSM stops asking to be woken up to attempt a
+ receive: the caller evidently cannot get data to this peer, so no
+ receive it makes can settle anything, and waking to try only burns
+ CPU."""
+ self.queued_bytes = queued_bytes
if self.state != Reconnect.Active:
self._transition(now, Reconnect.Active)
self.last_activity = now
diff --git a/tests/reconnect.at b/tests/reconnect.at
index 5bca84351..650ca3485 100644
--- a/tests/reconnect.at
+++ b/tests/reconnect.at
@@ -1363,3 +1363,147 @@ run
listening
in LISTENING for 0 ms (0 ms backoff)
])
+
+######################################################################
+RECONNECT_CHECK([no wake-up while data is queued],
+ [enable
+
+# Connection succeeds.
+run
+connected
+
+# Data is queued for the peer that we could not send.
+activity 1000
+
+# Long past the probe interval the FSM asks for no wake-up at all, and
+# nothing happens: the connection is neither probed nor disconnected.
+advance 60000
+timeout
+run
+],
+ [### t=1000 ###
+enable
+ in BACKOFF for 0 ms (0 ms backoff)
+
+# Connection succeeds.
+run
+ should connect
+connected
+ in ACTIVE for 0 ms (0 ms backoff)
+ created 1000, last activity 1000, last connected 1000
+ 1 successful connections out of 1 attempts, seqno 1
+ connected
+ last connected 0 ms ago, connected 0 ms total
+
+# Data is queued for the peer that we could not send.
+activity 1000
+
+# Long past the probe interval the FSM asks for no wake-up at all, and
+# nothing happens: the connection is neither probed nor disconnected.
+advance 60000
+
+### t=61000 ###
+ in ACTIVE for 60000 ms (0 ms backoff)
+timeout
+ no timeout
+run
+])
+
+######################################################################
+RECONNECT_CHECK([draining the queue restores probing],
+ [enable
+run
+connected
+
+# Queued: no wake-up, no probe.
+activity 1000
+advance 10000
+run
+
+# The queue drains, so the ordinary probe interval applies again.
+activity 0
+receive-attempted LLONG_MAX
+timeout
+run
+],
+ [### t=1000 ###
+enable
+ in BACKOFF for 0 ms (0 ms backoff)
+run
+ should connect
+connected
+ in ACTIVE for 0 ms (0 ms backoff)
+ created 1000, last activity 1000, last connected 1000
+ 1 successful connections out of 1 attempts, seqno 1
+ connected
+ last connected 0 ms ago, connected 0 ms total
+
+# Queued: no wake-up, no probe.
+activity 1000
+advance 10000
+
+### t=11000 ###
+ in ACTIVE for 10000 ms (0 ms backoff)
+run
+
+# The queue drains, so the ordinary probe interval applies again.
+activity 0
+ created 1000, last activity 11000, last connected 1000
+receive-attempted LLONG_MAX
+timeout
+ advance 5000 ms
+
+### t=16000 ###
+ in ACTIVE for 15000 ms (0 ms backoff)
+run
+ should send probe
+ in IDLE for 0 ms (0 ms backoff)
+])
+
+######################################################################
+RECONNECT_CHECK([disconnect forgets queued data],
+ [enable
+run
+connected
+activity 1000
+
+# Disconnecting forgets the queued data.
+disconnected
+run
+connected
+
+# So the ordinary probe interval applies again.
+timeout
+],
+ [### t=1000 ###
+enable
+ in BACKOFF for 0 ms (0 ms backoff)
+run
+ should connect
+connected
+ in ACTIVE for 0 ms (0 ms backoff)
+ created 1000, last activity 1000, last connected 1000
+ 1 successful connections out of 1 attempts, seqno 1
+ connected
+ last connected 0 ms ago, connected 0 ms total
+activity 1000
+
+# Disconnecting forgets the queued data.
+disconnected
+ in BACKOFF for 0 ms (1000 ms backoff)
+ 1 successful connections out of 1 attempts, seqno 2
+ disconnected
+ disconnected at 1000 ms (0 ms ago)
+run
+connected
+ in ACTIVE for 0 ms (1000 ms backoff)
+ 2 successful connections out of 2 attempts, seqno 3
+ connected
+
+# So the ordinary probe interval applies again.
+timeout
+ advance 5000 ms
+
+### t=6000 ###
+ in ACTIVE for 5000 ms (1000 ms backoff)
+])
diff --git a/tests/test-reconnect.c b/tests/test-reconnect.c
index c84bb1cdb..7c7d8fd53 100644
--- a/tests/test-reconnect.c
+++ b/tests/test-reconnect.c
@@ -147,9 +147,17 @@ do_connected(struct ovs_cmdl_context *ctx OVS_UNUSED)
}
static void
-do_activity(struct ovs_cmdl_context *ctx OVS_UNUSED)
+do_set_probe_interval(struct ovs_cmdl_context *ctx)
{
- reconnect_activity(reconnect, now);
+ reconnect_set_probe_interval(reconnect, atoi(ctx->argv[1]));
+}
+
+static void
+do_activity(struct ovs_cmdl_context *ctx)
+{
+ size_t queued_bytes = ctx->argc > 1 ? atoi(ctx->argv[1]) : 0;
+
+ reconnect_activity(reconnect, now, queued_bytes);
}
static void
@@ -297,7 +305,8 @@ static const struct ovs_cmdl_command all_commands[] = {
{ "connecting", NULL, 0, 0, do_connecting, OVS_RO },
{ "connect-failed", NULL, 0, 1, do_connect_failed, OVS_RO },
{ "connected", NULL, 0, 0, do_connected, OVS_RO },
- { "activity", NULL, 0, 0, do_activity, OVS_RO },
+ { "activity", NULL, 0, 1, do_activity, OVS_RO },
+ { "set-probe-interval", NULL, 1, 1, do_set_probe_interval, OVS_RO },
{ "run", NULL, 0, 1, do_run, OVS_RO },
{ "advance", NULL, 1, 1, do_advance, OVS_RO },
{ "timeout", NULL, 0, 0, do_timeout, OVS_RO },
diff --git a/tests/test-reconnect.py b/tests/test-reconnect.py
index cea48eb52..7001ac849 100644
--- a/tests/test-reconnect.py
+++ b/tests/test-reconnect.py
@@ -61,8 +61,12 @@ def do_connected(_):
r.connected(now)
-def do_activity(_):
- r.activity(now)
+def do_set_probe_interval(arg):
+ r.set_probe_interval(int(arg))
+
+
+def do_activity(arg):
+ r.activity(now, int(arg) if arg is not None else 0)
def do_run(arg):
@@ -181,6 +185,7 @@ def main():
"connect-failed": do_connect_failed,
"connected": do_connected,
"activity": do_activity,
+ "set-probe-interval": do_set_probe_interval,
"run": do_run,
"advance": do_advance,
"timeout": do_timeout,
--
2.43.0
--
_'Esta mensagem é direcionada apenas para os endereços constantes no
cabeçalho inicial. Se você não está listado nos endereços constantes no
cabeçalho, pedimos-lhe que desconsidere completamente o conteúdo dessa
mensagem e cuja cópia, encaminhamento e/ou execução das ações citadas estão
imediatamente anuladas e proibidas'._
* **'Apesar do Magazine Luiza tomar
todas as precauções razoáveis para assegurar que nenhum vírus esteja
presente nesse e-mail, a empresa não poderá aceitar a responsabilidade por
quaisquer perdas ou danos causados por esse e-mail ou por seus anexos'.*
_______________________________________________
dev mailing list
[email protected]
https://mail.openvswitch.org/mailman/listinfo/ovs-dev
