Release 1.17.14

- [FEATURE] http_client can now collect stats: time to connect, TTFB,
  time to download, requests per seconds, and bandwidth.  See -t flag.

- [BUGFIX] http_client: -B, -K, and -r can be used at the same time.

- [BUGFIX] http_client: do not display cert chain before each request.
  Now this is only done once per connection, if the handshake is
  successful and -a option is given.

- [BUGFIX] Do not wait to dispatch on_close() after reading.  If a
  stream is scheduled to be closed after on_read() callback returns,
  close it immediately instead of waiting until the end of the tick.
  If client creates new request from on_close() event, they will be
  processed in the same tick instead of waiting for the next one.

- [BUGFIX] HEADERS stream is critical: always treat it with highest
  priority.

CHANGELOG

@@ -1,3 +1,19 @@
+2019-01-16
+    - 1.17.14
+    - [FEATURE] http_client can now collect stats: time to connect, TTFB,
+      time to download, requests per seconds, and bandwidth.  See -t flag.
+    - [BUGFIX] http_client: -B, -K, and -r can be used at the same time.
+    - [BUGFIX] http_client: do not display cert chain before each request.
+      Now this is only done once per connection, if the handshake is
+      successful and -a option is given.
+    - [BUGFIX] Do not wait to dispatch on_close() after reading.  If a
+      stream is scheduled to be closed after on_read() callback returns,
+      close it immediately instead of waiting until the end of the tick.
+      If client creates new request from on_close() event, they will be
+      processed in the same tick instead of waiting for the next one.
+    - [BUGFIX] HEADERS stream is critical: always treat it with highest
+      priority.
+
 2019-01-10
     - 1.17.12
     - [FEATURE] http_client can now issue parallel requests in the context

EXAMPLES.txt

@@ -119,15 +119,15 @@ Control Network-Related Stuff
 More Compilation Options
 ------------------------
 
--DFULL_CONN_STATS=1
+-DLSQUIC_CONN_STATS=1
 
-    Track some statistics about full connection -- packets in, sent, delayed,
+    Track some statistics about connections -- packets in, sent, delayed,
     stream payload per packet size ratio, and some others -- and print them
     at NOTICE level when connection is destroyed.
 
-    This is useful when performing network testing and especially analyzing
-    the effects of changing send buffer size (see -S sndbuf= in the previous
-    section).
+    Cumulative connections statistics are printed by the engine when it is
+    destroyed if lsquic_engine_api.ea_stats_fh is set.  The HTTP client
+    programs sets it when -t or -T command-line option is used.
 
 -DLSQUIC_PACKINTS_SANITY_CHECK=1
 

include/lsquic.h

@@ -25,7 +25,7 @@ extern "C" {
 
 #define LSQUIC_MAJOR_VERSION 1
 #define LSQUIC_MINOR_VERSION 17
-#define LSQUIC_PATCH_VERSION 12
+#define LSQUIC_PATCH_VERSION 14
 
 /**
  * Engine flags:
@@ -614,6 +614,13 @@ typedef struct lsquic_engine_api
      */
     const struct lsquic_hset_if         *ea_hsi_if;
     void                                *ea_hsi_ctx;
+#if LSQUIC_CONN_STATS
+    /**
+     * If set, engine will print cumulative connection statistics to this
+     * file just before it is destroyed.
+     */
+    void /* FILE, really */             *ea_stats_fh;
+#endif
 } lsquic_engine_api_t;
 
 /**

src/liblsquic/lsquic_conn.h

@@ -22,6 +22,9 @@ struct lsquic_packet_in;
 struct sockaddr;
 struct parse_funcs;
 struct attq_elem;
+#if LSQUIC_CONN_STATS
+struct conn_stats;
+#endif
 
 enum lsquic_conn_flags {
     LSCONN_TICKED         = (1 << 0),
@@ -83,6 +86,11 @@ struct conn_iface
 
     lsquic_time_t
     (*ci_next_tick_time) (struct lsquic_conn *);
+
+#if LSQUIC_CONN_STATS
+    const struct conn_stats *
+    (*ci_get_stats) (struct lsquic_conn *);
+#endif
 };
 
 struct lsquic_conn
@@ -127,4 +135,37 @@ lsquic_conn_copy_and_release_pi_data (const lsquic_conn_t *conn,
 
 #define lsquic_conn_adv_time(c) ((c)->cn_attq_elem->ae_adv_time)
 
+#if LSQUIC_CONN_STATS
+struct conn_stats {
+    /* All counters are of the same type, unsigned long, because we cast the
+     * struct to an array to update the aggregate.
+     */
+    unsigned long           n_ticks;            /* How many time connection was ticked */
+    struct {
+        unsigned long       stream_data_sz;     /* Sum of all STREAM frames payload */
+        unsigned long       stream_frames;      /* Number of STREAM frames */
+        unsigned long       packets,            /* Incoming packets */
+                            undec_packets,      /* Undecryptable packets */
+                            dup_packets,        /* Duplicate packets */
+                            err_packets;        /* Error packets(?) */
+        unsigned long       n_acks,
+                            n_acks_proc,
+                            n_acks_merged[2];
+        unsigned long       bytes;              /* Overall bytes in */
+        unsigned long       headers_uncomp;     /* Sum of uncompressed header bytes */
+        unsigned long       headers_comp;       /* Sum of compressed header bytes */
+    }                   in;
+    struct {
+        unsigned long       stream_data_sz;
+        unsigned long       stream_frames;
+        unsigned long       acks;
+        unsigned long       packets;            /* Number of sent packets */
+        unsigned long       retx_packets;       /* Number of retransmitted packets */
+        unsigned long       bytes;              /* Overall bytes out */
+        unsigned long       headers_uncomp;     /* Sum of uncompressed header bytes */
+        unsigned long       headers_comp;       /* Sum of compressed header bytes */
+    }                   out;
+};
+#endif
+
 #endif

src/liblsquic/lsquic_conn_public.h

@@ -16,6 +16,9 @@ struct lsquic_mm;
 struct lsquic_hash;
 struct headers_stream;
 struct lsquic_send_ctl;
+#if LSQUIC_CONN_STATS
+struct conn_stats;
+#endif
 
 struct lsquic_conn_public {
     struct lsquic_streams_tailq     sending_streams,    /* Send RST_STREAM, BLOCKED, and WUF frames */
@@ -32,6 +35,9 @@ struct lsquic_conn_public {
     struct lsquic_mm               *mm;
     struct headers_stream          *hs;
     struct lsquic_send_ctl         *send_ctl;
+#if LSQUIC_CONN_STATS
+    struct conn_stats              *conn_stats;
+#endif
 };
 
 #endif

src/liblsquic/lsquic_engine.c

@@ -171,6 +171,13 @@ struct lsquic_engine
     unsigned                           n_conns;
     lsquic_time_t                      deadline;
     lsquic_time_t                      resume_sending_at;
+#if LSQUIC_CONN_STATS
+    struct {
+        unsigned                conns;
+    }                                  stats;
+    struct conn_stats                  conn_stats_sum;
+    FILE                              *stats_fh;
+#endif
     struct out_batch                   out_batch;
 };
 
@@ -348,6 +355,9 @@ lsquic_engine_new (unsigned flags,
     eng_hist_init(&engine->history);
     engine->batch_size = INITIAL_OUT_BATCH_SIZE;
 
+#if LSQUIC_CONN_STATS
+    engine->stats_fh = api->ea_stats_fh;
+#endif
 
     LSQ_INFO("instantiated engine");
     return engine;
@@ -368,12 +378,37 @@ shrink_batch_size (struct lsquic_engine *engine)
 }
 
 
+#if LSQUIC_CONN_STATS
+void
+update_stats_sum (struct lsquic_engine *engine, struct lsquic_conn *conn)
+{
+    unsigned long *const dst = (unsigned long *) &engine->conn_stats_sum;
+    const unsigned long *src;
+    const struct conn_stats *stats;
+    unsigned i;
+
+    if (conn->cn_if->ci_get_stats && (stats = conn->cn_if->ci_get_stats(conn)))
+    {
+        ++engine->stats.conns;
+        src = (unsigned long *) stats;
+        for (i = 0; i < sizeof(*stats) / sizeof(unsigned long); ++i)
+            dst[i] += src[i];
+    }
+}
+
+
+#endif
+
+
 /* Wrapper to make sure important things occur before the connection is
  * really destroyed.
  */
 static void
 destroy_conn (struct lsquic_engine *engine, lsquic_conn_t *conn)
 {
+#if LSQUIC_CONN_STATS
+    update_stats_sum(engine, conn);
+#endif
     --engine->n_conns;
     conn->cn_flags |= LSCONN_NEVER_TICKABLE;
     conn->cn_if->ci_destroy(conn);
@@ -580,6 +615,44 @@ lsquic_engine_destroy (lsquic_engine_t *engine)
     assert(0 == lsquic_mh_count(&engine->conns_tickable));
     lsquic_mm_cleanup(&engine->pub.enp_mm);
     free(engine->conns_tickable.mh_elems);
+#if LSQUIC_CONN_STATS
+    if (engine->stats_fh)
+    {
+        const struct conn_stats *const stats = &engine->conn_stats_sum;
+        fprintf(engine->stats_fh, "Aggregate connection stats collected by engine:\n");
+        fprintf(engine->stats_fh, "Connections: %u\n", engine->stats.conns);
+        fprintf(engine->stats_fh, "Ticks: %lu\n", stats->n_ticks);
+        fprintf(engine->stats_fh, "In:\n");
+        fprintf(engine->stats_fh, "    Total bytes: %lu\n", stats->in.bytes);
+        fprintf(engine->stats_fh, "    packets: %lu\n", stats->in.packets);
+        fprintf(engine->stats_fh, "    undecryptable packets: %lu\n", stats->in.undec_packets);
+        fprintf(engine->stats_fh, "    duplicate packets: %lu\n", stats->in.dup_packets);
+        fprintf(engine->stats_fh, "    error packets: %lu\n", stats->in.err_packets);
+        fprintf(engine->stats_fh, "    STREAM frame count: %lu\n", stats->in.stream_frames);
+        fprintf(engine->stats_fh, "    STREAM payload size: %lu\n", stats->in.stream_data_sz);
+        fprintf(engine->stats_fh, "    Header bytes: %lu; uncompressed: %lu; ratio %.3lf\n",
+            stats->in.headers_comp, stats->in.headers_uncomp,
+            stats->in.headers_uncomp ?
+            (double) stats->in.headers_comp / (double) stats->in.headers_uncomp
+            : 0);
+        fprintf(engine->stats_fh, "    ACK frames: %lu\n", stats->in.n_acks);
+        fprintf(engine->stats_fh, "    ACK frames processed: %lu\n", stats->in.n_acks_proc);
+        fprintf(engine->stats_fh, "    ACK frames merged to new: %lu\n", stats->in.n_acks_merged[0]);
+        fprintf(engine->stats_fh, "    ACK frames merged to old: %lu\n", stats->in.n_acks_merged[1]);
+        fprintf(engine->stats_fh, "Out:\n");
+        fprintf(engine->stats_fh, "    Total bytes: %lu\n", stats->out.bytes);
+        fprintf(engine->stats_fh, "    packets: %lu\n", stats->out.packets);
+        fprintf(engine->stats_fh, "    retx packets: %lu\n", stats->out.retx_packets);
+        fprintf(engine->stats_fh, "    STREAM frame count: %lu\n", stats->out.stream_frames);
+        fprintf(engine->stats_fh, "    STREAM payload size: %lu\n", stats->out.stream_data_sz);
+        fprintf(engine->stats_fh, "    Header bytes: %lu; uncompressed: %lu; ratio %.3lf\n",
+            stats->out.headers_comp, stats->out.headers_uncomp,
+            stats->out.headers_uncomp ?
+            (double) stats->out.headers_comp / (double) stats->out.headers_uncomp
+            : 0);
+        fprintf(engine->stats_fh, "    ACKs: %lu\n", stats->out.acks);
+    }
+#endif
     free(engine);
 }
 

src/liblsquic/lsquic_frame_reader.c

@@ -22,6 +22,7 @@
 #include "lsquic_http1x_if.h"
 #include "lsquic_headers.h"
 #include "lsquic_ev_log.h"
+#include "lsquic_conn.h"
 
 #define LSQUIC_LOGGER_MODULE LSQLM_FRAME_READER
 #define LSQUIC_LOG_CONN_ID lsquic_conn_id(lsquic_stream_conn(fr->fr_stream))
@@ -116,6 +117,9 @@ struct lsquic_frame_reader
      * CONTINUATION frames.  It gets added to as block fragments come in.
      */
     unsigned char                   *fr_header_block;
+#if LSQUIC_CONN_STATS
+    struct conn_stats               *fr_conn_stats;
+#endif
     unsigned                         fr_header_block_sz;
     unsigned                         fr_max_headers_sz; /* 0 means no limit */
     enum frame_reader_flags          fr_flags;
@@ -175,6 +179,9 @@ lsquic_frame_reader_new (enum frame_reader_flags flags,
                     struct lshpack_dec *hdec,
                     const struct frame_reader_callbacks *cb,
                     void *frame_reader_cb_ctx,
+#if LSQUIC_CONN_STATS
+                    struct conn_stats *conn_stats,
+#endif
                     const struct lsquic_hset_if *hsi_if, void *hsi_ctx)
 {
     struct lsquic_frame_reader *fr = malloc(sizeof(*fr));
@@ -202,6 +209,9 @@ lsquic_frame_reader_new (enum frame_reader_flags flags,
     else
         fr->fr_hsi_ctx = hsi_ctx;
     reset_state(fr);
+#if LSQUIC_CONN_STATS
+    fr->fr_conn_stats = conn_stats;
+#endif
     return fr;
 }
 
@@ -538,7 +548,12 @@ decode_and_pass_payload (struct lsquic_frame_reader *fr)
                 fr->fr_hsi_if->hsi_process_header(hset, name_idx, buf,
                                         name_len, buf + name_len, val_len);
             if (err == 0)
+            {
+#if LSQUIC_CONN_STATS
+                fr->fr_conn_stats->in.headers_uncomp += name_len + val_len;
+#endif
                 continue;
+            }
         }
         else
             err = FR_ERR_DECOMPRESS;
@@ -589,6 +604,9 @@ decode_and_pass_payload (struct lsquic_frame_reader *fr)
         fr->fr_callbacks->frc_on_headers(fr->fr_cb_ctx, uh);
     else
         fr->fr_callbacks->frc_on_push_promise(fr->fr_cb_ctx, uh);
+#if LSQUIC_CONN_STATS
+    fr->fr_conn_stats->in.headers_comp += fr->fr_header_block_sz;
+#endif
 
     return 0;
 

src/liblsquic/lsquic_frame_reader.h

@@ -18,6 +18,9 @@ struct lsquic_stream;
 struct lsquic_frame_reader;
 struct lsquic_hset_if;
 struct uncompressed_headers;
+#if LSQUIC_CONN_STATS
+struct conn_stats;
+#endif
 
 
 enum frame_reader_flags
@@ -79,6 +82,9 @@ lsquic_frame_reader_new (enum frame_reader_flags, unsigned max_headers_sz,
                          struct lsquic_mm *, struct lsquic_stream *,
                          fr_stream_read_f, struct lshpack_dec *,
                          const struct frame_reader_callbacks *, void *fr_cb_ctx,
+#if LSQUIC_CONN_STATS
+                         struct conn_stats *conn_stats,
+#endif
                          const struct lsquic_hset_if *, void *hsi_ctx);
 
 int

src/liblsquic/lsquic_frame_writer.c

@@ -21,6 +21,8 @@
 #include "lshpack.h"
 #include "lsquic_mm.h"
 #include "lsquic.h"
+#include "lsquic_int_types.h"
+#include "lsquic_conn.h"
 
 #include "lsquic_frame_writer.h"
 #include "lsquic_frame_common.h"
@@ -65,6 +67,9 @@ struct lsquic_frame_writer
     fw_write_f                  fw_write;
     struct lsquic_mm           *fw_mm;
     struct lshpack_enc         *fw_henc;
+#if LSQUIC_CONN_STATS
+    struct conn_stats          *fw_conn_stats;
+#endif
     struct frame_buf_head       fw_frabs;
     unsigned                    fw_max_frame_sz;
     uint32_t                    fw_max_header_list_sz;  /* 0 means unlimited */
@@ -86,6 +91,9 @@ struct lsquic_frame_writer
 struct lsquic_frame_writer *
 lsquic_frame_writer_new (struct lsquic_mm *mm, struct lsquic_stream *stream,
      unsigned max_frame_sz, struct lshpack_enc *henc, fw_write_f write,
+#if LSQUIC_CONN_STATS
+     struct conn_stats *conn_stats,
+#endif
      int is_server)
 {
     struct lsquic_frame_writer *fw;
@@ -124,6 +132,9 @@ lsquic_frame_writer_new (struct lsquic_mm *mm, struct lsquic_stream *stream,
     else
         fw->fw_flags    = 0;
     TAILQ_INIT(&fw->fw_frabs);
+#if LSQUIC_CONN_STATS
+    fw->fw_conn_stats   = conn_stats;
+#endif
     return fw;
 }
 
@@ -458,6 +469,12 @@ write_headers (struct lsquic_frame_writer *fw,
             s = hfc_write(hfc, buf, end - buf);
             if (s < 0)
                 return s;
+#if LSQUIC_CONN_STATS
+            fw->fw_conn_stats->out.headers_uncomp +=
+                headers->headers[i].name.iov_len
+                    + headers->headers[i].value.iov_len;
+            fw->fw_conn_stats->out.headers_comp += end - buf;
+#endif
         }
         else
         {