log dropped acks

book/api/metrics-generated.md

@@ -108,6 +108,7 @@
 | quic_​ack_​tx_​merged | `counter` | ACK events (merged into existing ACK range) |
 | quic_​ack_​tx_​drop | `counter` | ACK events (out of buffers) |
 | quic_​ack_​tx_​cancel | `counter` | ACK events (ACK suppressed by handler) |
+| quic_​ack_​overflow | `counter` | Number of times the QUIC ACK queue overflowed. |
 | quic_​service_​duration_​seconds | `histogram` | Duration spent in service |
 | quic_​receive_​duration_​seconds | `histogram` | Duration spent receiving packets |
 | quic_​frame_​fail_​parse | `counter` | Number of QUIC frames failed to parse. |

src/disco/metrics/generated/fd_metrics_quic.c

@@ -61,6 +61,7 @@ const fd_metrics_meta_t FD_METRICS_QUIC[FD_METRICS_QUIC_TOTAL] = {
     DECLARE_METRIC_ENUM( QUIC_ACK_TX, COUNTER, QUIC_ACK_TX, MERGED ),
     DECLARE_METRIC_ENUM( QUIC_ACK_TX, COUNTER, QUIC_ACK_TX, DROP ),
     DECLARE_METRIC_ENUM( QUIC_ACK_TX, COUNTER, QUIC_ACK_TX, CANCEL ),
+    DECLARE_METRIC( QUIC_ACK_OVERFLOW, COUNTER ),
     DECLARE_METRIC_HISTOGRAM_SECONDS( QUIC_SERVICE_DURATION_SECONDS ),
     DECLARE_METRIC_HISTOGRAM_SECONDS( QUIC_RECEIVE_DURATION_SECONDS ),
     DECLARE_METRIC( QUIC_FRAME_FAIL_PARSE, COUNTER ),

src/disco/metrics/generated/fd_metrics_quic.h

@@ -231,87 +231,93 @@
 #define FD_METRICS_COUNTER_QUIC_ACK_TX_DROP_OFF (73UL)
 #define FD_METRICS_COUNTER_QUIC_ACK_TX_CANCEL_OFF (74UL)
 
-#define FD_METRICS_HISTOGRAM_QUIC_SERVICE_DURATION_SECONDS_OFF  (75UL)
+#define FD_METRICS_COUNTER_QUIC_ACK_OVERFLOW_OFF  (75UL)
+#define FD_METRICS_COUNTER_QUIC_ACK_OVERFLOW_NAME "quic_ack_overflow"
+#define FD_METRICS_COUNTER_QUIC_ACK_OVERFLOW_TYPE (FD_METRICS_TYPE_COUNTER)
+#define FD_METRICS_COUNTER_QUIC_ACK_OVERFLOW_DESC "Number of times the QUIC ACK queue overflowed."
+#define FD_METRICS_COUNTER_QUIC_ACK_OVERFLOW_CVT  (FD_METRICS_CONVERTER_NONE)
+
+#define FD_METRICS_HISTOGRAM_QUIC_SERVICE_DURATION_SECONDS_OFF  (76UL)
 #define FD_METRICS_HISTOGRAM_QUIC_SERVICE_DURATION_SECONDS_NAME "quic_service_duration_seconds"
 #define FD_METRICS_HISTOGRAM_QUIC_SERVICE_DURATION_SECONDS_TYPE (FD_METRICS_TYPE_HISTOGRAM)
 #define FD_METRICS_HISTOGRAM_QUIC_SERVICE_DURATION_SECONDS_DESC "Duration spent in service"
 #define FD_METRICS_HISTOGRAM_QUIC_SERVICE_DURATION_SECONDS_CVT  (FD_METRICS_CONVERTER_SECONDS)
 #define FD_METRICS_HISTOGRAM_QUIC_SERVICE_DURATION_SECONDS_MIN  (1e-08)
 #define FD_METRICS_HISTOGRAM_QUIC_SERVICE_DURATION_SECONDS_MAX  (0.1)
 
-#define FD_METRICS_HISTOGRAM_QUIC_RECEIVE_DURATION_SECONDS_OFF  (92UL)
+#define FD_METRICS_HISTOGRAM_QUIC_RECEIVE_DURATION_SECONDS_OFF  (93UL)
 #define FD_METRICS_HISTOGRAM_QUIC_RECEIVE_DURATION_SECONDS_NAME "quic_receive_duration_seconds"
 #define FD_METRICS_HISTOGRAM_QUIC_RECEIVE_DURATION_SECONDS_TYPE (FD_METRICS_TYPE_HISTOGRAM)
 #define FD_METRICS_HISTOGRAM_QUIC_RECEIVE_DURATION_SECONDS_DESC "Duration spent receiving packets"
 #define FD_METRICS_HISTOGRAM_QUIC_RECEIVE_DURATION_SECONDS_CVT  (FD_METRICS_CONVERTER_SECONDS)
 #define FD_METRICS_HISTOGRAM_QUIC_RECEIVE_DURATION_SECONDS_MIN  (1e-08)
 #define FD_METRICS_HISTOGRAM_QUIC_RECEIVE_DURATION_SECONDS_MAX  (0.1)
 
-#define FD_METRICS_COUNTER_QUIC_FRAME_FAIL_PARSE_OFF  (109UL)
+#define FD_METRICS_COUNTER_QUIC_FRAME_FAIL_PARSE_OFF  (110UL)
 #define FD_METRICS_COUNTER_QUIC_FRAME_FAIL_PARSE_NAME "quic_frame_fail_parse"
 #define FD_METRICS_COUNTER_QUIC_FRAME_FAIL_PARSE_TYPE (FD_METRICS_TYPE_COUNTER)
 #define FD_METRICS_COUNTER_QUIC_FRAME_FAIL_PARSE_DESC "Number of QUIC frames failed to parse."
 #define FD_METRICS_COUNTER_QUIC_FRAME_FAIL_PARSE_CVT  (FD_METRICS_CONVERTER_NONE)
 
-#define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_OFF  (110UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_OFF  (111UL)
 #define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_NAME "quic_pkt_crypto_failed"
 #define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_TYPE (FD_METRICS_TYPE_COUNTER)
 #define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_DESC "Number of packets that failed decryption."
 #define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_CVT  (FD_METRICS_CONVERTER_NONE)
 #define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_CNT  (4UL)
 
-#define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_INITIAL_OFF (110UL)
-#define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_EARLY_OFF (111UL)
-#define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_HANDSHAKE_OFF (112UL)
-#define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_APP_OFF (113UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_INITIAL_OFF (111UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_EARLY_OFF (112UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_HANDSHAKE_OFF (113UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_CRYPTO_FAILED_APP_OFF (114UL)
 
-#define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_OFF  (114UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_OFF  (115UL)
 #define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_NAME "quic_pkt_no_key"
 #define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_TYPE (FD_METRICS_TYPE_COUNTER)
 #define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_DESC "Number of packets that failed decryption due to missing key."
 #define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_CVT  (FD_METRICS_CONVERTER_NONE)
 #define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_CNT  (4UL)
 
-#define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_INITIAL_OFF (114UL)
-#define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_EARLY_OFF (115UL)
-#define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_HANDSHAKE_OFF (116UL)
-#define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_APP_OFF (117UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_INITIAL_OFF (115UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_EARLY_OFF (116UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_HANDSHAKE_OFF (117UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_NO_KEY_APP_OFF (118UL)
 
-#define FD_METRICS_COUNTER_QUIC_PKT_NET_HEADER_INVALID_OFF  (118UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_NET_HEADER_INVALID_OFF  (119UL)
 #define FD_METRICS_COUNTER_QUIC_PKT_NET_HEADER_INVALID_NAME "quic_pkt_net_header_invalid"
 #define FD_METRICS_COUNTER_QUIC_PKT_NET_HEADER_INVALID_TYPE (FD_METRICS_TYPE_COUNTER)
 #define FD_METRICS_COUNTER_QUIC_PKT_NET_HEADER_INVALID_DESC "Number of packets dropped due to weird IP or UDP header."
 #define FD_METRICS_COUNTER_QUIC_PKT_NET_HEADER_INVALID_CVT  (FD_METRICS_CONVERTER_NONE)
 
-#define FD_METRICS_COUNTER_QUIC_PKT_QUIC_HEADER_INVALID_OFF  (119UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_QUIC_HEADER_INVALID_OFF  (120UL)
 #define FD_METRICS_COUNTER_QUIC_PKT_QUIC_HEADER_INVALID_NAME "quic_pkt_quic_header_invalid"
 #define FD_METRICS_COUNTER_QUIC_PKT_QUIC_HEADER_INVALID_TYPE (FD_METRICS_TYPE_COUNTER)
 #define FD_METRICS_COUNTER_QUIC_PKT_QUIC_HEADER_INVALID_DESC "Number of packets dropped due to weird QUIC header."
 #define FD_METRICS_COUNTER_QUIC_PKT_QUIC_HEADER_INVALID_CVT  (FD_METRICS_CONVERTER_NONE)
 
-#define FD_METRICS_COUNTER_QUIC_PKT_UNDERSZ_OFF  (120UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_UNDERSZ_OFF  (121UL)
 #define FD_METRICS_COUNTER_QUIC_PKT_UNDERSZ_NAME "quic_pkt_undersz"
 #define FD_METRICS_COUNTER_QUIC_PKT_UNDERSZ_TYPE (FD_METRICS_TYPE_COUNTER)
 #define FD_METRICS_COUNTER_QUIC_PKT_UNDERSZ_DESC "Number of QUIC packets dropped due to being too small."
 #define FD_METRICS_COUNTER_QUIC_PKT_UNDERSZ_CVT  (FD_METRICS_CONVERTER_NONE)
 
-#define FD_METRICS_COUNTER_QUIC_PKT_OVERSZ_OFF  (121UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_OVERSZ_OFF  (122UL)
 #define FD_METRICS_COUNTER_QUIC_PKT_OVERSZ_NAME "quic_pkt_oversz"
 #define FD_METRICS_COUNTER_QUIC_PKT_OVERSZ_TYPE (FD_METRICS_TYPE_COUNTER)
 #define FD_METRICS_COUNTER_QUIC_PKT_OVERSZ_DESC "Number of QUIC packets dropped due to being too large."
 #define FD_METRICS_COUNTER_QUIC_PKT_OVERSZ_CVT  (FD_METRICS_CONVERTER_NONE)
 
-#define FD_METRICS_COUNTER_QUIC_PKT_VERNEG_OFF  (122UL)
+#define FD_METRICS_COUNTER_QUIC_PKT_VERNEG_OFF  (123UL)
 #define FD_METRICS_COUNTER_QUIC_PKT_VERNEG_NAME "quic_pkt_verneg"
 #define FD_METRICS_COUNTER_QUIC_PKT_VERNEG_TYPE (FD_METRICS_TYPE_COUNTER)
 #define FD_METRICS_COUNTER_QUIC_PKT_VERNEG_DESC "Number of QUIC version negotiation packets received."
 #define FD_METRICS_COUNTER_QUIC_PKT_VERNEG_CVT  (FD_METRICS_CONVERTER_NONE)
 
-#define FD_METRICS_COUNTER_QUIC_RETRY_SENT_OFF  (123UL)
+#define FD_METRICS_COUNTER_QUIC_RETRY_SENT_OFF  (124UL)
 #define FD_METRICS_COUNTER_QUIC_RETRY_SENT_NAME "quic_retry_sent"
 #define FD_METRICS_COUNTER_QUIC_RETRY_SENT_TYPE (FD_METRICS_TYPE_COUNTER)
 #define FD_METRICS_COUNTER_QUIC_RETRY_SENT_DESC "Number of QUIC Retry packets sent."
 #define FD_METRICS_COUNTER_QUIC_RETRY_SENT_CVT  (FD_METRICS_CONVERTER_NONE)
 
-#define FD_METRICS_QUIC_TOTAL (76UL)
+#define FD_METRICS_QUIC_TOTAL (77UL)
 extern const fd_metrics_meta_t FD_METRICS_QUIC[FD_METRICS_QUIC_TOTAL];

src/disco/metrics/metrics.xml

@@ -159,6 +159,7 @@ metric introduced.
     <counter name="ReceivedFrames" enum="QuicFrameType" summary="Number of QUIC frames received." />
 
     <counter name="AckTx" enum="QuicAckTx" summary="ACK events" />
+    <counter name="AckOverflow" summary="Number of times the QUIC ACK queue overflowed." />
 
     <histogram name="ServiceDurationSeconds" min="0.00000001" max="0.1" converter="seconds">
       <summary>Duration spent in service</summary>

src/disco/quic/fd_quic_tile.c

@@ -168,6 +168,7 @@ metrics_write( fd_quic_ctx_t * ctx ) {
   FD_MCNT_SET      ( QUIC, FRAME_FAIL_PARSE, ctx->quic->metrics.frame_rx_err_cnt );
 
   FD_MCNT_ENUM_COPY( QUIC, ACK_TX, ctx->quic->metrics.ack_tx );
+  FD_MCNT_SET(       QUIC, ACK_OVERFLOW, ctx->quic->metrics.ack_overflow_cnt );
 
   FD_MHIST_COPY( QUIC, SERVICE_DURATION_SECONDS, ctx->quic->metrics.service_duration );
   FD_MHIST_COPY( QUIC, RECEIVE_DURATION_SECONDS, ctx->quic->metrics.receive_duration );

src/waltz/quic/fd_quic.c

@@ -2001,8 +2001,9 @@ fd_quic_lazy_ack_pkt( fd_quic_t *           quic,
   }
 
   fd_quic_state_t * state = fd_quic_get_state( quic );
-  int res = fd_quic_ack_pkt( conn->ack_gen, pkt->pkt_number, pkt->enc_level, state->now );
-  conn->ack_gen->is_elicited |= fd_uchar_if( pkt->ack_flag & ACK_FLAG_RQD, 1, 0 );
+  int res = fd_quic_ack_pkt( conn->ack_gen, pkt->pkt_number, pkt->enc_level,
+                             state->now, &quic->metrics.ack_overflow_cnt );
+  conn->ack_gen->is_elicited |= !!(pkt->ack_flag & ACK_FLAG_RQD);
 
   /* Trigger immediate ACK send? */
   int ack_sz_threshold_hit = conn->unacked_sz > quic->config.ack_threshold;

src/waltz/quic/fd_quic.h

@@ -342,6 +342,7 @@ union fd_quic_metrics {
 
     /* ACK metrics */
     ulong ack_tx[ 5 ];
+    ulong ack_overflow_cnt;
 
     /* Performance metrics */
     fd_histf_t service_duration[ 1 ]; /* time spent in service */

src/waltz/quic/fd_quic_ack_tx.c

@@ -24,7 +24,8 @@ int
 fd_quic_ack_pkt( fd_quic_ack_gen_t * gen,
                  ulong               pkt_number,
                  uint                enc_level,
-                 ulong               now ) {
+                 ulong               now,
+                 ulong             * ack_overflow_cnt ) {
 
   if( pkt_number == FD_QUIC_PKT_NUM_UNUSED ) return FD_QUIC_ACK_TX_NOOP;
 
@@ -55,11 +56,14 @@ fd_quic_ack_pkt( fd_quic_ack_gen_t * gen,
 
   /* Attempt to allocate another ACK queue entry */
   if( gen->head - gen->tail >= FD_QUIC_ACK_QUEUE_CNT ) {
+    FD_DTRACE_PROBE_3( fd_quic_ack_tx_overflow, enc_level, pkt_number, now );
+    (*ack_overflow_cnt)++;
     FD_DEBUG( FD_LOG_DEBUG(( "ACK queue overflow! (excessive reordering)" )); )
     return FD_QUIC_ACK_TX_ENOSPC;
   }
 
   /* Start new pending ACK */
+  FD_DTRACE_PROBE_3( fd_quic_ack_tx_new, enc_level, pkt_number, now );
   FD_ACK_DEBUG( FD_LOG_DEBUG(( "gen=%p queue ACK for enc=%u pkt_num=%lu seq=%u",
     (void *)gen, enc_level, pkt_number, gen->head )); )
   fd_quic_ack_t * next_ack = fd_quic_ack_queue_ele( gen, gen->head );
@@ -105,6 +109,7 @@ fd_quic_gen_ack_frames( fd_quic_ack_gen_t * gen,
   for( ; gen->tail != gen->head; gen->tail++ ) {
     fd_quic_ack_t * ack = fd_quic_ack_queue_ele( gen, gen->tail );
     if( ack->enc_level != enc_level ) {
+      FD_DTRACE_PROBE_2( fd_quic_ack_tx_enc_level_break, ack->enc_level, enc_level );
       FD_ACK_DEBUG( FD_LOG_DEBUG(( "need encryption level %u for ACKs but have %u", ack->enc_level, enc_level )); )
       break;
     }
@@ -134,6 +139,7 @@ fd_quic_gen_ack_frames( fd_quic_ack_gen_t * gen,
   if( gen->head == gen->tail ) {
     gen->is_elicited = 0;
   } else {
+    FD_DTRACE_PROBE_1( fd_quic_ack_not_all_frames_flushed, gen->head - gen->tail );
     FD_ACK_DEBUG( FD_LOG_DEBUG(( "Not all ACK frames were flushed" )); )
   }
 

src/waltz/quic/fd_quic_ack_tx.h

@@ -86,7 +86,8 @@ int
 fd_quic_ack_pkt( fd_quic_ack_gen_t * gen,
                  ulong               pkt_number,
                  uint                enc_level,
-                 ulong               now );
+                 ulong               now,
+                 ulong             * ack_overflow_cnt );
 
 #define FD_QUIC_ACK_TX_NOOP   (0)
 #define FD_QUIC_ACK_TX_NEW    (1)

src/waltz/quic/tests/test_quic_ack_tx.c

@@ -24,39 +24,40 @@ main( int     argc,
   FD_TEST( !gen->is_elicited );
 
   /* Test fd_quic_ack_pkt insertion */
+  ulong null;
 
-  fd_quic_ack_pkt( gen, 1UL, 0U, 9UL ); /* new range */
+  fd_quic_ack_pkt( gen, 1UL, 0U, 9UL, &null ); /* new range */
   FD_TEST( gen->head==1 && gen->tail==0 );
   FD_TEST( gen->queue[0].pkt_number.offset_lo==1UL && gen->queue[0].pkt_number.offset_hi==2UL );
   FD_TEST( gen->queue[0].ts==9UL );
   FD_TEST( gen->queue[0].enc_level==0U );
 
-  fd_quic_ack_pkt( gen, 0UL, 0U, 10UL ); /* extend downwards */
+  fd_quic_ack_pkt( gen, 0UL, 0U, 10UL, &null ); /* extend downwards */
   FD_TEST( gen->head==1 && gen->tail==0 );
   FD_TEST( gen->queue[0].pkt_number.offset_lo==0UL && gen->queue[0].pkt_number.offset_hi==2UL );
   FD_TEST( gen->queue[0].ts==9UL );
 
-  fd_quic_ack_pkt( gen, 2UL, 0U, 11UL ); /* extend upwards */
+  fd_quic_ack_pkt( gen, 2UL, 0U, 11UL, &null ); /* extend upwards */
   FD_TEST( gen->head==1 && gen->tail==0 );
   FD_TEST( gen->queue[0].pkt_number.offset_lo==0UL && gen->queue[0].pkt_number.offset_hi==3UL );
   FD_TEST( gen->queue[0].ts==11UL );
 
   for( ulong j=0UL; j<=2UL; j++ ) {
-    fd_quic_ack_pkt( gen, j, 0U, 99UL ); /* dup */
+    fd_quic_ack_pkt( gen, j, 0U, 99UL, &null ); /* dup */
     FD_TEST( gen->head==1 && gen->tail==0 );
     FD_TEST( gen->queue[0].pkt_number.offset_lo==0UL && gen->queue[0].pkt_number.offset_hi==3UL );
     FD_TEST( gen->queue[0].ts==11UL );
   }
 
-  fd_quic_ack_pkt( gen, 4UL, 0U, 18UL ); /* gap */
+  fd_quic_ack_pkt( gen, 4UL, 0U, 18UL, &null ); /* gap */
   FD_TEST( gen->head==2 && gen->tail==0 );
   FD_TEST( gen->queue[0].pkt_number.offset_lo==0UL && gen->queue[0].pkt_number.offset_hi==3UL );
   FD_TEST( gen->queue[1].pkt_number.offset_lo==4UL && gen->queue[1].pkt_number.offset_hi==5UL );
   FD_TEST( gen->queue[1].ts==18UL );
   FD_TEST( gen->queue[0].enc_level==0U );
   FD_TEST( gen->queue[1].enc_level==0U );
 
-  fd_quic_ack_pkt( gen, 0UL, 1U, 12UL ); /* switch encryption level */
+  fd_quic_ack_pkt( gen, 0UL, 1U, 12UL, &null ); /* switch encryption level */
   FD_TEST( gen->head==3 && gen->tail==0 );
   FD_TEST( gen->queue[2].pkt_number.offset_lo==0UL && gen->queue[2].pkt_number.offset_hi==1UL );
   FD_TEST( gen->queue[2].ts==12UL );
@@ -67,7 +68,7 @@ main( int     argc,
 
   while( gen->head - gen->tail < FD_QUIC_ACK_QUEUE_CNT ) {
     ulong pkt_number = gen->head * 2UL;
-    fd_quic_ack_pkt( gen, pkt_number, 2U, 13UL );
+    fd_quic_ack_pkt( gen, pkt_number, 2U, 13UL, &null );
     FD_TEST( gen->queue[ gen->head-1 ].pkt_number.offset_lo==pkt_number     );
     FD_TEST( gen->queue[ gen->head-1 ].pkt_number.offset_hi==pkt_number+1UL );
   }