diff --git a/tests/test_etcp_multipath.c b/tests/test_etcp_multipath.c index bea4723e..85d9987a 100644 --- a/tests/test_etcp_multipath.c +++ b/tests/test_etcp_multipath.c @@ -92,6 +92,7 @@ static const char* privkeys[2] = { struct diagnostic_interval { uint64_t tx_data, fresh_rx, data_packets, retries, ack_only_packets, ack_only_wire, piggy_packets, piggy_bytes; uint64_t ack_entries, ack_delay_sum, ack_delay_max, ack_only_entries, ack_only_delay_sum, early_ack_entries; + uint64_t ordinary_ack_packets, early_ack_packets; // молодые entries допустимы в пакете, где старейший ACK уже готов uint64_t control_packets, samples, limited, app_limited; uint64_t rtt_min, rtt_max, rtt_sum, rtt_samples, searches, window_blocked, pacer_blocked, observations; uint32_t flight_min, flight_max, cwnd_min, cwnd_max, send_max, ack_max; @@ -236,20 +237,21 @@ static void diagnostic_flush(void) { (unsigned long long)d->searches, (unsigned long long)d->window_blocked, (unsigned long long)d->pacer_blocked, (unsigned long long)d->observations, d->flight_min, d->flight_max, d->cwnd_min, d->cwnd_max, d->send_max, d->ack_max, (long long)d->debt_min_us, (long long)d->debt_max_us) > 0); - CHECK(fprintf(diagnostic_file, ",%u,%u,%u,%u,%u,%u,%u,%u,%u,%u,%u,%u,%u\n", s->app_suspended, s->app_resume, + CHECK(fprintf(diagnostic_file, ",%u,%u,%u,%u,%u,%u,%u,%u,%u,%u,%u,%u,%u,%llu,%llu\n", s->app_suspended, s->app_resume, s->fragment_suspended, s->fragment_resume, s->waiter_deferred, s->tx_state, s->tx_scheduled, s->tx_delayed, - s->tx_running, s->active_attempts, s->next_seq, s->peer_till, s->local_till) > 0); + s->tx_running, s->active_attempts, s->next_seq, s->peer_till, s->local_till, + (unsigned long long)d->ordinary_ack_packets, (unsigned long long)d->early_ack_packets) > 0); DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "MPATH %s mask=%x %s t_ms=%llu dt_us=%llu side=%u path=%u " "Q_app=%u Q_fragment=%u Q_send=%u(new=%u retry=%u) Q_ACK=%u age_us=%llu flight=%u/%u " "pace_Bps=%u debt_us=%lld ready_us=%llu timer=%u window_blocked_checks=%llu pacer_blocked_checks=%llu " - "channel_pending=%u mode=%u/%u DATA_B=%llu ACKonly=%llu early_ACK=%llu", + "channel_pending=%u mode=%u/%u DATA_B=%llu ACKonly=%llu early_ACK_entries=%llu early_ACK_packets=%llu", case_name, enabled_mask, s->phase, (unsigned long long)(s->time_us/1000), (unsigned long long)s->interval_us, s->side, s->path, s->queue_count[0], s->queue_count[1], s->queue_count[2], s->fresh, s->retries, s->ack_count, (unsigned long long)s->ack_age_us, s->flight, s->cwnd, s->pace, (long long)s->debt_us, (unsigned long long)s->pacer_ready_us, s->pacer_timer, (unsigned long long)d->window_blocked, (unsigned long long)d->pacer_blocked, s->channel_pending, s->mode, s->cycle, (unsigned long long)d->tx_data, - (unsigned long long)d->ack_only_packets, (unsigned long long)d->early_ack_entries); + (unsigned long long)d->ack_only_packets, (unsigned long long)d->early_ack_entries, (unsigned long long)d->early_ack_packets); } CHECK(fflush(diagnostic_file) == 0); diagnostic_count = 0; diagnostic_flushing = 0; @@ -321,16 +323,23 @@ static void observe_packet(struct ETCP_DGRAM* pkt, struct ETCP_LINK* link, int s d->ack_only_wire += pkt->data_len + ETCP_ENCRYPTED_HDR_SIZE + ETCP_SESSION_HEADER_SIZE + SC_NONCE_SIZE + SC_CRC32_SIZE + SC_TAG_SIZE; } else if (!pkt->payload_len) d->control_packets++; + uint32_t oldest_delay = 0; for (unsigned n = 0; n < data[1]; n++) { const uint8_t* a = data + ETCP_ACK_BASE_SIZE + n * ETCP_ACK_ENTRY_SIZE; uint32_t delay = (uint32_t)a[6] | ((uint32_t)a[7] << 8) | ((uint32_t)a[8] << 16) | ((uint32_t)a[9] << 24); d->ack_entries++; d->ack_delay_sum += delay; + if (delay > oldest_delay) oldest_delay = delay; if (delay > d->ack_delay_max) d->ack_delay_max = delay; if (ack_only) { d->ack_only_entries++; d->ack_only_delay_sum += delay; if (!link->ack_reply_pending && delay < 2000) d->early_ack_entries++; } } + if (ack_only && data[1] && !link->ack_reply_pending) { + d->ordinary_ack_packets++; + int till_due = link->etcp->ack_till_deadline_us && link->etcp->ack_till_deadline_us <= get_time_us(); + if (!till_due && oldest_delay < ETCP_ACK_DELAY_US) d->early_ack_packets++; + } } break; } @@ -847,7 +856,8 @@ int main(int argc, char** argv) { "selection_checks,selection_window_blocked,selection_pacer_blocked,observed_states,flight_min,flight_max," "cwnd_min,cwnd_max,send_peak_observed,ack_peak_observed,debt_min_us,debt_max_us,app_callback_suspended," "app_resume_scheduled,fragment_callback_suspended,fragment_resume_scheduled,normalizer_waiter_deferred," - "tx_state,tx_scheduled,tx_delayed,tx_running,active_attempts,next_tx_seq,peer_ack_till,local_delivered_till\n") > 0); + "tx_state,tx_scheduled,tx_delayed,tx_running,active_attempts,next_tx_seq,peer_ack_till,local_delivered_till," + "ordinary_ack_only_packets,early_ordinary_ack_packets\n") > 0); debug_set_category_level(DEBUG_CATEGORY_DEBUG, DEBUG_LEVEL_INFO); DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "Multipath diagnostics: period_us=%u file=%s; snapshots buffered until drain", diagnostic_period_us, detail); diff --git a/tools/etcp_diag_report.py b/tools/etcp_diag_report.py index 7e246b6e..641bb54d 100644 --- a/tools/etcp_diag_report.py +++ b/tools/etcp_diag_report.py @@ -24,6 +24,7 @@ def read_samples(path): valid &= row["flight_min"] <= row["flight_bytes"] <= row["flight_max"] valid &= row["cwnd_min"] <= row["cwnd_bytes"] <= row["cwnd_max"] valid &= row["early_ordinary_ack_entries"] <= row["ack_only_entries"] <= row["ack_entries"] + valid &= row["early_ordinary_ack_packets"] <= row["ordinary_ack_only_packets"] <= row["ack_only_packets"] valid &= row["retries"] <= row["data_packets"] and row["rtt_samples"] <= row["bbr_samples"] if key in previous: valid &= row["time_us"] - previous[key] == row["dt_us"] @@ -75,7 +76,7 @@ const definitions=[ ['Задержка ACK и RTT: мс',[['ACK-only mean',r=>r.ack_only_entries?r.ack_only_delay_sum_us/r.ack_only_entries/1000:0], ['ACK max',r=>r.ack_delay_max_us/1000],['SRTT',r=>r.srtt_us/1000],['min RTT',r=>r.min_rtt_us===4294967295?0:r.min_rtt_us/1000]]], ['Наблюдения блокировки выбора: проверки за срез',[['Окно',r=>r.selection_window_blocked], - ['Pacer',r=>r.selection_pacer_blocked],['Обычные ACK-only раньше 2мс',r=>r.early_ordinary_ack_entries]]], + ['Pacer',r=>r.selection_pacer_blocked],['ACK-пакеты раньше дедлайна',r=>r.early_ordinary_ack_packets]]], ['Эмулятор: ожидающие пакеты',[['Все ожидающие (delay + сериализация + HOLD)',r=>r.channel_pending]]] ]; let current=[], selectedTime=null;