Skip to content

Commit 06506b2

Browse files
committed
cachedb_perf: make a pull that never left the node visible
A pull datagram the transport refused to send was logged at LM_DBG, which means it was unreachable on every deployed node: log_level 3 is INFO and L_DBG is 4. That is the wrong level for it. A send that fails produces no packet, so the far end never learns there was a question and the requester just times out - this line is the only direct evidence of why, and it is the actual cause behind a class of "cross-node pull is slow / does not converge" reports. It cannot become an unconditional LM_WARN either: a partitioned or overloaded peer fails every send, and an unbounded warn is its own incident. So warn on the first failure and then at most once every 30s, folding in the count it stands for. The rate-limit state lives in shm, not in a static. A pull reply goes out from whichever worker happened to receive the request, so a per-process limiter would let all ~30 SIP workers warn once per interval each. Two workers can still pass the interval check simultaneously and both warn; that costs an occasional duplicate line and saves taking a lock on a failure path. Adds pulls_send_failed as a statistic and an MI field, so the exact total is available even while the log is suppressing. It is deliberately distinct from pulls_timeout: a timeout means a peer was asked and stayed silent, this means no peer was ever asked. Applied to all four send sites - both reply paths (clusterer_controller unicast and BIN) and both request paths - since a request that does not go out fails exactly the same way. (cherry picked from commit 5ce7e1c)
1 parent 6ee6234 commit 06506b2

1 file changed

Lines changed: 81 additions & 5 deletions

File tree

‎modules/cachedb_perf/cachedb_perf.c‎

Lines changed: 81 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -246,6 +246,14 @@ static unsigned int *pull_next_id; /* shm: ids must be unique per node */
246246
* is one shared line, which the module forbids on the hot path (CP-06); a
247247
* cross-node miss is not the hot path. */
248248
static unsigned int *pull_stats; /* PULL_ST_* counters */
249+
/* Rate-limit state for the send-failure warning (pull_send_failed()). In shm
250+
* rather than a plain static because a pull reply goes out from whichever
251+
* worker happened to receive the request: a per-process limiter would let all
252+
* ~30 SIP workers warn once per interval each. */
253+
static struct pcache_send_warn {
254+
unsigned int last; /* get_ticks() when we last warned */
255+
unsigned int suppressed; /* failures folded into the next warning */
256+
} *pull_send_warn;
249257

250258
/* Negative cache (R4). A key that is genuinely nowhere costs a full
251259
* round of questions, and SIP retransmits ask again a few hundred
@@ -279,7 +287,11 @@ static int pull_on_miss; /* modparam; read repair on the get path
279287
/* slots the reaper had to release because the caller never collected them -
280288
* distinct from a timeout, which the caller DID collect */
281289
#define PULL_ST_ABANDONED 6
282-
#define PULL_ST_MAX 7
290+
/* A pull datagram the transport refused to send. Distinct from a TIMEOUT:
291+
* the request never left this node, so no peer was ever given the chance to
292+
* answer it. */
293+
#define PULL_ST_SEND_FAIL 7
294+
#define PULL_ST_MAX 8
283295
/* Two different readinesses, deliberately kept apart:
284296
* cluster_ready - the clusterer is bound, the capability is registered and
285297
* membership is being tracked. Everything cross-node needs
@@ -565,13 +577,66 @@ static unsigned long pull_stat(int which)
565577
#define PULLSTATF(_fn, _which) \
566578
static unsigned long _fn(void *ctx) { return pull_stat(_which); }
567579

580+
/* Complain about a pull datagram that never left, at most once every
581+
* PCACHE_PULL_SEND_WARN_IVL seconds.
582+
*
583+
* This used to be LM_DBG, which made it unreachable on every deployed node:
584+
* log_level 3 is INFO and L_DBG is 4. That is the wrong level for it - a send
585+
* that fails is invisible at the far end, so the requester simply times out,
586+
* and this line is the only direct evidence of why. It is the actual cause
587+
* behind a class of "cross-node pull is slow / does not converge" reports.
588+
*
589+
* It cannot be an unconditional LM_WARN either: a partitioned or overloaded
590+
* peer fails every send, and an unbounded warn is its own incident. So warn
591+
* on the first failure, then at most once per interval, carrying the count it
592+
* stands for. The exact total is always available as pulls_send_failed.
593+
*
594+
* Two workers can pass the interval check at once and both warn. That is
595+
* deliberate - it costs an occasional duplicate line and saves taking a lock
596+
* on a failure path. */
597+
#define PCACHE_PULL_SEND_WARN_IVL 30
598+
599+
static void pull_send_failed(const char *what, int dst_node)
600+
{
601+
unsigned int now = get_ticks(), held;
602+
char tgt[32];
603+
604+
if (pull_stats)
605+
__sync_fetch_and_add(&pull_stats[PULL_ST_SEND_FAIL], 1);
606+
if (!pull_send_warn)
607+
return;
608+
609+
if (pull_send_warn->last != 0 &&
610+
now - pull_send_warn->last < PCACHE_PULL_SEND_WARN_IVL) {
611+
__sync_fetch_and_add(&pull_send_warn->suppressed, 1);
612+
return;
613+
}
614+
pull_send_warn->last = now;
615+
held = __sync_lock_test_and_set(&pull_send_warn->suppressed, 0);
616+
617+
if (dst_node > 0)
618+
snprintf(tgt, sizeof tgt, "node %d", dst_node);
619+
else
620+
snprintf(tgt, sizeof tgt, "the cluster");
621+
622+
if (held)
623+
LM_WARN("cross-node pull: %s [%s], and %u more in the last %ds - "
624+
"whoever asked is timing out; see the pulls_send_failed "
625+
"statistic for the running total\n",
626+
what, tgt, held, PCACHE_PULL_SEND_WARN_IVL);
627+
else
628+
LM_WARN("cross-node pull: %s [%s] - whoever asked is timing out\n",
629+
what, tgt);
630+
}
631+
568632
PULLSTATF(smf_pulls_requested, PULL_ST_REQUESTED)
569633
PULLSTATF(smf_pulls_served, PULL_ST_SERVED)
570634
PULLSTATF(smf_pulls_received, PULL_ST_RECEIVED)
571635
PULLSTATF(smf_pulls_timeout, PULL_ST_TIMEOUT)
572636
PULLSTATF(smf_pulls_stored, PULL_ST_STORED)
573637
PULLSTATF(smf_pulls_suppressed, PULL_ST_SUPPRESSED)
574638
PULLSTATF(smf_pulls_abandoned, PULL_ST_ABANDONED)
639+
PULLSTATF(smf_pulls_send_failed, PULL_ST_SEND_FAIL)
575640

576641
/* A GAUGE, unlike every other pull stat: it should read 0 whenever nothing is
577642
* being asked. Anything parked here means slots are taken and not released,
@@ -733,6 +798,7 @@ static const stat_export_t mod_stats[] = {
733798
{"pulls_stored", STAT_IS_FUNC, (stat_var **)smf_pulls_stored},
734799
{"pulls_suppressed", STAT_IS_FUNC, (stat_var **)smf_pulls_suppressed},
735800
{"pulls_abandoned", STAT_IS_FUNC, (stat_var **)smf_pulls_abandoned},
801+
{"pulls_send_failed", STAT_IS_FUNC, (stat_var **)smf_pulls_send_failed},
736802
{"pulls_in_flight", STAT_IS_FUNC, (stat_var **)smf_pulls_in_flight},
737803
{0,0,0}
738804
};
@@ -944,6 +1010,8 @@ static mi_response_t *mi_perf_stats(str *col_s)
9441010
pull_stats[PULL_ST_STORED]) < 0 ||
9451011
add_mi_number(clobj, MI_SSTR("pulls_suppressed"),
9461012
pull_stats[PULL_ST_SUPPRESSED]) < 0 ||
1013+
add_mi_number(clobj, MI_SSTR("pulls_send_failed"),
1014+
pull_stats[PULL_ST_SEND_FAIL]) < 0 ||
9471015
add_mi_number(clobj, MI_SSTR("pulls_abandoned"),
9481016
pull_stats[PULL_ST_ABANDONED]) < 0))
9491017
goto err;
@@ -1816,7 +1884,7 @@ static void pcache_pull_send_rpl(int dst_node, unsigned int id, const str *key,
18161884
pl.len = n;
18171885
if (clctr_api.send_ucast(sync_cluster_id, dst_node, &pull_channel,
18181886
&pl, 0) < 0)
1819-
LM_DBG("pull reply to node %d did not get through\n", dst_node);
1887+
pull_send_failed("a reply did not get through", dst_node);
18201888
else if (found == PCACHE_FOUND_YES)
18211889
__sync_fetch_and_add(&pull_stats[PULL_ST_SERVED], 1);
18221890
return;
@@ -1841,7 +1909,7 @@ static void pcache_pull_send_rpl(int dst_node, unsigned int id, const str *key,
18411909
}
18421910
if (clusterer_api.send_to(&out, sync_cluster_id, dst_node) !=
18431911
CLUSTERER_SEND_SUCCESS)
1844-
LM_DBG("pull reply to node %d did not get through\n", dst_node);
1912+
pull_send_failed("a reply did not get through", dst_node);
18451913
else if (found == PCACHE_FOUND_YES)
18461914
__sync_fetch_and_add(&pull_stats[PULL_ST_SERVED], 1);
18471915
bin_free_packet(&out);
@@ -2310,7 +2378,7 @@ static int pcache_pull_start(pcache_col_t *col, const str *key, int hint_node,
23102378
&pull_channel, &pl, 0) < 0
23112379
: clctr_api.send_mcast(sync_cluster_id, &pull_channel,
23122380
&pl, 0) < 0)
2313-
LM_DBG("pull request could not be sent\n");
2381+
pull_send_failed("a request could not be sent", hint_node);
23142382
} else
23152383
#endif
23162384
{
@@ -2327,7 +2395,8 @@ static int pcache_pull_start(pcache_col_t *col, const str *key, int hint_node,
23272395
? clusterer_api.send_to(&packet, sync_cluster_id, hint_node)
23282396
: clusterer_api.send_all(&packet, sync_cluster_id)) !=
23292397
CLUSTERER_SEND_SUCCESS)
2330-
LM_DBG("pull request reached no or only some nodes\n");
2398+
pull_send_failed("a request reached no or only some nodes",
2399+
hint_node);
23312400
bin_free_packet(&packet);
23322401
}
23332402

@@ -4233,9 +4302,11 @@ static int mod_init(void)
42334302
pull_slots = shm_malloc((size_t)PCACHE_PULL_SLOTS * pull_slot_sz);
42344303
pull_next_id = shm_malloc(sizeof *pull_next_id);
42354304
pull_stats = shm_malloc(PULL_ST_MAX * sizeof *pull_stats);
4305+
pull_send_warn = shm_malloc(sizeof *pull_send_warn);
42364306
peer_stats = shm_malloc((CL_MAX_NODE_ID + 1) * sizeof *peer_stats);
42374307
pull_lock = lock_alloc();
42384308
if (!pull_slots || !pull_next_id || !pull_stats || !peer_stats ||
4309+
!pull_send_warn ||
42394310
!pull_lock || !lock_init(pull_lock)) {
42404311
LM_ERR("no shm for the cross-node pull state\n");
42414312
return -1;
@@ -4259,6 +4330,7 @@ static int mod_init(void)
42594330
}
42604331
*pull_next_id = 0;
42614332
memset(pull_stats, 0, PULL_ST_MAX * sizeof *pull_stats);
4333+
memset(pull_send_warn, 0, sizeof *pull_send_warn);
42624334
if (pull_negative_ms < 0 || pull_negative_ms > 2000) {
42634335
LM_ERR("pull_negative_ms must be within 0..2000 (0 = off) "
42644336
"- a negative that outlives a retransmit turns a "
@@ -4519,6 +4591,10 @@ static void mod_destroy(void)
45194591
shm_free(pull_stats);
45204592
pull_stats = NULL;
45214593
}
4594+
if (pull_send_warn) {
4595+
shm_free(pull_send_warn);
4596+
pull_send_warn = NULL;
4597+
}
45224598
if (peer_stats) {
45234599
shm_free(peer_stats);
45244600
peer_stats = NULL;

0 commit comments

Comments
 (0)