From 5a32d08ffd32a7a9bf0ea6d48aba26ab00942dff Mon Sep 17 00:00:00 2001 From: evgeny Date: Sat, 24 Oct 2026 10:32:44 +0200 Subject: [PATCH] Buffer retry choice diagnostics until measurement completes --- tests/test_etcp_multipath.c | 25 ++++++++++++++++++++----- 1 file changed, 20 insertions(+), 5 deletions(-) diff --git a/tests/test_etcp_multipath.c b/tests/test_etcp_multipath.c index 823a611f..35c7578a 100644 --- a/tests/test_etcp_multipath.c +++ b/tests/test_etcp_multipath.c @@ -34,6 +34,10 @@ struct recovery_stats { uint64_t rto_count, retry_count, rto_late_us, ready_wait_us, transit_extra_us; uint32_t late_seq, ready_seq, transit_seq; }; +struct retry_choice { + uint64_t elapsed_us; + uint32_t seq, attempt, previous, selected, healthy, initialized, up, pacing, full, inflight, cwnd, total_attempts; +}; struct endpoint { struct UTUN_INSTANCE* inst; struct NODE_CONN_DIRECT* owner; @@ -61,6 +65,8 @@ static struct recovery_stats recovery; static uint32_t fault_rto_us[PATHS]; // максимум RTO каждого пути с начала отказа, независимо от измеренной паузы static uint32_t rx_trigger[2]; // DATA, разбор которого сейчас разблокировал выдачу сообщения static unsigned fault_paths; +static struct retry_choice retry_choices[4096]; // выводим после замера, чтобы I/O лога не менял выбор pacer +static unsigned retry_choice_count, retry_choice_dropped; static FILE* csv; static const char* case_name; static const char* pubkeys[2] = { @@ -202,11 +208,11 @@ struct ETCP_LINK* __wrap_etcp_loadbalancer_select_link(struct ETCP_CONN* conn, u for (struct ETCP_LINK* healthy = conn->links; healthy; healthy = healthy->next) for (unsigned p = 0; p < path_count; p++) { if ((fault_paths & (1u << p)) || ss_get_port(&healthy->remote_addr) != dummynet_get_listen_port(channels[p])) continue; int full = bytes > healthy->inflight_lim_bytes || healthy->inflight_bytes > healthy->inflight_lim_bytes - bytes; - DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "FAULT retry-choice %s seq=%u attempt=%u previous=%d selected=%d elapsed_us=%llu " - "healthy=%u initialized=%u UP=%u pacing_blocked=%d window_full=%d inflight=%u cwnd=%u total_attempts=%u", case_name, - retry->seq, retry->attempt_count, previous, chosen, (unsigned long long)(get_time_us() - fault_start), - p, healthy->initialized, healthy->link_status, healthy->shaper_timer != NULL, full, - healthy->inflight_bytes, healthy->inflight_lim_bytes, conn->active_attempts); + if (retry_choice_count == sizeof(retry_choices) / sizeof(retry_choices[0])) { retry_choice_dropped++; continue; } + retry_choices[retry_choice_count++] = (struct retry_choice){.elapsed_us=get_time_us() - fault_start, + .seq=retry->seq, .attempt=retry->attempt_count, .previous=previous, .selected=chosen, .healthy=p, + .initialized=healthy->initialized, .up=healthy->link_status, .pacing=healthy->shaper_timer != NULL, .full=full, + .inflight=healthy->inflight_bytes, .cwnd=healthy->inflight_lim_bytes, .total_attempts=conn->active_attempts}; } return selected; } @@ -264,6 +270,7 @@ static void setup(const struct profile* settings, unsigned count, unsigned mask) memset(&recovery, 0, sizeof(recovery)); memset(fault_rto_us, 0, sizeof(fault_rto_us)); memset(rx_trigger, 0, sizeof(rx_trigger)); fault_paths = 0; + retry_choice_count = retry_choice_dropped = 0; path_count = count; enabled_mask = mask; measuring = 0; fault_start = 0; fault_trace_count = 0; memcpy(profiles, settings, count * sizeof(*settings)); ua = uasync_create(); CHECK(ua); @@ -530,6 +537,14 @@ static void stalled(const struct profile* settings, unsigned count, unsigned bro else if (duration_ms > 1000) expect(rate >= capacity * 85 / 100, "fault steady goodput >=85% healthy capacity", rate, capacity * 85 / 100); for (int i = 0; i < 2; i++) CHECK(ep[i].conn->reinit_count == epochs[i] && ep[i].conn->links_up); + expect(!retry_choice_dropped, "retry choice trace has no dropped events", retry_choice_dropped, 0); + for (unsigned n = 0; n < retry_choice_count; n++) { + const struct retry_choice* c = &retry_choices[n]; + DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "FAULT retry-choice %s seq=%u attempt=%u previous=%u selected=%u elapsed_us=%llu " + "healthy=%u initialized=%u UP=%u pacing_blocked=%u window_full=%u inflight=%u cwnd=%u total_attempts=%u", case_name, + c->seq, c->attempt, c->previous, c->selected, (unsigned long long)c->elapsed_us, + c->healthy, c->initialized, c->up, c->pacing, c->full, c->inflight, c->cwnd, c->total_attempts); + } measuring = duration_ms <= 100; for (unsigned p = 0; p < count; p++) if (broken & (1u << p)) for (unsigned dir = 0; dir < 2; dir++) CHECK(dummynet_set_mode(channels[p], dir, DUMMYNET_RUN) == 0);