Distinguish early ACK packets from legitimate batched entries

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);

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;