diff --git a/CHANGELOG b/CHANGELOG index e41e412c1..ef7558481 100644 --- a/CHANGELOG +++ b/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 diff --git a/EXAMPLES.txt b/EXAMPLES.txt index ac9a3c131..e75146119 100644 --- a/EXAMPLES.txt +++ b/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 diff --git a/include/lsquic.h b/include/lsquic.h index 71659bd2c..669b790d0 100644 --- a/include/lsquic.h +++ b/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; /** diff --git a/src/liblsquic/lsquic_conn.h b/src/liblsquic/lsquic_conn.h index 3b638d0b6..3f5dcd40d 100644 --- a/src/liblsquic/lsquic_conn.h +++ b/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 diff --git a/src/liblsquic/lsquic_conn_public.h b/src/liblsquic/lsquic_conn_public.h index b01185efd..b6c6be090 100644 --- a/src/liblsquic/lsquic_conn_public.h +++ b/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 diff --git a/src/liblsquic/lsquic_engine.c b/src/liblsquic/lsquic_engine.c index cf0e96661..a1de724e2 100644 --- a/src/liblsquic/lsquic_engine.c +++ b/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); } diff --git a/src/liblsquic/lsquic_frame_reader.c b/src/liblsquic/lsquic_frame_reader.c index 01cafa228..9d53924a4 100644 --- a/src/liblsquic/lsquic_frame_reader.c +++ b/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; diff --git a/src/liblsquic/lsquic_frame_reader.h b/src/liblsquic/lsquic_frame_reader.h index bcd780535..66bc959f8 100644 --- a/src/liblsquic/lsquic_frame_reader.h +++ b/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 diff --git a/src/liblsquic/lsquic_frame_writer.c b/src/liblsquic/lsquic_frame_writer.c index a84b8d6bc..444412432 100644 --- a/src/liblsquic/lsquic_frame_writer.c +++ b/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 { diff --git a/src/liblsquic/lsquic_frame_writer.h b/src/liblsquic/lsquic_frame_writer.h index c3b73dae1..f3554a62d 100644 --- a/src/liblsquic/lsquic_frame_writer.h +++ b/src/liblsquic/lsquic_frame_writer.h @@ -18,13 +18,20 @@ struct lsquic_frame_writer; struct lsquic_stream; struct lsquic_http_headers; struct lsquic_http2_setting; +#if LSQUIC_CONN_STATS +struct conn_stats; +#endif typedef ssize_t (*fw_write_f)(struct lsquic_stream *, const void *, size_t); struct lsquic_frame_writer * lsquic_frame_writer_new (struct lsquic_mm *, struct lsquic_stream *, unsigned max_frame_sz, struct lshpack_enc *, - fw_write_f, int is_server); + fw_write_f, +#if LSQUIC_CONN_STATS + struct conn_stats *, +#endif + int is_server); void lsquic_frame_writer_destroy (struct lsquic_frame_writer *); diff --git a/src/liblsquic/lsquic_full_conn.c b/src/liblsquic/lsquic_full_conn.c index 34936981b..a56c99181 100644 --- a/src/liblsquic/lsquic_full_conn.c +++ b/src/liblsquic/lsquic_full_conn.c @@ -188,19 +188,8 @@ struct full_conn union { struct client_hsk_ctx client; } fc_hsk_ctx; -#if FULL_CONN_STATS - struct { - unsigned n_all_packets_in, - n_packets_out, - n_undec_packets, - n_dup_packets, - n_err_packets; - unsigned long stream_data_sz; - unsigned long n_ticks; - unsigned n_acks_in, - n_acks_proc, - n_acks_merged[2]; - } fc_stats; +#if LSQUIC_CONN_STATS + struct conn_stats fc_stats; #endif #if KEEP_CLOSED_STREAM_HISTORY /* Rolling log of histories of closed streams. Older entries are @@ -552,6 +541,9 @@ new_conn_common (lsquic_cid_t cid, struct lsquic_engine_public *enpub, conn->fc_pub.mm = &enpub->enp_mm; conn->fc_pub.lconn = &conn->fc_conn; conn->fc_pub.send_ctl = &conn->fc_send_ctl; +#if LSQUIC_CONN_STATS + conn->fc_pub.conn_stats = &conn->fc_stats; +#endif conn->fc_pub.packet_out_malo = lsquic_malo_create(sizeof(struct lsquic_packet_out)); conn->fc_stream_ifs[STREAM_IF_STD].stream_if = stream_if; @@ -599,7 +591,11 @@ new_conn_common (lsquic_cid_t cid, struct lsquic_engine_public *enpub, { conn->fc_pub.hs = lsquic_headers_stream_new( !!(conn->fc_flags & FC_SERVER), conn->fc_enpub, - headers_callbacks_ptr, conn); + headers_callbacks_ptr, +#if LSQUIC_CONN_STATS + &conn->fc_stats, +#endif + conn); if (!conn->fc_pub.hs) goto cleanup_on_error; conn->fc_stream_ifs[STREAM_IF_HDR].stream_if = lsquic_headers_stream_if; @@ -807,18 +803,18 @@ full_conn_ci_destroy (lsquic_conn_t *lconn) if (conn->fc_conn.cn_enc_session) conn->fc_conn.cn_esf->esf_destroy(conn->fc_conn.cn_enc_session); lsquic_malo_destroy(conn->fc_pub.packet_out_malo); -#if FULL_CONN_STATS +#if LSQUIC_CONN_STATS LSQ_NOTICE("# ticks: %lu", conn->fc_stats.n_ticks); - LSQ_NOTICE("received %u packets, of which %u were not decryptable, %u were " - "dups and %u were errors; sent %u packets, avg stream data per outgoing" + LSQ_NOTICE("received %lu packets, of which %lu were not decryptable, %lu were " + "dups and %lu were errors; sent %lu packets, avg stream data per outgoing" " packet is %lu bytes", - conn->fc_stats.n_all_packets_in, conn->fc_stats.n_undec_packets, - conn->fc_stats.n_dup_packets, conn->fc_stats.n_err_packets, - conn->fc_stats.n_packets_out, - conn->fc_stats.stream_data_sz / conn->fc_stats.n_packets_out); - LSQ_NOTICE("ACKs: in: %u; processed: %u; merged to: new %u, old %u", - conn->fc_stats.n_acks_in, conn->fc_stats.n_acks_proc, - conn->fc_stats.n_acks_merged[0], conn->fc_stats.n_acks_merged[1]); + conn->fc_stats.in.packets, conn->fc_stats.in.undec_packets, + conn->fc_stats.in.dup_packets, conn->fc_stats.in.err_packets, + conn->fc_stats.out.packets, + conn->fc_stats.out.stream_data_sz / conn->fc_stats.out.packets); + LSQ_NOTICE("ACKs: in: %lu; processed: %lu; merged to: new %lu, old %lu", + conn->fc_stats.in.n_acks, conn->fc_stats.in.n_acks_proc, + conn->fc_stats.in.n_acks_merged[0], conn->fc_stats.in.n_acks_merged[1]); #endif while ((sitr = STAILQ_FIRST(&conn->fc_stream_ids_to_reset))) { @@ -933,11 +929,11 @@ new_stream (struct full_conn *conn, uint32_t stream_id, { case LSQUIC_STREAM_HANDSHAKE: idx = STREAM_IF_HSK; - flags |= SCF_DI_AUTOSWITCH; + flags |= SCF_DI_AUTOSWITCH|SCF_CRITICAL; break; case LSQUIC_STREAM_HEADERS: idx = STREAM_IF_HDR; - flags |= SCF_DI_AUTOSWITCH; + flags |= SCF_DI_AUTOSWITCH|SCF_CRITICAL; if (!(conn->fc_flags & FC_HTTP) && conn->fc_enpub->enp_settings.es_rw_once) flags |= SCF_DISP_RW_ONCE; @@ -1138,6 +1134,10 @@ process_stream_frame (struct full_conn *conn, lsquic_packet_in_t *packet_in, } EV_LOG_STREAM_FRAME_IN(LSQUIC_LOG_CONN_ID, stream_frame); LSQ_DEBUG("Got stream frame for stream #%u", stream_frame->stream_id); +#if LSQUIC_CONN_STATS + ++conn->fc_stats.in.stream_frames; + conn->fc_stats.in.stream_data_sz += stream_frame->data_frame.df_size; +#endif enc_level = lsquic_packet_in_enc_level(packet_in); if (stream_frame->stream_id != LSQUIC_STREAM_HANDSHAKE @@ -1349,8 +1349,8 @@ static int process_ack (struct full_conn *conn, struct ack_info *acki, lsquic_time_t received) { -#if FULL_CONN_STATS - ++conn->fc_stats.n_acks_proc; +#if LSQUIC_CONN_STATS + ++conn->fc_stats.in.n_acks_proc; #endif LSQ_DEBUG("Processing ACK"); if (0 == lsquic_send_ctl_got_ack(&conn->fc_send_ctl, acki, received)) @@ -1470,8 +1470,8 @@ process_ack_frame (struct full_conn *conn, lsquic_packet_in_t *packet_in, struct ack_info *const new_acki = conn->fc_pub.mm->acki; int parsed_len; -#if FULL_CONN_STATS - ++conn->fc_stats.n_acks_in; +#if LSQUIC_CONN_STATS + ++conn->fc_stats.in.n_acks; #endif parsed_len = conn->fc_conn.cn_pf->pf_parse_ack_frame(p, len, new_acki); @@ -1504,8 +1504,8 @@ process_ack_frame (struct full_conn *conn, lsquic_packet_in_t *packet_in, case (0 << 1) | (0 << 0): if (merge_saved_to_new(&conn->fc_saved_ack_info, new_acki)) { -#if FULL_CONN_STATS - ++conn->fc_stats.n_acks_merged[0] +#if LSQUIC_CONN_STATS + ++conn->fc_stats.in.n_acks_merged[0] #endif ; } @@ -1518,8 +1518,8 @@ process_ack_frame (struct full_conn *conn, lsquic_packet_in_t *packet_in, case (0 << 1) | (1 << 0): if (merge_new_to_saved(&conn->fc_saved_ack_info, new_acki)) { -#if FULL_CONN_STATS - ++conn->fc_stats.n_acks_merged[1] +#if LSQUIC_CONN_STATS + ++conn->fc_stats.in.n_acks_merged[1] #endif ; } @@ -1914,8 +1914,8 @@ process_regular_packet (struct full_conn *conn, lsquic_packet_in_t *packet_in) reconstruct_packet_number(conn, packet_in); EV_LOG_PACKET_IN(LSQUIC_LOG_CONN_ID, packet_in); -#if FULL_CONN_STATS - ++conn->fc_stats.n_all_packets_in; +#if LSQUIC_CONN_STATS + ++conn->fc_stats.in.packets; #endif /* The packet is decrypted before receive history is updated. This is @@ -1934,8 +1934,8 @@ process_regular_packet (struct full_conn *conn, lsquic_packet_in_t *packet_in) else { LSQ_INFO("could not decrypt packet"); -#if FULL_CONN_STATS - ++conn->fc_stats.n_undec_packets; +#if LSQUIC_CONN_STATS + ++conn->fc_stats.in.undec_packets; #endif return 0; } @@ -1957,8 +1957,8 @@ process_regular_packet (struct full_conn *conn, lsquic_packet_in_t *packet_in) } return 0; case REC_ST_DUP: -#if FULL_CONN_STATS - ++conn->fc_stats.n_dup_packets; +#if LSQUIC_CONN_STATS + ++conn->fc_stats.in.dup_packets; #endif LSQ_INFO("packet %"PRIu64" is a duplicate", packet_in->pi_packno); return 0; @@ -1966,8 +1966,8 @@ process_regular_packet (struct full_conn *conn, lsquic_packet_in_t *packet_in) assert(0); /* Fall through */ case REC_ST_ERR: -#if FULL_CONN_STATS - ++conn->fc_stats.n_err_packets; +#if LSQUIC_CONN_STATS + ++conn->fc_stats.in.err_packets; #endif LSQ_INFO("error processing packet %"PRIu64, packet_in->pi_packno); return -1; @@ -2343,7 +2343,7 @@ process_streams_ready_to_send (struct full_conn *conn) lsquic_spi_init(&spi, TAILQ_FIRST(&conn->fc_pub.sending_streams), TAILQ_LAST(&conn->fc_pub.sending_streams, lsquic_streams_tailq), (uintptr_t) &TAILQ_NEXT((lsquic_stream_t *) NULL, next_send_stream), - STREAM_SENDING_FLAGS, conn->fc_conn.cn_cid, "send"); + STREAM_SENDING_FLAGS, conn->fc_conn.cn_cid, "send", NULL, NULL); for (stream = lsquic_spi_first(&spi); stream; stream = lsquic_spi_next(&spi)) @@ -2485,6 +2485,8 @@ static void process_streams_read_events (struct full_conn *conn) { lsquic_stream_t *stream; + enum stream_flags service_flags; + int needs_service; struct stream_prio_iter spi; if (TAILQ_EMPTY(&conn->fc_pub.read_streams)) @@ -2493,11 +2495,21 @@ process_streams_read_events (struct full_conn *conn) lsquic_spi_init(&spi, TAILQ_FIRST(&conn->fc_pub.read_streams), TAILQ_LAST(&conn->fc_pub.read_streams, lsquic_streams_tailq), (uintptr_t) &TAILQ_NEXT((lsquic_stream_t *) NULL, next_read_stream), - STREAM_WANT_READ, conn->fc_conn.cn_cid, "read"); + STREAM_WANT_READ, conn->fc_conn.cn_cid, "read", NULL, NULL); + needs_service = 0; for (stream = lsquic_spi_first(&spi); stream; stream = lsquic_spi_next(&spi)) + { + service_flags = stream->stream_flags & STREAM_SERVICE_FLAGS; lsquic_stream_dispatch_read_events(stream); + needs_service |= service_flags + ^ (stream->stream_flags & STREAM_SERVICE_FLAGS); + } + + if (needs_service) + service_streams(conn); + } @@ -2525,7 +2537,7 @@ process_streams_write_events (struct full_conn *conn, int high_prio) TAILQ_LAST(&conn->fc_pub.write_streams, lsquic_streams_tailq), (uintptr_t) &TAILQ_NEXT((lsquic_stream_t *) NULL, next_write_stream), STREAM_WANT_WRITE|STREAM_WANT_FLUSH, conn->fc_conn.cn_cid, - high_prio ? "write-high" : "write-low"); + high_prio ? "write-high" : "write-low", NULL, NULL); if (high_prio) lsquic_spi_drop_non_high(&spi); @@ -2633,6 +2645,9 @@ generate_ack_frame (struct full_conn *conn) ABORT_ERROR("generating ACK frame failed: %d", errno); return; } +#if LSQUIC_CONN_STATS + ++conn->fc_stats.out.acks; +#endif EV_LOG_GENERATED_ACK_FRAME(LSQUIC_LOG_CONN_ID, conn->fc_conn.cn_pf, packet_out->po_data + packet_out->po_data_sz, w); verify_ack_frame(conn, packet_out->po_data + packet_out->po_data_sz, w); @@ -2796,7 +2811,7 @@ full_conn_ci_tick (lsquic_conn_t *lconn, lsquic_time_t now) } \ } while (0) -#if FULL_CONN_STATS +#if LSQUIC_CONN_STATS ++conn->fc_stats.n_ticks; #endif @@ -3050,6 +3065,9 @@ full_conn_ci_packet_in (lsquic_conn_t *lconn, lsquic_packet_in_t *packet_in) { struct full_conn *conn = (struct full_conn *) lconn; +#if LSQUIC_CONN_STATS + conn->fc_stats.in.bytes += packet_in->pi_data_sz; +#endif lsquic_alarmset_set(&conn->fc_alset, AL_IDLE, packet_in->pi_received + conn->fc_settings->es_idle_conn_to); if (0 == (conn->fc_flags & FC_ERROR)) @@ -3086,8 +3104,9 @@ full_conn_ci_packet_sent (lsquic_conn_t *lconn, lsquic_packet_out_t *packet_out) s = lsquic_send_ctl_sent_packet(&conn->fc_send_ctl, packet_out, 1); if (s != 0) ABORT_ERROR("sent packet failed: %s", strerror(errno)); -#if FULL_CONN_STATS - ++conn->fc_stats.n_packets_out; +#if LSQUIC_CONN_STATS + ++conn->fc_stats.out.packets; + conn->fc_stats.out.bytes += lsquic_packet_out_sent_sz(lconn, packet_out); #endif } @@ -3531,6 +3550,18 @@ full_conn_ci_next_tick_time (lsquic_conn_t *lconn) } +#if LSQUIC_CONN_STATS +static const struct conn_stats * +full_conn_ci_get_stats (struct lsquic_conn *lconn) +{ + struct full_conn *conn = (struct full_conn *) lconn; + return &conn->fc_stats; +} + + +#endif + + static const struct headers_stream_callbacks headers_callbacks = { .hsc_on_headers = headers_stream_on_incoming_headers, @@ -3545,6 +3576,9 @@ static const struct headers_stream_callbacks *headers_callbacks_ptr = &headers_c static const struct conn_iface full_conn_iface = { .ci_destroy = full_conn_ci_destroy, +#if LSQUIC_CONN_STATS + .ci_get_stats = full_conn_ci_get_stats, +#endif .ci_handshake_failed = full_conn_ci_handshake_failed, .ci_handshake_ok = full_conn_ci_handshake_ok, .ci_is_tickable = full_conn_ci_is_tickable, diff --git a/src/liblsquic/lsquic_headers_stream.c b/src/liblsquic/lsquic_headers_stream.c index 302f3ea56..0af159640 100644 --- a/src/liblsquic/lsquic_headers_stream.c +++ b/src/liblsquic/lsquic_headers_stream.c @@ -49,6 +49,9 @@ struct headers_stream HS_HENC_INITED = (1 << 1), } hs_flags; struct lsquic_engine_public *hs_enpub; +#if LSQUIC_CONN_STATS + struct conn_stats *hs_conn_stats; +#endif }; @@ -89,6 +92,9 @@ headers_on_new_stream (void *stream_if_ctx, lsquic_stream_t *stream) MAX_HEADERS_SIZE, &hs->hs_enpub->enp_mm, stream, lsquic_stream_read, &hs->hs_hdec, frame_callbacks_ptr, hs, +#if LSQUIC_CONN_STATS + hs->hs_conn_stats, +#endif hs->hs_enpub->enp_hsi_if, hs->hs_enpub->enp_hsi_ctx); if (!hs->hs_fr) { @@ -97,7 +103,11 @@ headers_on_new_stream (void *stream_if_ctx, lsquic_stream_t *stream) return NULL; } hs->hs_fw = lsquic_frame_writer_new(&hs->hs_enpub->enp_mm, stream, 0, - &hs->hs_henc, lsquic_stream_write, (hs->hs_flags & HS_IS_SERVER)); + &hs->hs_henc, lsquic_stream_write, +#if LSQUIC_CONN_STATS + hs->hs_conn_stats, +#endif + (hs->hs_flags & HS_IS_SERVER)); if (!hs->hs_fw) { LSQ_WARN("could not create frame writer: %s", strerror(errno)); @@ -196,6 +206,9 @@ lsquic_headers_stream_send_priority (struct headers_stream *hs, struct headers_stream * lsquic_headers_stream_new (int is_server, struct lsquic_engine_public *enpub, const struct headers_stream_callbacks *callbacks, +#if LSQUIC_CONN_STATS + struct conn_stats *conn_stats, +#endif void *cb_ctx) { struct headers_stream *hs = calloc(1, sizeof(*hs)); @@ -208,6 +221,9 @@ lsquic_headers_stream_new (int is_server, struct lsquic_engine_public *enpub, else hs->hs_flags = 0; hs->hs_enpub = enpub; +#if LSQUIC_CONN_STATS + hs->hs_conn_stats= conn_stats; +#endif return hs; } diff --git a/src/liblsquic/lsquic_headers_stream.h b/src/liblsquic/lsquic_headers_stream.h index 5cfb657ab..bc7bfb610 100644 --- a/src/liblsquic/lsquic_headers_stream.h +++ b/src/liblsquic/lsquic_headers_stream.h @@ -18,6 +18,9 @@ struct lsquic_frame_writer; struct uncompressed_headers; struct lsquic_engine_public; struct lsquic_http2_setting; +#if LSQUIC_CONN_STATS +struct conn_stats; +#endif /* Incoming frames result in new objects or events. Callbacks in this @@ -40,6 +43,9 @@ struct headers_stream_callbacks struct headers_stream * lsquic_headers_stream_new (int is_server, struct lsquic_engine_public *, const struct headers_stream_callbacks *, +#if LSQUIC_CONN_STATS + struct conn_stats *, +#endif void *hs_cb_ctx); void diff --git a/src/liblsquic/lsquic_send_ctl.c b/src/liblsquic/lsquic_send_ctl.c index cd90e3b3e..702942b8e 100644 --- a/src/liblsquic/lsquic_send_ctl.c +++ b/src/liblsquic/lsquic_send_ctl.c @@ -1117,6 +1117,9 @@ lsquic_send_ctl_next_packet_to_send (lsquic_send_ctl_t *ctl) { if (packet_out->po_regen_sz < packet_out->po_data_sz) { +#if LSQUIC_CONN_STATS + ++ctl->sc_conn_pub->conn_stats->out.retx_packets; +#endif update_for_resending(ctl, packet_out); packet_out->po_flags &= ~PO_REPACKNO; } diff --git a/src/liblsquic/lsquic_spi.c b/src/liblsquic/lsquic_spi.c index 04de9ad96..a6d71bc22 100644 --- a/src/liblsquic/lsquic_spi.c +++ b/src/liblsquic/lsquic_spi.c @@ -49,7 +49,9 @@ add_stream_to_spi (struct stream_prio_iter *iter, lsquic_stream_t *stream) void lsquic_spi_init (struct stream_prio_iter *iter, struct lsquic_stream *first, struct lsquic_stream *last, uintptr_t next_ptr_offset, - enum stream_flags onlist_mask, lsquic_cid_t cid, const char *name) + enum stream_flags onlist_mask, lsquic_cid_t cid, const char *name, + int (*filter)(void *filter_ctx, struct lsquic_stream *), + void *filter_ctx) { struct lsquic_stream *stream; unsigned count; @@ -68,14 +70,27 @@ lsquic_spi_init (struct stream_prio_iter *iter, struct lsquic_stream *first, stream = first; count = 0; - while (1) - { - add_stream_to_spi(iter, stream); - ++count; - if (stream == last) - break; - stream = NEXT_STREAM(stream, next_ptr_offset); - } + if (filter) + while (1) + { + if (filter(filter_ctx, stream)) + { + add_stream_to_spi(iter, stream); + ++count; + } + if (stream == last) + break; + stream = NEXT_STREAM(stream, next_ptr_offset); + } + else + while (1) + { + add_stream_to_spi(iter, stream); + ++count; + if (stream == last) + break; + stream = NEXT_STREAM(stream, next_ptr_offset); + } if (count > 2) SPI_DEBUG("initialized; # elems: %u; sets: [ %016"PRIX64", %016"PRIX64 diff --git a/src/liblsquic/lsquic_spi.h b/src/liblsquic/lsquic_spi.h index 4b96f0649..371945aa2 100644 --- a/src/liblsquic/lsquic_spi.h +++ b/src/liblsquic/lsquic_spi.h @@ -32,7 +32,9 @@ struct stream_prio_iter void lsquic_spi_init (struct stream_prio_iter *, struct lsquic_stream *first, struct lsquic_stream *last, uintptr_t next_ptr_offset, - unsigned onlist_mask, lsquic_cid_t cid, const char *name); + unsigned onlist_mask, lsquic_cid_t cid, const char *name, + int (*filter)(void *filter_ctx, struct lsquic_stream *), + void *filter_ctx); struct lsquic_stream * lsquic_spi_first (struct stream_prio_iter *); diff --git a/src/liblsquic/lsquic_stream.c b/src/liblsquic/lsquic_stream.c index b01eae75c..473d997c4 100644 --- a/src/liblsquic/lsquic_stream.c +++ b/src/liblsquic/lsquic_stream.c @@ -273,6 +273,8 @@ lsquic_stream_new_ext (uint32_t id, struct lsquic_conn_public *conn_pub, lsquic_stream_call_on_new(stream); if (ctor_flags & SCF_DISP_RW_ONCE) stream->stream_flags |= STREAM_RW_ONCE; + if (ctor_flags & SCF_CRITICAL) + stream->stream_flags |= STREAM_CRITICAL; return stream; } @@ -1574,6 +1576,9 @@ stream_write_to_packet (struct frame_gen_ctx *fg_ctx, const size_t size) packet_out->po_header_type = stream->tosend_off == 0 ? HETY_INITIAL : HETY_HANDSHAKE; +#if LSQUIC_CONN_STATS + const uint64_t begin_off = stream->tosend_off; +#endif off = packet_out->po_data_sz; len = pf->pf_gen_stream_frame( packet_out->po_data + packet_out->po_data_sz, @@ -1596,6 +1601,11 @@ stream_write_to_packet (struct frame_gen_ctx *fg_ctx, const size_t size) } } +#if LSQUIC_CONN_STATS + stream->conn_pub->conn_stats->out.stream_frames += 1; + stream->conn_pub->conn_stats->out.stream_data_sz + += stream->tosend_off - begin_off; +#endif EV_LOG_GENERATED_STREAM_FRAME(LSQUIC_LOG_CONN_ID, pf, packet_out->po_data + packet_out->po_data_sz, len); lsquic_send_ctl_incr_pack_sz(send_ctl, packet_out, len); diff --git a/src/liblsquic/lsquic_stream.h b/src/liblsquic/lsquic_stream.h index 925cdc03d..7bdd07022 100644 --- a/src/liblsquic/lsquic_stream.h +++ b/src/liblsquic/lsquic_stream.h @@ -62,6 +62,7 @@ struct lsquic_stream STREAM_ONNEW_DONE = (1 <<26), /* on_new_stream has been called */ STREAM_AUTOSWITCH = (1 <<27), STREAM_RW_ONCE = (1 <<28), /* When set, read/write events are dispatched once per call */ + STREAM_CRITICAL = (1 <<29), } stream_flags; /* There are more than one reason that a stream may be put onto @@ -139,6 +140,7 @@ enum stream_ctor_flags * performance. */ SCF_DISP_RW_ONCE = (1 << 3), + SCF_CRITICAL = (1 << 4), /* This is a critical stream */ }; lsquic_stream_t * @@ -274,10 +276,8 @@ struct stream_read_prog_status enum stream_flags srps_flags; }; -#define lsquic_stream_is_critical(stream) ( \ - (stream)->id == LSQUIC_STREAM_HANDSHAKE || \ - ((stream)->id == LSQUIC_STREAM_HEADERS && \ - (stream)->stream_flags & STREAM_USE_HEADERS)) +#define lsquic_stream_is_critical(stream) \ + ((stream)->stream_flags & STREAM_CRITICAL) size_t lsquic_stream_mem_used (const struct lsquic_stream *); diff --git a/test/http_client.c b/test/http_client.c index 32dd5ac6f..3745cba4c 100644 --- a/test/http_client.c +++ b/test/http_client.c @@ -31,6 +31,7 @@ #include #include #include +#include #ifndef WIN32 @@ -44,12 +45,16 @@ #include "prog.h" #include "../src/liblsquic/lsquic_logger.h" +#include "../src/liblsquic/lsquic_int_types.h" +#include "../src/liblsquic/lsquic_util.h" #define MIN(a, b) ((a) < (b) ? (a) : (b)) /* This is used to exercise generating and sending of priority frames */ static int randomly_reprioritize_streams; +static int s_display_cert_chain; + /* If this file descriptor is open, the client will accept server push and * dump the contents here. See -u flag. */ @@ -61,6 +66,71 @@ static int promise_fd = -1; */ static int g_header_bypass; +static int s_discard_response; + +struct sample_stats +{ + unsigned n; + unsigned long min, max; + unsigned long sum; /* To calculate mean */ + unsigned long sum_X2; /* To calculate stddev */ +}; + +static struct sample_stats s_stat_to_conn, /* Time to connect */ + s_stat_ttfb, + s_stat_req; /* From TTFB to EOS */ +static unsigned s_stat_conns_ok, s_stat_conns_failed; +static unsigned long s_stat_downloaded_bytes; + +static void +update_sample_stats (struct sample_stats *stats, unsigned long val) +{ + LSQ_DEBUG("%s: %p: %lu", __func__, stats, val); + if (stats->n) + { + if (val < stats->min) + stats->min = val; + else if (val > stats->max) + stats->max = val; + } + else + { + stats->min = val; + stats->max = val; + } + stats->sum += val; + stats->sum_X2 += val * val; + ++stats->n; +} + + +static void +calc_sample_stats (const struct sample_stats *stats, + long double *mean_p, long double *stddev_p) +{ + unsigned long mean, tmp; + + if (stats->n) + { + mean = stats->sum / stats->n; + *mean_p = (long double) mean; + if (stats->n > 1) + { + tmp = stats->sum_X2 - stats->n * mean * mean; + tmp /= stats->n - 1; + *stddev_p = sqrtl((long double) tmp); + } + else + *stddev_p = 0; + } + else + { + *mean_p = 0; + *stddev_p = 0; + } +} + + struct lsquic_conn_ctx; struct path_elem { @@ -91,10 +161,8 @@ struct http_client_ctx { unsigned hcc_n_open_conns; enum { - HCC_DISCARD_RESPONSE = (1 << 0), HCC_SEEN_FIN = (1 << 1), HCC_ABORT_ON_INCOMPLETE = (1 << 2), - HCC_PROCESSED_HEADERS = (1 << 3), } hcc_flags; struct prog *prog; }; @@ -103,6 +171,7 @@ struct lsquic_conn_ctx { TAILQ_ENTRY(lsquic_conn_ctx) next_ch; lsquic_conn_t *conn; struct http_client_ctx *client_ctx; + lsquic_time_t ch_created; unsigned ch_n_reqs; /* This number gets decremented as streams are closed and * incremented as push promises are accepted. */ @@ -128,6 +197,8 @@ static void hset_dump (const struct hset *, FILE *); static void hset_destroy (void *hset); +static void +display_cert_chain (lsquic_conn_t *); static void @@ -168,6 +239,7 @@ http_client_on_new_conn (void *stream_if_ctx, lsquic_conn_t *conn) TAILQ_INSERT_TAIL(&client_ctx->conn_ctxs, conn_h, next_ch); ++conn_h->client_ctx->hcc_n_open_conns; create_streams(client_ctx, conn_h); + conn_h->ch_created = lsquic_time_now(); return conn_h; } @@ -246,7 +318,21 @@ http_client_on_conn_closed (lsquic_conn_t *conn) static void http_client_on_hsk_done (lsquic_conn_t *conn, int ok) { + lsquic_conn_ctx_t *conn_h; LSQ_INFO("handshake %s", ok ? "completed successfully" : "failed"); + + if (ok && s_display_cert_chain) + display_cert_chain(conn); + + if (ok) + { + conn_h = lsquic_conn_get_ctx(conn); + ++s_stat_conns_ok; + update_sample_stats(&s_stat_to_conn, + lsquic_time_now() - conn_h->ch_created); + } + else + ++s_stat_conns_failed; } @@ -256,8 +342,10 @@ struct lsquic_stream_ctx { const char *path; enum { HEADERS_SENT = (1 << 0), - CHAIN_DISPLAYED = (1 << 1), + PROCESSED_HEADERS = 1 << 1, } sh_flags; + lsquic_time_t sh_created; + lsquic_time_t sh_ttfb; unsigned count; struct lsquic_reader reader; }; @@ -278,6 +366,7 @@ http_client_on_new_stream (void *stream_if_ctx, lsquic_stream_t *stream) lsquic_stream_ctx_t *st_h = calloc(1, sizeof(*st_h)); st_h->stream = stream; st_h->client_ctx = stream_if_ctx; + st_h->sh_created = lsquic_time_now(); if (st_h->client_ctx->hcc_cur_pe) { st_h->client_ctx->hcc_cur_pe = TAILQ_NEXT( @@ -406,12 +495,6 @@ http_client_on_write (lsquic_stream_t *stream, lsquic_stream_ctx_t *st_h) { ssize_t nw; - if (!(st_h->sh_flags & CHAIN_DISPLAYED)) - { - display_cert_chain(lsquic_stream_conn(stream)); - st_h->sh_flags |= CHAIN_DISPLAYED; - } - if (st_h->sh_flags & HEADERS_SENT) { if (st_h->client_ctx->payload && test_reader_size(st_h->reader.lsqr_ctx) > 0) @@ -459,8 +542,7 @@ http_client_on_read (lsquic_stream_t *stream, lsquic_stream_ctx_t *st_h) srand(GetTickCount()); #endif - if (g_header_bypass - && !(client_ctx->hcc_flags & HCC_PROCESSED_HEADERS)) + if (g_header_bypass && !(st_h->sh_flags & PROCESSED_HEADERS)) { hset = lsquic_stream_get_hset(stream); if (!hset) @@ -468,10 +550,14 @@ http_client_on_read (lsquic_stream_t *stream, lsquic_stream_ctx_t *st_h) LSQ_ERROR("could not get header set from stream"); exit(2); } - if (!(client_ctx->hcc_flags & HCC_DISCARD_RESPONSE)) + st_h->sh_ttfb = lsquic_time_now(); + update_sample_stats(&s_stat_ttfb, st_h->sh_ttfb - st_h->sh_created); + if (s_discard_response) + LSQ_DEBUG("discard response: do not dump headers"); + else hset_dump(hset, stdout); hset_destroy(hset); - client_ctx->hcc_flags |= HCC_PROCESSED_HEADERS; + st_h->sh_flags |= PROCESSED_HEADERS; } do @@ -479,7 +565,16 @@ http_client_on_read (lsquic_stream_t *stream, lsquic_stream_ctx_t *st_h) nread = lsquic_stream_read(stream, buf, sizeof(buf)); if (nread > 0) { - if (!(client_ctx->hcc_flags & HCC_DISCARD_RESPONSE)) + s_stat_downloaded_bytes += nread; + if (!g_header_bypass && !(st_h->sh_flags & PROCESSED_HEADERS)) + { + /* First read is assumed to be the first byte */ + st_h->sh_ttfb = lsquic_time_now(); + update_sample_stats(&s_stat_ttfb, + st_h->sh_ttfb - st_h->sh_created); + st_h->sh_flags |= PROCESSED_HEADERS; + } + if (!s_discard_response) write(STDOUT_FILENO, buf, nread); if (randomly_reprioritize_streams && (st_h->count++ & 0x3F) == 0) { @@ -496,6 +591,7 @@ http_client_on_read (lsquic_stream_t *stream, lsquic_stream_ctx_t *st_h) } else if (0 == nread) { + update_sample_stats(&s_stat_req, lsquic_time_now() - st_h->sh_ttfb); client_ctx->hcc_flags |= HCC_SEEN_FIN; lsquic_stream_shutdown(stream, 0); break; @@ -597,6 +693,9 @@ usage (const char *prog) " -C DIR Certificate store. If specified, server certificate will\n" " be verified.\n" #endif +" -a Display server certificate chain after successful handshake.\n" +" -t Print stats to stdout.\n" +" -T FILE Print stats to FILE. If FILE is -, print stats to stdout.\n" , prog); } @@ -708,8 +807,9 @@ hset_create (void *hsi_ctx, int is_push_promise) { struct hset *hset; - hset = malloc(sizeof(*hset)); - if (hset) + if (s_discard_response) + return (void *) 1; + else if ((hset = malloc(sizeof(*hset)))) { STAILQ_INIT(hset); return hset; @@ -727,6 +827,14 @@ hset_add_header (void *hset_p, unsigned name_idx, struct hset *hset = hset_p; struct hset_elem *el; + if (name) + s_stat_downloaded_bytes += name_len + value_len + 4; /* ": \r\n" */ + else + s_stat_downloaded_bytes += 2; /* \r\n "*/ + + if (s_discard_response) + return LSQUIC_HDR_OK; + if (!name) /* This signals end of headers. We do no post-processing. */ return LSQUIC_HDR_OK; @@ -756,14 +864,17 @@ hset_destroy (void *hset_p) struct hset *hset = hset_p; struct hset_elem *el, *next; - for (el = STAILQ_FIRST(hset); el; el = next) + if (!s_discard_response) { - next = STAILQ_NEXT(el, next); - free(el->name); - free(el->value); - free(el); + for (el = STAILQ_FIRST(hset); el; el = next) + { + next = STAILQ_NEXT(el, next); + free(el->name); + free(el->value); + free(el); + } + free(hset); } - free(hset); } @@ -796,10 +907,25 @@ static const struct lsquic_hset_if header_bypass_api = }; +static void +display_stat (FILE *out, const struct sample_stats *stats, const char *name) +{ + long double mean, stddev; + + calc_sample_stats(stats, &mean, &stddev); + fprintf(out, "%s: n: %u; min: %.2Lf ms; max: %.2Lf ms; mean: %.2Lf ms; " + "sd: %.2Lf ms\n", name, stats->n, (long double) stats->min / 1000, + (long double) stats->max / 1000, mean / 1000, stddev / 1000); +} + + int main (int argc, char **argv) { int opt, s; + lsquic_time_t start_time; + FILE *stats_fh = NULL; + long double elapsed; struct http_client_ctx client_ctx; struct stat st; struct path_elem *pe; @@ -825,11 +951,14 @@ main (int argc, char **argv) while (-1 != (opt = getopt(argc, argv, PROG_OPTS "46Br:R:IKu:EP:M:n:w:H:p:h" #ifndef WIN32 - "C:" + "C:atT:" #endif ))) { switch (opt) { + case 'a': + ++s_display_cert_chain; + break; case '4': case '6': prog.prog_ipver = opt - '0'; @@ -843,7 +972,7 @@ main (int argc, char **argv) client_ctx.hcc_flags |= HCC_ABORT_ON_INCOMPLETE; break; case 'K': - client_ctx.hcc_flags |= HCC_DISCARD_RESPONSE; + ++s_discard_response; break; case 'u': /* Accept psh promise */ promise_fd = open(optarg, O_WRONLY|O_CREAT|O_TRUNC, 0644); @@ -902,18 +1031,39 @@ main (int argc, char **argv) prog.prog_api.ea_verify_ctx = optarg; break; #endif + case 't': + stats_fh = stdout; + break; + case 'T': + if (0 == strcmp(optarg, "-")) + stats_fh = stdout; + else + { + stats_fh = fopen(optarg, "w"); + if (!stats_fh) + { + perror("fopen"); + exit(1); + } + } + break; default: if (0 != prog_set_opt(&prog, opt, optarg)) exit(1); } } +#if LSQUIC_CONN_STATS + prog.prog_api.ea_stats_fh = stats_fh; +#endif + if (TAILQ_EMPTY(&client_ctx.hcc_path_elems)) { fprintf(stderr, "Specify at least one path using -p option\n"); exit(1); } + start_time = lsquic_time_now(); if (0 != prog_prep(&prog)) { LSQ_ERROR("could not prep"); @@ -925,6 +1075,21 @@ main (int argc, char **argv) LSQ_DEBUG("entering event loop"); s = prog_run(&prog); + + if (stats_fh) + { + elapsed = (long double) (lsquic_time_now() - start_time) / 1000000; + fprintf(stats_fh, "overall statistics as calculated by %s:\n", argv[0]); + display_stat(stats_fh, &s_stat_to_conn, "time for connect"); + display_stat(stats_fh, &s_stat_req, "time for request"); + display_stat(stats_fh, &s_stat_ttfb, "time to 1st byte"); + fprintf(stats_fh, "downloaded %lu application bytes in %.3Lf seconds\n", + s_stat_downloaded_bytes, elapsed); + fprintf(stats_fh, "%.2Lf reqs/sec; %.0Lf bytes/sec\n", + (long double) s_stat_req.n / elapsed, + (long double) s_stat_downloaded_bytes / elapsed); + } + prog_cleanup(&prog); if (promise_fd >= 0) (void) close(promise_fd); diff --git a/test/unittests/test_frame_chop.c b/test/unittests/test_frame_chop.c index 47cb48b08..18d2635ee 100644 --- a/test/unittests/test_frame_chop.c +++ b/test/unittests/test_frame_chop.c @@ -27,6 +27,10 @@ #include "lsquic_frame_common.h" #include "lsquic_frame_writer.h" #include "lsquic_frame_reader.h" +#if LSQUIC_CONN_STATS +#include "lsquic_int_types.h" +#include "lsquic_conn.h" +#endif struct lsquic_stream @@ -98,11 +102,20 @@ test_chop (unsigned max_write_sz) struct lshpack_enc henc; int s; +#if LSQUIC_CONN_STATS + struct conn_stats conn_stats; + memset(&conn_stats, 0, sizeof(conn_stats)); +#endif + lsquic_mm_init(&mm); lshpack_enc_init(&henc); stream = stream_new(max_write_sz); - fw = lsquic_frame_writer_new(&mm, stream, 0, &henc, stream_write, 0); + fw = lsquic_frame_writer_new(&mm, stream, 0, &henc, stream_write, +#if LSQUIC_CONN_STATS + &conn_stats, +#endif + 0); struct lsquic_http_header header_arr[] = { diff --git a/test/unittests/test_frame_reader.c b/test/unittests/test_frame_reader.c index e28ec9097..b0657d2ca 100644 --- a/test/unittests/test_frame_reader.c +++ b/test/unittests/test_frame_reader.c @@ -23,6 +23,10 @@ #include "lsquic_stream.h" #include "lsquic_conn_public.h" #include "lsquic_logger.h" +#if LSQUIC_CONN_STATS +#include "lsquic_int_types.h" +#include "lsquic_conn.h" +#endif #include "lsquic_frame_reader.h" #include "lsquic_headers.h" @@ -1105,6 +1109,11 @@ test_one_frt (const struct frame_reader_test *frt) struct lsquic_stream stream; int s; +#if LSQUIC_CONN_STATS + struct conn_stats conn_stats; + memset(&conn_stats, 0, sizeof(conn_stats)); +#endif + memset(&stream, 0, sizeof(stream)); memset(&lconn, 0, sizeof(lconn)); memset(&conn_pub, 0, sizeof(conn_pub)); @@ -1125,6 +1134,9 @@ test_one_frt (const struct frame_reader_test *frt) fr = lsquic_frame_reader_new(frt->frt_fr_flags, frt->frt_max_headers_sz, &mm, &stream, read_from_stream, &hdec, &frame_callbacks, &g_cb_ctx, +#if LSQUIC_CONN_STATS + &conn_stats, +#endif lsquic_http1x_if, NULL); do { diff --git a/test/unittests/test_frame_rw.c b/test/unittests/test_frame_rw.c index 6bc3fe219..1e4370c03 100644 --- a/test/unittests/test_frame_rw.c +++ b/test/unittests/test_frame_rw.c @@ -29,6 +29,10 @@ #include "lsquic_frame_reader.h" #include "lsquic_headers.h" #include "lsquic_http1x_if.h" +#if LSQUIC_CONN_STATS +#include "lsquic_int_types.h" +#include "lsquic_conn.h" +#endif struct lsquic_stream @@ -192,6 +196,10 @@ test_rw (unsigned max_frame_sz) struct lshpack_enc henc; struct lshpack_dec hdec; int s; +#if LSQUIC_CONN_STATS + struct conn_stats conn_stats; + memset(&conn_stats, 0, sizeof(conn_stats)); +#endif lsquic_mm_init(&mm); lshpack_enc_init(&henc); @@ -200,7 +208,11 @@ test_rw (unsigned max_frame_sz) stream->sm_max_sz = 1; fw = lsquic_frame_writer_new(&mm, stream, max_frame_sz, &henc, - stream_write, 0); + stream_write, +#if LSQUIC_CONN_STATS + &conn_stats, +#endif + 0); struct lsquic_http_headers headers = { .count = N_HEADERS, @@ -216,7 +228,11 @@ test_rw (unsigned max_frame_sz) stream->sm_off = 0; fr = lsquic_frame_reader_new(0, 0, &mm, stream, read_from_stream, &hdec, - &frame_callbacks, &uh, lsquic_http1x_if, NULL); + &frame_callbacks, &uh, +#if LSQUIC_CONN_STATS + &conn_stats, +#endif + lsquic_http1x_if, NULL); do { s = lsquic_frame_reader_read(fr); diff --git a/test/unittests/test_frame_writer.c b/test/unittests/test_frame_writer.c index d252052a4..dd84ff8e4 100644 --- a/test/unittests/test_frame_writer.c +++ b/test/unittests/test_frame_writer.c @@ -14,6 +14,14 @@ #include "lsquic_mm.h" #include "lsquic_frame_common.h" #include "lsquic_frame_writer.h" +#if LSQUIC_CONN_STATS +#include "lsquic_int_types.h" +#include "lsquic_conn.h" +#endif + +#if LSQUIC_CONN_STATS +static struct conn_stats s_conn_stats; +#endif static struct { @@ -65,11 +73,19 @@ test_max_frame_size (void) for (max_size = 1; max_size < 6 /* one settings frame */; ++max_size) { fw = lsquic_frame_writer_new(&mm, NULL, max_size, &henc, - output_write, 0); + output_write, +#if LSQUIC_CONN_STATS + &s_conn_stats, +#endif + 0); assert(!fw); } - fw = lsquic_frame_writer_new(&mm, NULL, max_size, &henc, output_write, 0); + fw = lsquic_frame_writer_new(&mm, NULL, max_size, &henc, output_write, +#if LSQUIC_CONN_STATS + &s_conn_stats, +#endif + 0); assert(fw); lsquic_frame_writer_destroy(fw); @@ -88,7 +104,11 @@ test_one_header (void) lshpack_enc_init(&henc); lsquic_mm_init(&mm); - fw = lsquic_frame_writer_new(&mm, NULL, 0x200, &henc, output_write, 0); + fw = lsquic_frame_writer_new(&mm, NULL, 0x200, &henc, output_write, +#if LSQUIC_CONN_STATS + &s_conn_stats, +#endif + 0); reset_output(0); struct lsquic_http_header header_arr[] = @@ -148,7 +168,11 @@ test_oversize_header (void) lshpack_enc_init(&henc); lsquic_mm_init(&mm); - fw = lsquic_frame_writer_new(&mm, NULL, 0x200, &henc, output_write, 0); + fw = lsquic_frame_writer_new(&mm, NULL, 0x200, &henc, output_write, +#if LSQUIC_CONN_STATS + &s_conn_stats, +#endif + 0); reset_output(0); value = malloc(big_len); @@ -186,7 +210,11 @@ test_continuations (void) lshpack_enc_init(&henc); lsquic_mm_init(&mm); - fw = lsquic_frame_writer_new(&mm, NULL, 6, &henc, output_write, 0); + fw = lsquic_frame_writer_new(&mm, NULL, 6, &henc, output_write, +#if LSQUIC_CONN_STATS + &s_conn_stats, +#endif + 0); reset_output(0); /* @@ -271,7 +299,11 @@ test_settings_short (void) struct lsquic_mm mm; lsquic_mm_init(&mm); - fw = lsquic_frame_writer_new(&mm, NULL, 7, NULL, output_write, 0); + fw = lsquic_frame_writer_new(&mm, NULL, 7, NULL, output_write, +#if LSQUIC_CONN_STATS + &s_conn_stats, +#endif + 0); { reset_output(0); @@ -315,7 +347,11 @@ test_settings_normal (void) struct lsquic_mm mm; lsquic_mm_init(&mm); - fw = lsquic_frame_writer_new(&mm, NULL, 0, NULL, output_write, 0); + fw = lsquic_frame_writer_new(&mm, NULL, 0, NULL, output_write, +#if LSQUIC_CONN_STATS + &s_conn_stats, +#endif + 0); { reset_output(0); @@ -372,7 +408,11 @@ test_priority (void) struct lsquic_mm mm; lsquic_mm_init(&mm); - fw = lsquic_frame_writer_new(&mm, NULL, 6, NULL, output_write, 0); + fw = lsquic_frame_writer_new(&mm, NULL, 6, NULL, output_write, +#if LSQUIC_CONN_STATS + &s_conn_stats, +#endif + 0); s = lsquic_frame_writer_write_priority(fw, 3, 0, 1UL << 31, 256); assert(s < 0); /* Invalid dependency stream ID */ @@ -431,7 +471,11 @@ test_errors (void) lshpack_enc_init(&henc); lsquic_mm_init(&mm); - fw = lsquic_frame_writer_new(&mm, NULL, 0x200, &henc, output_write, 1); + fw = lsquic_frame_writer_new(&mm, NULL, 0x200, &henc, output_write, +#if LSQUIC_CONN_STATS + &s_conn_stats, +#endif + 1); reset_output(0); { @@ -481,7 +525,11 @@ test_push_promise (void) lshpack_enc_init(&henc); lsquic_mm_init(&mm); - fw = lsquic_frame_writer_new(&mm, NULL, 0x200, &henc, output_write, 1); + fw = lsquic_frame_writer_new(&mm, NULL, 0x200, &henc, output_write, +#if LSQUIC_CONN_STATS + &s_conn_stats, +#endif + 1); reset_output(0); /* diff --git a/test/unittests/test_spi.c b/test/unittests/test_spi.c index d47b53c0c..87a0e39ef 100644 --- a/test/unittests/test_spi.c +++ b/test/unittests/test_spi.c @@ -72,7 +72,7 @@ test_same_priority (unsigned priority) lsquic_spi_init(&spi, TAILQ_FIRST(&streams), TAILQ_LAST(&streams, lsquic_streams_tailq), (uintptr_t) &TAILQ_NEXT((lsquic_stream_t *) NULL, next_write_stream), - flags, 0, __func__); + flags, 0, __func__, NULL, NULL); stream = lsquic_spi_first(&spi); assert(stream == stream_arr[0]); @@ -88,7 +88,7 @@ test_same_priority (unsigned priority) /* Test reinitialization: */ lsquic_spi_init(&spi, stream_arr[0], stream_arr[1], (uintptr_t) &TAILQ_NEXT((lsquic_stream_t *) NULL, next_write_stream), - flags, 0, __func__); + flags, 0, __func__, NULL, NULL); stream = lsquic_spi_first(&spi); assert(stream == stream_arr[0]); stream = lsquic_spi_next(&spi); @@ -122,7 +122,7 @@ test_different_priorities (int *priority) lsquic_spi_init(&spi, TAILQ_FIRST(&streams), TAILQ_LAST(&streams, lsquic_streams_tailq), (uintptr_t) &TAILQ_NEXT((lsquic_stream_t *) NULL, next_send_stream), - flags, 0, __func__); + flags, 0, __func__, NULL, NULL); for (prev_prio = -1, count = 0, stream = lsquic_spi_first(&spi); stream; stream = lsquic_spi_next(&spi), ++count) @@ -209,7 +209,7 @@ test_drop (const struct drop_test *test) lsquic_spi_init(&spi, TAILQ_FIRST(&streams), TAILQ_LAST(&streams, lsquic_streams_tailq), (uintptr_t) &TAILQ_NEXT((lsquic_stream_t *) NULL, next_write_stream), - STREAM_WRITE_Q_FLAGS, 0, __func__); + STREAM_WRITE_Q_FLAGS, 0, __func__, NULL, NULL); if (drop_high) lsquic_spi_drop_high(&spi); @@ -229,6 +229,69 @@ test_drop (const struct drop_test *test) } +#define MAGIC 0x12312312U + +struct my_filter_ctx +{ + unsigned magic; +}; + + +static int +filter_out_odd_priorities (void *ctx, lsquic_stream_t *stream) +{ + struct my_filter_ctx *fctx = ctx; + assert(fctx->magic == MAGIC); + return 0 == (stream->sm_priority & 1); +} + + +static void +test_different_priorities_filter_odd (int *priority) +{ + struct lsquic_streams_tailq streams; + unsigned flags = 0xC000; /* Arbitrary value */ + lsquic_stream_t *stream; + int prio, prev_prio, count, n_streams = 0; + + TAILQ_INIT(&streams); + + for ( ; *priority >= 0; ++priority) + { + assert(*priority < 256); + stream = new_stream(*priority); + TAILQ_INSERT_TAIL(&streams, stream, next_send_stream); + stream->stream_flags |= flags; + ++n_streams; + } + + struct my_filter_ctx my_filter_ctx = { MAGIC }; + + lsquic_spi_init(&spi, TAILQ_FIRST(&streams), + TAILQ_LAST(&streams, lsquic_streams_tailq), + (uintptr_t) &TAILQ_NEXT((lsquic_stream_t *) NULL, next_send_stream), + flags, 0, NULL, filter_out_odd_priorities, &my_filter_ctx); + + for (prev_prio = -1, count = 0, stream = lsquic_spi_first(&spi); stream; + stream = lsquic_spi_next(&spi), ++count) + { + prio = stream->sm_priority; + assert(0 == (prio & 1)); + assert(prio >= prev_prio); + if (prio > prev_prio) + prev_prio = prio; + } + + assert(count < n_streams); + + while ((stream = TAILQ_FIRST(&streams))) + { + TAILQ_REMOVE(&streams, stream, next_send_stream); + free(stream); + } +} + + int main (int argc, char **argv) { @@ -259,6 +322,11 @@ main (int argc, char **argv) test_different_priorities(prio); } + { + int prio[] = { 200, 202, 240, 201, 200, 199, -1 }; + test_different_priorities_filter_odd(prio); + } + unsigned n; for (n = 0; n < sizeof(drop_tests) / sizeof(drop_tests[0]); ++n) test_drop(&drop_tests[n]);