From 4ce8d93d93186de92e786563208f95430b85819a Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Mon, 4 Nov 2019 18:49:53 -0600 Subject: [PATCH 01/18] Adds support for logging framework - Uses DPDK logging as the backend - Every log message includes Module, Timestamp, Filename and Linenumber - Log modules and Log levels are supported Signed-off-by: Rajath Shashidhara --- Makefile | 2 +- include/utils_log.h | 95 +++++++++++++++++++++++++++++++++++++++++++++ tas/fast/fastemu.c | 3 ++ 3 files changed, 99 insertions(+), 1 deletion(-) create mode 100644 include/utils_log.h diff --git a/Makefile b/Makefile index 506c2426..0968188d 100644 --- a/Makefile +++ b/Makefile @@ -7,7 +7,7 @@ INCDIR ?= $(PREFIX)/include RTE_SDK ?= /usr/ -CFLAGS += -std=gnu99 -O3 -g -Wall -Werror -I. -Iinclude/ -march=native -fno-omit-frame-pointer +CFLAGS += -std=gnu99 -O3 -g -Wall -Wno-address-of-packed-member -Werror -I. -Iinclude/ -march=native -fno-omit-frame-pointer LDFLAGS += -pthread -g RTE_SDK ?= $(HOME)/dpdk/x86_64-native-linuxapp-gcc diff --git a/include/utils_log.h b/include/utils_log.h new file mode 100644 index 00000000..fee46aed --- /dev/null +++ b/include/utils_log.h @@ -0,0 +1,95 @@ +#ifndef UTILS_LOG_H_ +#define UTILS_LOG_H_ + +#include +#include + +#include +#include + +/* + * DPDK supports 8 user-defined log types. + * TAS modules are mapped into user-defined types for: + * (a) Helps identify the module from the log + * (b) Module-wise filtering of logs may be implemented in the future + */ + +#define _LOG_USER_START RTE_LOGTYPE_USER1 +#define _LOG_USER_END RTE_LOGTYPE_USER8 + +enum +{ + LOG_MAIN, + LOG_FAST_TX, + LOG_FAST_RX, + LOG_FAST_QMAN, + LOG_FAST_QMAN_FWD, + LOG_FAST_APPIF, + LOG_SLOW, + // Add more if required ! + LOG_END +}; + +/* Useful macros */ +#define BUILD_BUG_ON(condition) ((void)sizeof(char[1 - 2*!!(condition)])) + +#define TIMESTAMP_FMTSTR "[%4.4u:%2.2u:%2.2u.%6.6u]" +#define FILE_LINENUM_FMTSTR "[%15.15s:%4.4d]" +#define PAD_FMTSTR " " +#define __FILENAME__ (__builtin_strrchr(__FILE__, '/') ? __builtin_strrchr(__FILE__, '/') + 1 : __FILE__) + +static inline const char* +gettimestamp() +{ + static __thread char buf[20]; + + // Prepare the timestamp + uint64_t cyc = rte_get_tsc_cycles(); + static __thread uint64_t freq = 0; + + if (freq == 0) + freq = rte_get_tsc_hz(); + + uint64_t elapsed_time_secs = cyc / freq; + cyc = cyc % freq; // for sub-second values + unsigned int hrs, mins, secs, microsecs; + hrs = (unsigned) (elapsed_time_secs / (60 * 60)); + elapsed_time_secs -= (hrs * 60 * 60); + mins = (unsigned) (elapsed_time_secs / 60); + elapsed_time_secs -= (mins * 60); + secs = (unsigned) elapsed_time_secs; + microsecs = (unsigned) ((cyc * 1000000ULL) / freq); + + snprintf(buf, sizeof(buf), TIMESTAMP_FMTSTR, hrs, mins, secs, microsecs); + + return buf; +} + +static inline int +tas_log(uint32_t level, + uint32_t logtype, + const char* format, ...) +{ + BUILD_BUG_ON((LOG_END + _LOG_USER_START) > _LOG_USER_END); + + va_list ap; + int ret; + + va_start(ap, format); + ret = rte_vlog(level, logtype, format, ap); + va_end(ap); + + return ret; +} + +#define TAS_LOG(l, t, fmtstr, ...) \ + (void)((RTE_LOG_ ## l <= RTE_LOG_DP_LEVEL) ? \ + tas_log(RTE_LOG_ ## l, \ + _LOG_USER_START + LOG_ ## t, \ + "%s" FILE_LINENUM_FMTSTR PAD_FMTSTR # t ": " fmtstr, \ + gettimestamp(), \ + __FILENAME__, __LINE__, \ + __VA_ARGS__) : \ + 0) + +#endif /* UTILS_LOG_H_ */ diff --git a/tas/fast/fastemu.c b/tas/fast/fastemu.c index 5dbb63f2..ec24fcde 100644 --- a/tas/fast/fastemu.c +++ b/tas/fast/fastemu.c @@ -32,6 +32,7 @@ #include #include +#include #include "internal.h" #include "fastemu.h" @@ -143,6 +144,8 @@ void dataplane_loop(struct dataplane_context *ctx) uint64_t cyc, prev_cyc; int was_idle = 1; + TAS_LOG(INFO, MAIN, "lcore %d: Entering dataplane_loop()\n", rte_lcore_id()); + while (!exited) { unsigned n = 0; From dffd4ed5121eefee4f2abf4651e08983e704482a Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Sun, 10 Nov 2019 13:18:14 -0600 Subject: [PATCH 02/18] Trim trailing whitespaces and fix indentation Signed-off-by: Rajath Shashidhara --- tas/fast/fastemu.c | 61 ++++++++++++++++--------------- tas/slow/kernel.c | 91 +++++++++++++++++++++++----------------------- 2 files changed, 77 insertions(+), 75 deletions(-) diff --git a/tas/fast/fastemu.c b/tas/fast/fastemu.c index ec24fcde..94a64f5f 100644 --- a/tas/fast/fastemu.c +++ b/tas/fast/fastemu.c @@ -184,38 +184,39 @@ void dataplane_loop(struct dataplane_context *ctx) was_idle = 1; if(startwait == 0) { - startwait = ts; + startwait = ts; } else if (config.fp_interrupts && ts - startwait >= POLL_CYCLE) { - // Idle -- wait for interrupt or data from apps/kernel - int r = network_rx_interrupt_ctl(&ctx->net, 1); - - // Only if device running - if(r == 0) { - uint32_t timeout_us = qman_next_ts(&ctx->qman, ts); - /* fprintf(stderr, "[%u] fastemu idle - timeout %d ms\n", ctx->core, */ - /* timeout_us == (uint32_t)-1 ? -1 : timeout_us / 1000); */ - struct rte_epoll_event event[2]; - int n = rte_epoll_wait(RTE_EPOLL_PER_THREAD, event, 2, - timeout_us == (uint32_t)-1 ? -1 : timeout_us / 1000); - assert(n != -1); - /* fprintf(stderr, "[%u] fastemu busy - %u events\n", ctx->core, n); */ - for(int i = 0; i < n; i++) { - if(event[i].fd == ctx->evfd) { - /* fprintf(stderr, "[%u] fastemu - woken up by event FD = %d\n", */ - /* ctx->core, event[i].fd); */ - uint64_t val; - int r = read(ctx->evfd, &val, sizeof(uint64_t)); - assert(r == sizeof(uint64_t)); - /* } else { */ - /* fprintf(stderr, "[%u] fastemu - woken up by RX interrupt FD = %d\n", */ - /* ctx->core, event[i].fd); */ - } - } + // Idle -- wait for interrupt or data from apps/kernel + int r = network_rx_interrupt_ctl(&ctx->net, 1); + + // Only if device running + if(r == 0) { + uint32_t timeout_us = qman_next_ts(&ctx->qman, ts); + /* fprintf(stderr, "[%u] fastemu idle - timeout %d ms\n", ctx->core, */ + /* timeout_us == (uint32_t)-1 ? -1 : timeout_us / 1000); */ + struct rte_epoll_event event[2]; + int n = rte_epoll_wait(RTE_EPOLL_PER_THREAD, event, 2, + timeout_us == (uint32_t)-1 ? -1 : timeout_us / 1000); + assert(n != -1); + /* fprintf(stderr, "[%u] fastemu busy - %u events\n", ctx->core, n); */ + for(int i = 0; i < n; i++) { + if(event[i].fd == ctx->evfd) { + /* fprintf(stderr, "[%u] fastemu - woken up by event FD = %d\n", */ + /* ctx->core, event[i].fd); */ + uint64_t val; + int r = read(ctx->evfd, &val, sizeof(uint64_t)); + assert(r == sizeof(uint64_t)); + /* } else { */ + /* fprintf(stderr, "[%u] fastemu - woken up by RX interrupt FD = %d\n", */ + /* ctx->core, event[i].fd); */ + } + } /*fprintf(stderr, "dataplane_loop: woke up %u n=%u fd=%d evfd=%d\n", ctx->id, n, event[0].fd, ctx->evfd);*/ - network_rx_interrupt_ctl(&ctx->net, 0); - } - startwait = 0; + network_rx_interrupt_ctl(&ctx->net, 0); + } + + startwait = 0; } } else { was_idle = 0; @@ -392,7 +393,7 @@ static unsigned poll_kernel(struct dataplane_context *ctx, uint32_t ts) for (k = 0; k < max;) { ret = fast_kernel_poll(ctx, handles[k], ts); - + if (ret == 0) k++; else if (ret < 0) diff --git a/tas/slow/kernel.c b/tas/slow/kernel.c index 3f687e01..4aa18539 100644 --- a/tas/slow/kernel.c +++ b/tas/slow/kernel.c @@ -131,52 +131,53 @@ int slowpath_main(void) if(UNLIKELY(n == 0)) { if(startwait == 0) { - startwait = cur_ts; + startwait = cur_ts; } else if(cur_ts - startwait >= POLL_CYCLE) { - // Idle -- wait for data from apps/flexnic - uint32_t cc_timeout = cc_next_ts(cur_ts), - util_timeout = util_timeout_next(&timeout_mgr, cur_ts), - timeout_us; - int timeout_ms; - - if(cc_timeout != -1U && util_timeout != -1U) { - timeout_us = MIN(cc_timeout, util_timeout); - } else if(cc_timeout != -1U) { - timeout_us = util_timeout; - } else { - timeout_us = cc_timeout; - } - if(timeout_us != -1U) { - timeout_ms = timeout_us / 1000; - } else { - timeout_ms = -1; - } - - // Deal with load management - if(timeout_ms == -1 || timeout_ms > 1000) { - timeout_ms = 10; - } - - /* fprintf(stderr, "idle - timeout %d ms, cc_timeout = %u us, util_timeout = %u us\n", timeout_ms, cc_timeout, util_timeout); */ - struct epoll_event event[2]; - int n; - again: - n = epoll_wait(epfd, event, 2, timeout_ms); - if(n == -1) { - if(errno == EINTR) { - // XXX: To support attaching GDB - goto again; - } - } - assert(n != -1); - /* fprintf(stderr, "busy - %u events\n", n); */ - for(int i = 0; i < n; i++) { - assert(event[i].data.fd == kernel_notifyfd); - uint64_t val; - /* fprintf(stderr, "- woken up by event FD = %d\n", event[i].data.fd); */ - int r = read(kernel_notifyfd, &val, sizeof(uint64_t)); - assert(r == sizeof(uint64_t)); - } + // Idle -- wait for data from apps/flexnic + uint32_t cc_timeout = cc_next_ts(cur_ts), + util_timeout = util_timeout_next(&timeout_mgr, cur_ts), + timeout_us; + int timeout_ms; + + if(cc_timeout != -1U && util_timeout != -1U) { + timeout_us = MIN(cc_timeout, util_timeout); + } else if(cc_timeout != -1U) { + timeout_us = util_timeout; + } else { + timeout_us = cc_timeout; + } + if(timeout_us != -1U) { + timeout_ms = timeout_us / 1000; + } else { + timeout_ms = -1; + } + + // Deal with load management + if(timeout_ms == -1 || timeout_ms > 1000) { + timeout_ms = 10; + } + + /* fprintf(stderr, "idle - timeout %d ms, cc_timeout = %u us, util_timeout = %u us\n", timeout_ms, cc_timeout, util_timeout); */ + struct epoll_event event[2]; + int n; + + again: + n = epoll_wait(epfd, event, 2, timeout_ms); + if(n == -1) { + if(errno == EINTR) { + // XXX: To support attaching GDB + goto again; + } + } + assert(n != -1); + /* fprintf(stderr, "busy - %u events\n", n); */ + for(int i = 0; i < n; i++) { + assert(event[i].data.fd == kernel_notifyfd); + uint64_t val; + /* fprintf(stderr, "- woken up by event FD = %d\n", event[i].data.fd); */ + int r = read(kernel_notifyfd, &val, sizeof(uint64_t)); + assert(r == sizeof(uint64_t)); + } } } else { startwait = 0; From fab3d664aad769c31668e40170e2b0148ad610e7 Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Sun, 10 Nov 2019 15:01:16 -0600 Subject: [PATCH 03/18] Improve dataplane stats collection and logging Signed-off-by: Rajath Shashidhara --- Makefile | 1 + tas/fast/fastemu.c | 32 +++++++++++++++++++++++++++++--- tas/include/fastpath.h | 10 ++++++++++ tas/slow/kernel.c | 6 ++++++ 4 files changed, 46 insertions(+), 3 deletions(-) diff --git a/Makefile b/Makefile index 0968188d..c8109fa8 100644 --- a/Makefile +++ b/Makefile @@ -15,6 +15,7 @@ DPDK_PMDS ?= ixgbe i40e tap virtio CFLAGS+= -I$(RTE_SDK)/include -I$(RTE_SDK)/include/dpdk CFLAGS+= -I$(RTE_SDK)/include/x86_64-linux-gnu/dpdk/ +CFLAGS+= -DDATAPLANE_STATS LDFLAGS+= -L$(RTE_SDK)/lib/ LIBS_DPDK= -Wl,--whole-archive diff --git a/tas/fast/fastemu.c b/tas/fast/fastemu.c index 94a64f5f..7bf6d3e7 100644 --- a/tas/fast/fastemu.c +++ b/tas/fast/fastemu.c @@ -162,6 +162,8 @@ void dataplane_loop(struct dataplane_context *ctx) n += poll_rx(ctx, ts); STATS_TS(rx); tx_flush(ctx); + STATS_TS(acktx); + STATS_TSADD(ctx, cyc_tx, acktx - rx); n += poll_qman_fwd(ctx, ts); @@ -173,9 +175,13 @@ void dataplane_loop(struct dataplane_context *ctx) STATS_TS(qs); STATS_TSADD(ctx, cyc_qs, qs - qm); n += poll_kernel(ctx, ts); + STATS_TS(sp); + STATS_TSADD(ctx, cyc_sp, sp - qs); /* flush transmit buffer */ tx_flush(ctx); + STATS_TS(tx); + STATS_TSADD(ctx, cyc_tx, tx - sp); if (ctx->id == 0) poll_scale(ctx); @@ -238,19 +244,29 @@ void dataplane_dump_stats(void) for (i = 0; i < fp_cores_max; i++) { ctx = ctxs[i]; + if (ctx == NULL) + continue; + fprintf(stderr, "dp stats %u: " "qm=(%"PRIu64",%"PRIu64",%"PRIu64") " "rx=(%"PRIu64",%"PRIu64",%"PRIu64") " "qs=(%"PRIu64",%"PRIu64",%"PRIu64") " - "cyc=(%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64")\n", i, + "sp=(%"PRIu64",%"PRIu64",%"PRIu64") " + "tx=(%"PRIu64",%"PRIu64",%"PRIu64") " + "cyc=(%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64")\n", i, read_stat(&ctx->stat_qm_poll), read_stat(&ctx->stat_qm_empty), read_stat(&ctx->stat_qm_total), read_stat(&ctx->stat_rx_poll), read_stat(&ctx->stat_rx_empty), read_stat(&ctx->stat_rx_total), read_stat(&ctx->stat_qs_poll), read_stat(&ctx->stat_qs_empty), read_stat(&ctx->stat_qs_total), + read_stat(&ctx->stat_sp_poll), read_stat(&ctx->stat_sp_empty), + read_stat(&ctx->stat_sp_total), + read_stat(&ctx->stat_tx_poll), read_stat(&ctx->stat_tx_empty), + read_stat(&ctx->stat_tx_total), read_stat(&ctx->stat_cyc_db), read_stat(&ctx->stat_cyc_qm), - read_stat(&ctx->stat_cyc_rx), read_stat(&ctx->stat_cyc_qs)); + read_stat(&ctx->stat_cyc_rx), read_stat(&ctx->stat_cyc_qs), + read_stat(&ctx->stat_cyc_sp), read_stat(&ctx->stat_cyc_tx)); } } #endif @@ -371,7 +387,7 @@ static unsigned poll_queues(struct dataplane_context *ctx, uint32_t ts) STATS_ADD(ctx, qs_total, total); if (total == 0) - STATS_ADD(ctx, qs_empty, total); + STATS_ADD(ctx, qs_empty, 1); return total; } @@ -405,6 +421,10 @@ static unsigned poll_kernel(struct dataplane_context *ctx, uint32_t ts) /* apply buffer reservations */ bufcache_alloc(ctx, k); + STATS_ADD(ctx, sp_total, total); + if (total == 0) + STATS_ADD(ctx, sp_empty, 1); + return total; } @@ -551,6 +571,8 @@ static inline void tx_flush(struct dataplane_context *ctx) return; } + STATS_TSADD(ctx, tx_poll, 1); + /* try to send out packets */ ret = network_send(&ctx->net, ctx->tx_num, ctx->tx_handles); @@ -564,6 +586,10 @@ static inline void tx_flush(struct dataplane_context *ctx) } ctx->tx_num -= ret; } + + STATS_TSADD(ctx, tx_total, ret); + if (ret == 0) + STATS_TSADD(ctx, tx_empty, 1); } static void poll_scale(struct dataplane_context *ctx) diff --git a/tas/include/fastpath.h b/tas/include/fastpath.h index b2f9f21f..3c31583b 100644 --- a/tas/include/fastpath.h +++ b/tas/include/fastpath.h @@ -110,10 +110,20 @@ struct dataplane_context { uint64_t stat_qs_empty; uint64_t stat_qs_total; + uint64_t stat_sp_poll; + uint64_t stat_sp_empty; + uint64_t stat_sp_total; + + uint64_t stat_tx_poll; + uint64_t stat_tx_empty; + uint64_t stat_tx_total; + uint64_t stat_cyc_db; uint64_t stat_cyc_qm; uint64_t stat_cyc_rx; uint64_t stat_cyc_qs; + uint64_t stat_cyc_sp; + uint64_t stat_cyc_tx; #endif }; diff --git a/tas/slow/kernel.c b/tas/slow/kernel.c index 4aa18539..23f718d0 100644 --- a/tas/slow/kernel.c +++ b/tas/slow/kernel.c @@ -37,6 +37,9 @@ static void timeout_trigger(struct timeout *to, uint8_t type, void *opaque); static void signal_tas_ready(void); void flexnic_loadmon(uint32_t cur_ts); +#ifdef DATAPLANE_STATS +extern void dataplane_dump_stats(void); +#endif struct timeout_manager timeout_mgr; static int exited = 0; @@ -189,6 +192,9 @@ int slowpath_main(void) PRIu64"\n", kstats.drops, kstats.kernel_rexmit, kstats.ecn_marked, kstats.acks); fflush(stdout); +#ifdef DATAPLANE_STATS + dataplane_dump_stats(); +#endif } last_print = cur_ts; } From 0f253046d05192e20ad91d73aba24ecc775b3477 Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Mon, 11 Nov 2019 13:31:56 -0600 Subject: [PATCH 04/18] Profile connection state machine Signed-off-by: Rajath Shashidhara --- Makefile | 2 +- include/kernel_appif.h | 14 ++++++++------ include/tas_memif.h | 6 ++++-- lib/sockets/context.c | 34 ++++++++++++++++++++++++++++++++++ lib/sockets/control.c | 3 +++ lib/sockets/internal.h | 1 + lib/tas/conn.c | 1 + lib/tas/include/tas_ll.h | 15 +++++++++++++++ lib/tas/init.c | 17 +++++++++++++++++ tas/fast/fast_kernel.c | 8 ++++++++ tas/include/fastpath.h | 3 +++ tas/slow/appif_ctx.c | 24 ++++++++++++++++++++++++ tas/slow/internal.h | 10 ++++++++++ tas/slow/kernel.c | 5 +++++ tas/slow/nicif.c | 11 +++++++++++ tas/slow/tcp.c | 10 +++++++--- 16 files changed, 152 insertions(+), 12 deletions(-) diff --git a/Makefile b/Makefile index c8109fa8..6c687e59 100644 --- a/Makefile +++ b/Makefile @@ -15,7 +15,7 @@ DPDK_PMDS ?= ixgbe i40e tap virtio CFLAGS+= -I$(RTE_SDK)/include -I$(RTE_SDK)/include/dpdk CFLAGS+= -I$(RTE_SDK)/include/x86_64-linux-gnu/dpdk/ -CFLAGS+= -DDATAPLANE_STATS +CFLAGS+= -DDATAPLANE_STATS -DCONNECTION_STATS -DAPPQUEUE_STATS LDFLAGS+= -L$(RTE_SDK)/lib/ LIBS_DPDK= -Wl,--whole-archive diff --git a/include/kernel_appif.h b/include/kernel_appif.h index d0cda586..3e18b937 100644 --- a/include/kernel_appif.h +++ b/include/kernel_appif.h @@ -129,6 +129,7 @@ struct kernel_appout_req_scale { /** Common struct for events on kernel -> app queue */ struct kernel_appout { + uint64_t ts; union { struct kernel_appout_conn_open conn_open; struct kernel_appout_conn_close conn_close; @@ -140,7 +141,7 @@ struct kernel_appout { struct kernel_appout_req_scale req_scale; - uint8_t raw[63]; + uint8_t raw[64 - sizeof(uint64_t) - sizeof(uint8_t)]; } __attribute__((packed)) data; uint8_t type; } __attribute__((packed)); @@ -172,8 +173,8 @@ struct kernel_appin_status { /** New connection opened */ struct kernel_appin_conn_opened { uint64_t opaque; - uint64_t rx_off; - uint64_t tx_off; + uint32_t rx_off; + uint32_t tx_off; uint32_t rx_len; uint32_t tx_len; int32_t status; @@ -195,8 +196,8 @@ struct kernel_appin_listen_newconn { /** Accepted connection on listener */ struct kernel_appin_accept_conn { uint64_t opaque; - uint64_t rx_off; - uint64_t tx_off; + uint32_t rx_off; + uint32_t tx_off; uint32_t rx_len; uint32_t tx_len; int32_t status; @@ -211,12 +212,13 @@ struct kernel_appin_accept_conn { /** Common struct for events on app -> kernel queue */ struct kernel_appin { + uint64_t ts; union { struct kernel_appin_status status; struct kernel_appin_conn_opened conn_opened; struct kernel_appin_listen_newconn listen_newconn; struct kernel_appin_accept_conn accept_connection; - uint8_t raw[63]; + uint8_t raw[64 - sizeof(uint64_t) - sizeof(uint8_t)]; } __attribute__((packed)) data; uint8_t type; } __attribute__((packed)); diff --git a/include/tas_memif.h b/include/tas_memif.h index caed5a8f..8fbff3c4 100644 --- a/include/tas_memif.h +++ b/include/tas_memif.h @@ -74,13 +74,14 @@ struct flexnic_info { /** Kernel RX queue entry */ struct flextcp_pl_krx { uint64_t addr; + uint64_t ts; union { struct { uint16_t len; uint16_t fn_core; uint16_t flow_group; } packet; - uint8_t raw[55]; + uint8_t raw[64 - sizeof(uint8_t) - sizeof(uint64_t) - sizeof(uint64_t)]; } __attribute__((packed)) msg; volatile uint8_t type; } __attribute__((packed)); @@ -106,8 +107,9 @@ struct flextcp_pl_ktx { struct { uint32_t flow_id; } connretran; - uint8_t raw[63]; + uint8_t raw[64 - sizeof(uint8_t) - sizeof(uint64_t)]; } __attribute__((packed)) msg; + uint64_t ts; volatile uint8_t type; } __attribute__((packed)); diff --git a/lib/sockets/context.c b/lib/sockets/context.c index 6bca2e1e..639b5e66 100644 --- a/lib/sockets/context.c +++ b/lib/sockets/context.c @@ -145,6 +145,23 @@ int flextcp_sockctx_poll(struct flextcp_context *ctx) } } +#ifdef TCP_CONNECTION_STATS + /* Report the stats roughly every 1s on a 2GHz processor*/ + uint64_t now = util_rdtsc(); + if (now - ctx->stats_last_ts > 2000000000ull) + { + fprintf(stderr, "[STATS] connect() cycles=%lu count=%lu\n", + ctx->connect_cycles, ctx->connect_count); + fprintf(stderr, "[STATS] listen() cycles=%lu count=%lu\n", + ctx->listen_cycles, ctx->listen_count); + fprintf(stderr, "[STATS] accept() cycles=%lu count=%lu\n", + ctx->accept_cycles, ctx->accept_count); + fprintf(stderr, "[STATS] close() cycles=%lu count=%lu\n", + ctx->close_cycles, ctx->close_count); + ctx->stats_last_ts = now; + } +#endif + return num; } @@ -174,6 +191,10 @@ static inline void ev_listen_open(struct flextcp_context *ctx, assert(s->data.listener.status == SOL_OPENING); if (ev->ev.listen_open.status == 0) { s->data.listener.status = SOL_OPEN; +#ifdef CONNECTION_STATS + ctx->listen_cycles += util_rdtsc() - s->ts; + ctx->listen_count += 1; +#endif } else { s->data.listener.status = SOL_FAILED; } @@ -214,6 +235,10 @@ static inline void ev_listen_accept(struct flextcp_context *ctx, if (ev->ev.listen_accept.status == 0) { s->data.connection.status = SOC_CONNECTED; flextcp_epoll_set(s, EPOLLOUT); +#ifdef CONNECTION_STATS + ctx->accept_cycles += (util_rdtsc() - s->ts); + ctx->accept_count += 1; +#endif } else { s->data.connection.status = SOC_FAILED; flextcp_epoll_set(s, EPOLLERR); @@ -237,6 +262,10 @@ static inline void ev_conn_open(struct flextcp_context *ctx, if (ev->ev.conn_open.status == 0) { s->data.connection.status = SOC_CONNECTED; flextcp_epoll_set(s, EPOLLOUT); +#ifdef CONNECTION_STATS + ctx->connect_cycles += util_rdtsc() - s->ts; + ctx->connect_count += 1; +#endif } else { s->data.connection.status = SOC_FAILED; flextcp_epoll_set(s, EPOLLERR); @@ -427,5 +456,10 @@ static inline void ev_conn_closed(struct flextcp_context *ctx, assert(s->type == SOCK_CONNECTION); assert(s->data.connection.status == SOC_CLOSED); +#ifdef CONNECTION_STATS + ctx->close_cycles += (util_rdtsc() - s->ts); + ctx->close_count += 1; +#endif + free(s); } diff --git a/lib/sockets/control.c b/lib/sockets/control.c index d7289674..083327ed 100644 --- a/lib/sockets/control.c +++ b/lib/sockets/control.c @@ -269,6 +269,7 @@ int tas_connect(int sockfd, const struct sockaddr *addr, socklen_t addrlen) /* open flextcp connection */ ctx = flextcp_sockctx_get(); + s->ts = util_rdtsc(); if (flextcp_connection_open(ctx, &s->data.connection.c, ntohl(sin->sin_addr.s_addr), ntohs(sin->sin_port))) { @@ -350,6 +351,7 @@ int tas_listen(int sockfd, int backlog) /* open flextcp listener */ ctx = flextcp_sockctx_get(); + s->ts = util_rdtsc(); if (flextcp_listen_open(ctx, &s->data.listener.l, ntohs(s->addr.sin_port), backlog, flags)) { @@ -452,6 +454,7 @@ int tas_accept4(int sockfd, struct sockaddr *addr, socklen_t *addrlen, sp->next = NULL; /* send accept request to kernel */ + ns->ts = util_rdtsc(); if (flextcp_listen_accept(ctx, &s->data.listener.l, &ns->data.connection.c) != 0) { diff --git a/lib/sockets/internal.h b/lib/sockets/internal.h index 1415e202..7b22197d 100644 --- a/lib/sockets/internal.h +++ b/lib/sockets/internal.h @@ -97,6 +97,7 @@ struct socket { struct socket_conn connection; struct socket_listen listener; } data; + uint64_t ts; struct sockaddr_in addr; uint8_t flags; uint8_t type; diff --git a/lib/tas/conn.c b/lib/tas/conn.c index 044c4677..f9c25038 100644 --- a/lib/tas/conn.c +++ b/lib/tas/conn.c @@ -145,6 +145,7 @@ int flextcp_connection_open(struct flextcp_context *ctx, kin->data.conn_open.flags = f; MEM_BARRIER(); kin->type = KERNEL_APPOUT_CONN_OPEN; + kin->ts = util_rdtsc(); flextcp_kernel_kick(); pos = pos + 1; diff --git a/lib/tas/include/tas_ll.h b/lib/tas/include/tas_ll.h index b181593a..c93bb851 100644 --- a/lib/tas/include/tas_ll.h +++ b/lib/tas/include/tas_ll.h @@ -45,6 +45,21 @@ * - notification queue pair to flexnic */ struct flextcp_context { +#ifdef CONNECTION_STATS + uint64_t connect_cycles; + uint64_t connect_count; + + uint64_t listen_cycles; + uint64_t listen_count; + + uint64_t accept_cycles; + uint64_t accept_count; + + uint64_t close_cycles; + uint64_t close_count; + + uint64_t stats_last_ts; +#endif /* incoming queue from the kernel */ void *kin_base; uint32_t kin_len; diff --git a/lib/tas/init.c b/lib/tas/init.c index bda211f8..c332c980 100644 --- a/lib/tas/init.c +++ b/lib/tas/init.c @@ -147,6 +147,16 @@ int flextcp_context_create(struct flextcp_context *ctx) #include int debug_flextcp_on = 0; +#ifdef APPQUEUE_STATS +static uint64_t stats_appout_cycles = 0; +static uint64_t stats_appout_count = 0; + +void appqueue_stats_dump() +{ + fprintf(stderr, "appqout stats: cyc=%lu count=%lu\n", + stats_appout_cycles, stats_appout_count); +} +#endif static int kernel_poll(struct flextcp_context *ctx, int num, struct flextcp_event *events, int *used) @@ -164,6 +174,13 @@ static int kernel_poll(struct flextcp_context *ctx, int num, type = kout->type; MEM_BARRIER(); +#ifdef APPQUEUE_STATS + if (type != KERNEL_APPIN_INVALID) + { + stats_appout_cycles += (util_rdtsc() - kout->ts); + stats_appout_count += 1; + } +#endif if (type == KERNEL_APPIN_INVALID) { break; diff --git a/tas/fast/fast_kernel.c b/tas/fast/fast_kernel.c index 2c11926f..26ee1024 100644 --- a/tas/fast/fast_kernel.c +++ b/tas/fast/fast_kernel.c @@ -52,6 +52,13 @@ int fast_kernel_poll(struct dataplane_context *ctx, return -1; ktx = dma_pointer(kctx->tx_base + kctx->tx_head, sizeof(*ktx)); +#ifdef CONNECTION_STATS + if (ktx->type != 0) + { + ctx->stat_kin_cycles += (util_rdtsc() - ktx->ts); + ctx->stat_kin_count += 1; + } +#endif if (ktx->type == 0) { return -1; @@ -153,6 +160,7 @@ void fast_kernel_packet(struct dataplane_context *ctx, krx->msg.packet.fn_core = ctx->id; MEM_BARRIER(); + krx->ts = util_rdtsc(); /* krx queue header */ krx->type = FLEXTCP_PL_KRX_PACKET; fast_kernel_kick(); diff --git a/tas/include/fastpath.h b/tas/include/fastpath.h index 3c31583b..510dbcee 100644 --- a/tas/include/fastpath.h +++ b/tas/include/fastpath.h @@ -124,6 +124,9 @@ struct dataplane_context { uint64_t stat_cyc_qs; uint64_t stat_cyc_sp; uint64_t stat_cyc_tx; + + uint64_t stat_kin_cycles; + uint64_t stat_kin_count; #endif }; diff --git a/tas/slow/appif_ctx.c b/tas/slow/appif_ctx.c index 2a827bee..7b1843d7 100644 --- a/tas/slow/appif_ctx.c +++ b/tas/slow/appif_ctx.c @@ -48,6 +48,17 @@ static int kin_accept_conn(struct application *app, struct app_context *ctx, static int kin_req_scale(struct application *app, struct app_context *ctx, volatile struct kernel_appout *kin, volatile struct kernel_appin *kout); +#ifdef APPQUEUE_STATS +static uint64_t stats_appin_cycles = 0; +static uint64_t stats_appin_count = 0; + +void appqueue_stats_dump() +{ + fprintf(stderr, "appqin stats: cyc=%lu count=%lu\n", + stats_appin_cycles, stats_appin_count); +} +#endif + static void appif_ctx_kick(struct app_context *ctx) { assert(ctx->evfd != 0); @@ -98,6 +109,7 @@ void appif_conn_opened(struct connection *c, int status) } MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_CONN_OPENED; appif_ctx_kick(ctx); @@ -128,6 +140,7 @@ void appif_conn_closed(struct connection *c, int status) kout->data.status.status = status; MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_STATUS_CONN_CLOSE; appif_ctx_kick(ctx); @@ -170,6 +183,7 @@ void appif_listen_newconn(struct listener *l, uint32_t remote_ip, kout->data.listen_newconn.remote_ip = remote_ip; kout->data.listen_newconn.remote_port = remote_port; MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_LISTEN_NEWCONN; appif_ctx_kick(ctx); @@ -219,6 +233,7 @@ void appif_accept_conn(struct connection *c, int status) } MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_ACCEPTED_CONN; appif_ctx_kick(ctx); @@ -250,6 +265,14 @@ unsigned appif_ctx_poll(struct application *app, struct app_context *ctx) type = kin->type; MEM_BARRIER(); +#ifdef APPQUEUE_STATS + if (type != KERNEL_APPOUT_INVALID) + { + stats_appin_cycles += (util_rdtsc() - kin->ts); + stats_appin_count += 1; + } +#endif + switch (type) { case KERNEL_APPOUT_INVALID: /* nothing yet */ @@ -303,6 +326,7 @@ unsigned appif_ctx_poll(struct application *app, struct app_context *ctx) /* update kout queue position if the entry was used */ if (kout_inc > 0) { + kout->ts = util_rdtsc(); kout_pos += kout_inc; if (kout_pos >= ctx->kout_len) { kout_pos = 0; diff --git a/tas/slow/internal.h b/tas/slow/internal.h index 2721a088..69ab9d4d 100644 --- a/tas/slow/internal.h +++ b/tas/slow/internal.h @@ -541,6 +541,16 @@ struct connection { uint32_t flags; /** Flow group (RSS bucket for steering). */ uint16_t flow_group; + + /** + * @name Stats + * @{ + */ + /** Timestamps at various connection states */ + uint64_t state_ts[8]; + uint16_t arp_immediate: 1; + uint16_t padding: 15; + /**@}*/ }; /** TCP listener */ diff --git a/tas/slow/kernel.c b/tas/slow/kernel.c index 23f718d0..8ec37da3 100644 --- a/tas/slow/kernel.c +++ b/tas/slow/kernel.c @@ -41,6 +41,11 @@ void flexnic_loadmon(uint32_t cur_ts); extern void dataplane_dump_stats(void); #endif +#ifdef CONNECTION_STATS +uint64_t stats_kout_cycles = 0; +uint64_t stats_kout_count = 0; +#endif + struct timeout_manager timeout_mgr; static int exited = 0; struct kernel_statistics kstats; diff --git a/tas/slow/nicif.c b/tas/slow/nicif.c index 5e62db4e..3b4f6e06 100644 --- a/tas/slow/nicif.c +++ b/tas/slow/nicif.c @@ -82,6 +82,11 @@ static volatile struct flextcp_pl_ktx **txq_base; static uint32_t txq_len; static uint32_t *txq_tail; +#ifdef CONNECTION_STATS +extern uint64_t stats_kout_cycles; +extern uint64_t stats_kout_count; +#endif + int nicif_init(void) { rte_hash_crc_init_alg(); @@ -341,6 +346,7 @@ int nicif_connection_retransmit(uint32_t f_id, uint16_t flow_group) ktx->msg.connretran.flow_id = f_id; MEM_BARRIER(); + ktx->ts = util_rdtsc(); ktx->type = FLEXTCP_PL_KTX_CONNRETRAN; util_flexnic_kick(&fp_state->kctx[core], util_timeout_time_us()); @@ -371,6 +377,7 @@ void nicif_tx_send(uint32_t opaque, int no_ts) volatile struct flextcp_pl_ktx *ktx = &txq_base[0][tail]; MEM_BARRIER(); + ktx->ts = util_rdtsc(); ktx->type = (!no_ts ? FLEXTCP_PL_KTX_PACKET : FLEXTCP_PL_KTX_PACKET_NOTS); txq_tail[0] = opaque; @@ -501,6 +508,10 @@ static inline int rxq_poll(void) if (type == FLEXTCP_PL_KRX_INVALID) { return -1; } +#ifdef CONNECTION_STATS + stats_kout_cycles += (util_rdtsc() - krx->ts); + stats_kout_count += 1; +#endif /* update tail */ tail = tail + 1; diff --git a/tas/slow/tcp.c b/tas/slow/tcp.c index 54e58174..20b3a246 100644 --- a/tas/slow/tcp.c +++ b/tas/slow/tcp.c @@ -149,6 +149,7 @@ int tcp_open(struct app_context *ctx, uint64_t opaque, uint32_t remote_ip, int ret; struct connection *conn; uint16_t local_port; + uint64_t ts = util_rdtsc(); /* allocate connection struct */ if ((conn = conn_alloc()) == NULL) { @@ -183,6 +184,8 @@ int tcp_open(struct app_context *ctx, uint64_t opaque, uint32_t remote_ip, conn->comp.notify_fd = -1; conn->comp.status = 0; + conn->state_ts[CONN_ARP_PENDING] = ts; + /* resolve IP to mac */ ret = routing_resolve(&conn->comp, remote_ip, &conn->remote_mac); @@ -194,6 +197,7 @@ int tcp_open(struct app_context *ctx, uint64_t opaque, uint32_t remote_ip, CONN_DEBUG0(conn, "routing_resolve succeeded immediately\n"); conn_register(conn); + conn->arp_immediate = 1; ret = conn_arp_done(conn); } else { CONN_DEBUG0(conn, "routing_resolve pending\n"); @@ -517,7 +521,7 @@ static void conn_packet(struct connection *c, const struct pkt_tcp *p, static int conn_arp_done(struct connection *conn) { CONN_DEBUG0(conn, "arp resolution done\n"); - + conn->state_ts[CONN_SYN_SENT] = util_rdtsc(); conn->status = CONN_SYN_SENT; /* arm timeout */ @@ -579,7 +583,6 @@ static int conn_syn_sent_packet(struct connection *c, const struct pkt_tcp *p, } CONN_DEBUG0(c, "conn_syn_sent_packet: connection registered\n"); - c->status = CONN_OPEN; /* send ACK */ @@ -589,6 +592,7 @@ static int conn_syn_sent_packet(struct connection *c, const struct pkt_tcp *p, appif_conn_opened(c, 0); + c->state_ts[CONN_OPEN] = util_rdtsc(); return 0; } @@ -606,7 +610,7 @@ static int conn_reg_synack(struct connection *c) send_control(c, TCP_SYN | TCP_ACK | ecn_flags, 1, c->syn_ts, TCP_MSS); appif_accept_conn(c, 0); - + c->state_ts[CONN_OPEN] = util_rdtsc(); return 0; } From e28b858f5d7f5c391f8154404dfa58de805d8e16 Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Mon, 11 Nov 2019 15:49:04 -0600 Subject: [PATCH 05/18] Use CONNECTION_STATS macro instead of TCP_CONNECTION_STATS to dump stats in lib Signed-off-by: Rajath Shashidhara --- lib/sockets/context.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/sockets/context.c b/lib/sockets/context.c index 639b5e66..2b3b9fa2 100644 --- a/lib/sockets/context.c +++ b/lib/sockets/context.c @@ -145,7 +145,7 @@ int flextcp_sockctx_poll(struct flextcp_context *ctx) } } -#ifdef TCP_CONNECTION_STATS +#ifdef CONNECTION_STATS /* Report the stats roughly every 1s on a 2GHz processor*/ uint64_t now = util_rdtsc(); if (now - ctx->stats_last_ts > 2000000000ull) From 7d1a276652716eb51baa9a4f5e5c6396bfe07b44 Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Mon, 11 Nov 2019 18:50:23 -0600 Subject: [PATCH 06/18] Migrate to a revamped stats framework Signed-off-by: Rajath Shashidhara --- Makefile | 2 +- tas/fast/fast_kernel.c | 2 +- tas/fast/fastemu.c | 92 +++++++++++++---------------- tas/include/fastpath.h | 34 +---------- tas/include/stats.h | 129 +++++++++++++++++++++++++++++++++++++++++ tas/slow/kernel.c | 74 ++++++++++++++++++++++- tas/slow/nicif.c | 4 +- 7 files changed, 249 insertions(+), 88 deletions(-) create mode 100644 tas/include/stats.h diff --git a/Makefile b/Makefile index 6c687e59..3082b7c7 100644 --- a/Makefile +++ b/Makefile @@ -15,7 +15,7 @@ DPDK_PMDS ?= ixgbe i40e tap virtio CFLAGS+= -I$(RTE_SDK)/include -I$(RTE_SDK)/include/dpdk CFLAGS+= -I$(RTE_SDK)/include/x86_64-linux-gnu/dpdk/ -CFLAGS+= -DDATAPLANE_STATS -DCONNECTION_STATS -DAPPQUEUE_STATS +CFLAGS+= -DCONNECTION_STATS -DPROFILING LDFLAGS+= -L$(RTE_SDK)/lib/ LIBS_DPDK= -Wl,--whole-archive diff --git a/tas/fast/fast_kernel.c b/tas/fast/fast_kernel.c index 26ee1024..b570d78d 100644 --- a/tas/fast/fast_kernel.c +++ b/tas/fast/fast_kernel.c @@ -52,7 +52,7 @@ int fast_kernel_poll(struct dataplane_context *ctx, return -1; ktx = dma_pointer(kctx->tx_base + kctx->tx_head, sizeof(*ktx)); -#ifdef CONNECTION_STATS +#ifdef APPQUEUE_STATS if (ktx->type != 0) { ctx->stat_kin_cycles += (util_rdtsc() - ktx->ts); diff --git a/tas/fast/fastemu.c b/tas/fast/fastemu.c index 7bf6d3e7..570f5d42 100644 --- a/tas/fast/fastemu.c +++ b/tas/fast/fastemu.c @@ -37,23 +37,6 @@ #include "internal.h" #include "fastemu.h" -#define DATAPLANE_TSCS - -#ifdef DATAPLANE_STATS -# ifdef DATAPLANE_TSCS -# define STATS_TS(n) uint64_t n = rte_get_tsc_cycles() -# define STATS_TSADD(c, f, n) __sync_fetch_and_add(&c->stat_##f, n) -# else -# define STATS_TS(n) do { } while (0) -# define STATS_TSADD(c, f, n) do { } while (0) -# endif -# define STATS_ADD(c, f, n) __sync_fetch_and_add(&c->stat_##f, n) -#else -# define STATS_TS(n) do { } while (0) -# define STATS_TSADD(c, f, n) do { } while (0) -# define STATS_ADD(c, f, n) do { } while (0) -#endif - static unsigned poll_rx(struct dataplane_context *ctx, uint32_t ts) __attribute__((noinline)); static unsigned poll_queues(struct dataplane_context *ctx, uint32_t ts) __attribute__((noinline)); @@ -163,25 +146,25 @@ void dataplane_loop(struct dataplane_context *ctx) STATS_TS(rx); tx_flush(ctx); STATS_TS(acktx); - STATS_TSADD(ctx, cyc_tx, acktx - rx); + STATS_ATOMIC_ADD(ctx, cyc_tx, acktx - rx); n += poll_qman_fwd(ctx, ts); - STATS_TSADD(ctx, cyc_rx, rx - start); + STATS_ATOMIC_ADD(ctx, cyc_rx, rx - start); n += poll_qman(ctx, ts); STATS_TS(qm); - STATS_TSADD(ctx, cyc_qm, qm - rx); + STATS_ATOMIC_ADD(ctx, cyc_qm, qm - rx); n += poll_queues(ctx, ts); STATS_TS(qs); - STATS_TSADD(ctx, cyc_qs, qs - qm); + STATS_ATOMIC_ADD(ctx, cyc_qs, qs - qm); n += poll_kernel(ctx, ts); STATS_TS(sp); - STATS_TSADD(ctx, cyc_sp, sp - qs); + STATS_ATOMIC_ADD(ctx, cyc_sp, sp - qs); /* flush transmit buffer */ tx_flush(ctx); STATS_TS(tx); - STATS_TSADD(ctx, cyc_tx, tx - sp); + STATS_ATOMIC_ADD(ctx, cyc_tx, tx - sp); if (ctx->id == 0) poll_scale(ctx); @@ -232,11 +215,6 @@ void dataplane_loop(struct dataplane_context *ctx) } #ifdef DATAPLANE_STATS -static inline uint64_t read_stat(uint64_t *p) -{ - return __sync_lock_test_and_set(p, 0); -} - void dataplane_dump_stats(void) { struct dataplane_context *ctx; @@ -247,28 +225,40 @@ void dataplane_dump_stats(void) if (ctx == NULL) continue; - fprintf(stderr, "dp stats %u: " - "qm=(%"PRIu64",%"PRIu64",%"PRIu64") " - "rx=(%"PRIu64",%"PRIu64",%"PRIu64") " - "qs=(%"PRIu64",%"PRIu64",%"PRIu64") " - "sp=(%"PRIu64",%"PRIu64",%"PRIu64") " - "tx=(%"PRIu64",%"PRIu64",%"PRIu64") " - "cyc=(%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64")\n", i, - read_stat(&ctx->stat_qm_poll), read_stat(&ctx->stat_qm_empty), - read_stat(&ctx->stat_qm_total), - read_stat(&ctx->stat_rx_poll), read_stat(&ctx->stat_rx_empty), - read_stat(&ctx->stat_rx_total), - read_stat(&ctx->stat_qs_poll), read_stat(&ctx->stat_qs_empty), - read_stat(&ctx->stat_qs_total), - read_stat(&ctx->stat_sp_poll), read_stat(&ctx->stat_sp_empty), - read_stat(&ctx->stat_sp_total), - read_stat(&ctx->stat_tx_poll), read_stat(&ctx->stat_tx_empty), - read_stat(&ctx->stat_tx_total), - read_stat(&ctx->stat_cyc_db), read_stat(&ctx->stat_cyc_qm), - read_stat(&ctx->stat_cyc_rx), read_stat(&ctx->stat_cyc_qs), - read_stat(&ctx->stat_cyc_sp), read_stat(&ctx->stat_cyc_tx)); + TAS_LOG(INFO, MAIN, "DP [%u]> (POLL, EMPTY, TOTAL)", i); + TAS_LOG(INFO, MAIN, "qm=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_ATOMIC_FETCH(ctx, qm_poll), + STATS_ATOMIC_FETCH(ctx, qm_empty), + STATS_ATOMIC_FETCH(ctx, qm_total)); + TAS_LOG(INFO, MAIN, "rx=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_ATOMIC_FETCH(ctx, rx_poll), + STATS_ATOMIC_FETCH(ctx, rx_empty), + STATS_ATOMIC_FETCH(ctx, rx_total)); + TAS_LOG(INFO, MAIN, "qs=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_ATOMIC_FETCH(ctx, qs_poll), + STATS_ATOMIC_FETCH(ctx, qs_empty), + STATS_ATOMIC_FETCH(ctx, qs_total)); + TAS_LOG(INFO, MAIN, "sp=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_ATOMIC_FETCH(ctx, sp_poll), + STATS_ATOMIC_FETCH(ctx, sp_empty), + STATS_ATOMIC_FETCH(ctx, sp_total)); + TAS_LOG(INFO, MAIN, "tx=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_ATOMIC_FETCH(ctx, tx_poll), + STATS_ATOMIC_FETCH(ctx, tx_empty), + STATS_ATOMIC_FETCH(ctx, tx_total)); + TAS_LOG(INFO, MAIN, "cyc=(%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_ATOMIC_FETCH(ctx, cyc_qm), + STATS_ATOMIC_FETCH(ctx, cyc_rx), + STATS_ATOMIC_FETCH(ctx, cyc_qs), + STATS_ATOMIC_FETCH(ctx, cyc_sp), + STATS_ATOMIC_FETCH(ctx, cyc_tx)); } } +#else +void dataplane_dump_stats(void) +{ + return; +} #endif static unsigned poll_rx(struct dataplane_context *ctx, uint32_t ts) @@ -571,7 +561,7 @@ static inline void tx_flush(struct dataplane_context *ctx) return; } - STATS_TSADD(ctx, tx_poll, 1); + STATS_ATOMIC_ADD(ctx, tx_poll, 1); /* try to send out packets */ ret = network_send(&ctx->net, ctx->tx_num, ctx->tx_handles); @@ -587,9 +577,9 @@ static inline void tx_flush(struct dataplane_context *ctx) ctx->tx_num -= ret; } - STATS_TSADD(ctx, tx_total, ret); + STATS_ATOMIC_ADD(ctx, tx_total, ret); if (ret == 0) - STATS_TSADD(ctx, tx_empty, 1); + STATS_ATOMIC_ADD(ctx, tx_empty, 1); } static void poll_scale(struct dataplane_context *ctx) diff --git a/tas/include/fastpath.h b/tas/include/fastpath.h index 510dbcee..d1161400 100644 --- a/tas/include/fastpath.h +++ b/tas/include/fastpath.h @@ -32,6 +32,7 @@ #include #include +#include #define BATCH_SIZE 16 #define BUFCACHE_SIZE 128 @@ -95,39 +96,10 @@ struct dataplane_context { uint64_t loadmon_cyc_busy; uint64_t kernel_drop; -#ifdef DATAPLANE_STATS + /********************************************************/ /* Stats */ - uint64_t stat_qm_poll; - uint64_t stat_qm_empty; - uint64_t stat_qm_total; - - uint64_t stat_rx_poll; - uint64_t stat_rx_empty; - uint64_t stat_rx_total; - - uint64_t stat_qs_poll; - uint64_t stat_qs_empty; - uint64_t stat_qs_total; - - uint64_t stat_sp_poll; - uint64_t stat_sp_empty; - uint64_t stat_sp_total; - - uint64_t stat_tx_poll; - uint64_t stat_tx_empty; - uint64_t stat_tx_total; - - uint64_t stat_cyc_db; - uint64_t stat_cyc_qm; - uint64_t stat_cyc_rx; - uint64_t stat_cyc_qs; - uint64_t stat_cyc_sp; - uint64_t stat_cyc_tx; - - uint64_t stat_kin_cycles; - uint64_t stat_kin_count; -#endif + struct dataplane_stats stats; }; extern struct dataplane_context **ctxs; diff --git a/tas/include/stats.h b/tas/include/stats.h new file mode 100644 index 00000000..56fb23e4 --- /dev/null +++ b/tas/include/stats.h @@ -0,0 +1,129 @@ +#ifndef TASSTATS_H_ +#define TASSTATS_H_ + +#include + + +#ifdef PROFILING +#define DATAPLANE_STATS 1 +#define CONTROLPLANE_STATS 1 +#endif + +#ifdef DATAPLANE_STATS + +#define STATS_TS(n) uint64_t n = rte_get_tsc_cycles() +#define STATS_ATOMIC_ADD(c, f, n) __sync_fetch_and_add(&c->stats.stat_##f, n) +#define STATS_ADD(c, f, n) (c->stats.stat_##f += n) + +#define STATS_ATOMIC_FETCHRESET(c, f) (__sync_lock_test_and_set(&c->stats.stat_##f, 0)) +#define STATS_ATOMIC_FETCH(c, f) STATS_ATOMIC_ADD(c, f, 0) +#define STATS_FETCH(c, f) (&c->stats.stat_##f) + +#else + +#define STATS_TS(n) do { } while (0) +#define STATS_ATOMIC_ADD(c, f, n) do { } while (0) +#define STATS_ADD(c, f, n) do { } while (0) + +#define STATS_ATOMIC_FETCHRESET(c, f) (0) +#define STATS_ATOMIC_FETCH(c, f) (0) +#define STATS_FETCH(c, f) (0) + +#endif + +struct dataplane_stats +{ +#ifdef DATAPLANE_STATS + /* Fastpath Stats + * Poll: # of polls + * Empty: # of empty polls + * Total: # of events processed + */ + + /* Queue Manager */ + uint64_t stat_qm_poll; + uint64_t stat_qm_empty; + uint64_t stat_qm_total; + + /* NIC RX/TX */ + uint64_t stat_rx_poll; + uint64_t stat_rx_empty; + uint64_t stat_rx_total; + uint64_t stat_tx_poll; + uint64_t stat_tx_empty; + uint64_t stat_tx_total; + + /* Application Queue */ + uint64_t stat_qs_poll; + uint64_t stat_qs_empty; + uint64_t stat_qs_total; + + /* Slow Path */ + uint64_t stat_sp_poll; + uint64_t stat_sp_empty; + uint64_t stat_sp_total; + + /* Slow path RX queue */ + uint64_t stat_sprx_cycles; + uint64_t stat_sprx_count; + + /* Cycles consumed in processing by modules */ + uint64_t stat_cyc_qm; + uint64_t stat_cyc_rx; + uint64_t stat_cyc_qs; + uint64_t stat_cyc_sp; + uint64_t stat_cyc_tx; + +#endif +}; + +struct controlplane_stats +{ +#ifdef CONTROLPLANE_STATS + /* Fastpath Stats + * Poll: # of polls + * Empty: # of empty polls + * Total: # of events processed + */ + + /* NIC RX */ + uint64_t stat_rx_poll; + uint64_t stat_rx_idle; + uint64_t stat_rx_total; + + /* Congestion Control */ + uint64_t stat_cc_poll; + uint64_t stat_cc_idle; + uint64_t stat_cc_total; + + /* Application */ + uint64_t stat_ax_poll; + uint64_t stat_ax_idle; + uint64_t stat_ax_total; + + /* Application context */ + uint64_t stat_ac_poll; + uint64_t stat_ac_idle; + uint64_t stat_ac_total; + + /* Kernel Native Interface */ + uint64_t stat_kni_poll; + uint64_t stat_kni_idle; + uint64_t stat_kni_total; + + /* TCP States */ + uint64_t stat_tcp_poll; + uint64_t stat_tcp_idle; + uint64_t stat_tcp_total; + + /* Cycles consumed in processing by modules */ + uint64_t stat_cyc_rx; + uint64_t stat_cyc_cc; + uint64_t stat_cyc_ax; + uint64_t stat_cyc_ac; + uint64_t stat_cyc_kni; + uint64_t stat_cyc_tcp; +#endif +}; + +#endif /* TASSTATS_H_ */ diff --git a/tas/slow/kernel.c b/tas/slow/kernel.c index 8ec37da3..f0ca41a2 100644 --- a/tas/slow/kernel.c +++ b/tas/slow/kernel.c @@ -33,6 +33,8 @@ #include #include #include "internal.h" +#include +#include static void timeout_trigger(struct timeout *to, uint8_t type, void *opaque); static void signal_tas_ready(void); @@ -41,7 +43,14 @@ void flexnic_loadmon(uint32_t cur_ts); extern void dataplane_dump_stats(void); #endif -#ifdef CONNECTION_STATS +struct kernel_context +{ + struct controlplane_stats stats; +}; + +static struct kernel_context slowpath_ctx; + +#ifdef APPQUEUE_STATS uint64_t stats_kout_cycles = 0; uint64_t stats_kout_count = 0; #endif @@ -53,6 +62,52 @@ uint32_t cur_ts; static uint32_t startwait = 0; int kernel_notifyfd = 0; +#ifdef CONTROLPLANE_STATS +void controlplane_dump_stats(void) +{ + struct kernel_context *ctx = &slowpath_ctx; + TAS_LOG(INFO, MAIN, "CP [%u]> (POLL, EMPTY, TOTAL)", 0); +/* + TAS_LOG(INFO, MAIN, "rx=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_FETCH(ctx, rx_poll), + STATS_FETCH(ctx, rx_empty), + STATS_FETCH(ctx, rx_total)); + TAS_LOG(INFO, MAIN, "cc=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_FETCH(ctx, cc_poll), + STATS_FETCH(ctx, cc_empty), + STATS_FETCH(ctx, cc_total)); + TAS_LOG(INFO, MAIN, "ax=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_FETCH(ctx, ax_poll), + STATS_FETCH(ctx, ax_empty), + STATS_FETCH(ctx, ax_total)); + TAS_LOG(INFO, MAIN, "ac=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_FETCH(ctx, ac_poll), + STATS_FETCH(ctx, ac_empty), + STATS_FETCH(ctx, ac_total)); + TAS_LOG(INFO, MAIN, "kni=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_FETCH(ctx, kni_poll), + STATS_FETCH(ctx, kni_empty), + STATS_FETCH(ctx, kni_total)); + TAS_LOG(INFO, MAIN, "tcp=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_FETCH(ctx, tcp_poll), + STATS_FETCH(ctx, tcp_empty), + STATS_FETCH(ctx, tcp_total)); +*/ + TAS_LOG(INFO, MAIN, "cyc=(%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_FETCH(ctx, cyc_rx), + STATS_FETCH(ctx, cyc_cc), + STATS_FETCH(ctx, cyc_ax), + STATS_FETCH(ctx, cyc_ac), + STATS_FETCH(ctx, cyc_kni), + STATS_FETCH(ctx, cyc_tcp)); +} +#else +void controlplane_dump_stats(void) +{ + return; +} +#endif + int slowpath_main(void) { uint32_t last_print = 0; @@ -121,15 +176,29 @@ int slowpath_main(void) signal_tas_ready(); + struct kernel_context *ctx = &slowpath_ctx; + while (exited == 0) { unsigned n = 0; cur_ts = util_timeout_time_us(); + + STATS_TS(start); n += nicif_poll(); + STATS_TS(cc); + STATS_ADD(ctx, cyc_rx, cc - start); n += cc_poll(cur_ts); + STATS_TS(ax); + STATS_ADD(ctx, cyc_cc, ax - cc); n += appif_poll(); + STATS_TS(kni); + STATS_ADD(ctx, cyc_ax, kni - ax); n += kni_poll(); + STATS_TS(tcp); + STATS_ADD(ctx, cyc_kni, tcp - kni); tcp_poll(); + STATS_TS(end); + STATS_ADD(ctx, cyc_tcp, end - tcp); util_timeout_poll_ts(&timeout_mgr, cur_ts); if (config.fp_autoscale && cur_ts - loadmon_ts >= 10000) { @@ -197,8 +266,9 @@ int slowpath_main(void) PRIu64"\n", kstats.drops, kstats.kernel_rexmit, kstats.ecn_marked, kstats.acks); fflush(stdout); -#ifdef DATAPLANE_STATS +#ifdef PROFILING dataplane_dump_stats(); + controlplane_dump_stats(); #endif } last_print = cur_ts; diff --git a/tas/slow/nicif.c b/tas/slow/nicif.c index 3b4f6e06..b6ac706c 100644 --- a/tas/slow/nicif.c +++ b/tas/slow/nicif.c @@ -82,7 +82,7 @@ static volatile struct flextcp_pl_ktx **txq_base; static uint32_t txq_len; static uint32_t *txq_tail; -#ifdef CONNECTION_STATS +#ifdef APPQUEUE_STATS extern uint64_t stats_kout_cycles; extern uint64_t stats_kout_count; #endif @@ -508,7 +508,7 @@ static inline int rxq_poll(void) if (type == FLEXTCP_PL_KRX_INVALID) { return -1; } -#ifdef CONNECTION_STATS +#ifdef APPQUEUE_STATS stats_kout_cycles += (util_rdtsc() - krx->ts); stats_kout_count += 1; #endif From 314f691f767c3946ccddcc0c10558663fda99060 Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Wed, 13 Nov 2019 12:44:26 -0600 Subject: [PATCH 07/18] Improve stats loggin - Collect slowpath poll, idle and total stats - Log the queue delay stats --- Makefile | 2 +- lib/sockets/context.c | 8 ++++++++ lib/tas/init.c | 4 ++-- tas/fast/fast_kernel.c | 6 +++--- tas/fast/fastemu.c | 5 +++++ tas/include/slowpath.h | 41 +++++++++++++++++++++++++++++++++++++++++ tas/include/stats.h | 17 ++++++++++++++++- tas/slow/appif.c | 17 ++++++++++++++++- tas/slow/appif_ctx.c | 17 ++++++++--------- tas/slow/cc.c | 8 ++++++++ tas/slow/kernel.c | 29 ++++++++++++++++------------- tas/slow/nicif.c | 27 +++++++++++++++++++++------ tas/slow/tcp.c | 9 +++++++++ 13 files changed, 154 insertions(+), 36 deletions(-) create mode 100644 tas/include/slowpath.h diff --git a/Makefile b/Makefile index 3082b7c7..1565531b 100644 --- a/Makefile +++ b/Makefile @@ -15,7 +15,7 @@ DPDK_PMDS ?= ixgbe i40e tap virtio CFLAGS+= -I$(RTE_SDK)/include -I$(RTE_SDK)/include/dpdk CFLAGS+= -I$(RTE_SDK)/include/x86_64-linux-gnu/dpdk/ -CFLAGS+= -DCONNECTION_STATS -DPROFILING +CFLAGS+= -DCONNECTION_STATS -DQUEUE_STATS -DPROFILING LDFLAGS+= -L$(RTE_SDK)/lib/ LIBS_DPDK= -Wl,--whole-archive diff --git a/lib/sockets/context.c b/lib/sockets/context.c index 2b3b9fa2..88aab14a 100644 --- a/lib/sockets/context.c +++ b/lib/sockets/context.c @@ -36,6 +36,10 @@ #include "internal.h" #include "../tas/internal.h" +#ifdef QUEUE_STATS +extern void appqueue_stats_dump(); +#endif + static inline void ev_listen_open(struct flextcp_context *ctx, struct flextcp_event *ev); static inline void ev_listen_newconn(struct flextcp_context *ctx, @@ -159,6 +163,10 @@ int flextcp_sockctx_poll(struct flextcp_context *ctx) fprintf(stderr, "[STATS] close() cycles=%lu count=%lu\n", ctx->close_cycles, ctx->close_count); ctx->stats_last_ts = now; + +#ifdef QUEUE_STATS + appqueue_stats_dump(); +#endif } #endif diff --git a/lib/tas/init.c b/lib/tas/init.c index c332c980..68c0c95c 100644 --- a/lib/tas/init.c +++ b/lib/tas/init.c @@ -147,7 +147,7 @@ int flextcp_context_create(struct flextcp_context *ctx) #include int debug_flextcp_on = 0; -#ifdef APPQUEUE_STATS +#ifdef QUEUE_STATS static uint64_t stats_appout_cycles = 0; static uint64_t stats_appout_count = 0; @@ -174,7 +174,7 @@ static int kernel_poll(struct flextcp_context *ctx, int num, type = kout->type; MEM_BARRIER(); -#ifdef APPQUEUE_STATS +#ifdef QUEUE_STATS if (type != KERNEL_APPIN_INVALID) { stats_appout_cycles += (util_rdtsc() - kout->ts); diff --git a/tas/fast/fast_kernel.c b/tas/fast/fast_kernel.c index b570d78d..5b1a6050 100644 --- a/tas/fast/fast_kernel.c +++ b/tas/fast/fast_kernel.c @@ -52,11 +52,11 @@ int fast_kernel_poll(struct dataplane_context *ctx, return -1; ktx = dma_pointer(kctx->tx_base + kctx->tx_head, sizeof(*ktx)); -#ifdef APPQUEUE_STATS +#ifdef QUEUE_STATS if (ktx->type != 0) { - ctx->stat_kin_cycles += (util_rdtsc() - ktx->ts); - ctx->stat_kin_count += 1; + STATS_ATOMIC_ADD(ctx, kin_cycles, (util_rdtsc() - ktx->ts)); + STATS_ATOMIC_ADD(ctx, kin_count, 1); } #endif diff --git a/tas/fast/fastemu.c b/tas/fast/fastemu.c index 570f5d42..127d8b54 100644 --- a/tas/fast/fastemu.c +++ b/tas/fast/fastemu.c @@ -252,6 +252,11 @@ void dataplane_dump_stats(void) STATS_ATOMIC_FETCH(ctx, cyc_qs), STATS_ATOMIC_FETCH(ctx, cyc_sp), STATS_ATOMIC_FETCH(ctx, cyc_tx)); +#ifdef QUEUE_STATS + TAS_LOG(INFO, MAIN, "kin=(%"PRIu64",%"PRIu64") \n", + STATS_ATOMIC_FETCH(ctx, kin_cycles), + STATS_ATOMIC_FETCH(ctx, kin_count)); +#endif } } #else diff --git a/tas/include/slowpath.h b/tas/include/slowpath.h new file mode 100644 index 00000000..696f48d8 --- /dev/null +++ b/tas/include/slowpath.h @@ -0,0 +1,41 @@ +/* + * Copyright 2019 University of Washington, Max Planck Institute for + * Software Systems, and The University of Texas at Austin + * + * Permission is hereby granted, free of charge, to any person obtaining + * a copy of this software and associated documentation files (the + * "Software"), to deal in the Software without restriction, including + * without limitation the rights to use, copy, modify, merge, publish, + * distribute, sublicense, and/or sell copies of the Software, and to + * permit persons to whom the Software is furnished to do so, subject to + * the following conditions: + * + * The above copyright notice and this permission notice shall be + * included in all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, + * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF + * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. + * IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY + * CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, + * TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE + * SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. + */ + +#ifndef SLOWPATH_H_ +#define SLOWPATH_H_ + +#include + +struct kernel_context +{ + struct controlplane_stats stats; +}; + +extern struct kernel_context* slowpath_ctx; + +#ifdef CONTROLPLANE_STATS +void controlplane_dump_stats(void) +#endif + +#endif /* ndef SLOWPATH_H_ */ \ No newline at end of file diff --git a/tas/include/stats.h b/tas/include/stats.h index 56fb23e4..073b055f 100644 --- a/tas/include/stats.h +++ b/tas/include/stats.h @@ -3,6 +3,7 @@ #include +#define PROFILING #ifdef PROFILING #define DATAPLANE_STATS 1 @@ -17,7 +18,7 @@ #define STATS_ATOMIC_FETCHRESET(c, f) (__sync_lock_test_and_set(&c->stats.stat_##f, 0)) #define STATS_ATOMIC_FETCH(c, f) STATS_ATOMIC_ADD(c, f, 0) -#define STATS_FETCH(c, f) (&c->stats.stat_##f) +#define STATS_FETCH(c, f) (c->stats.stat_##f) #else @@ -74,6 +75,12 @@ struct dataplane_stats uint64_t stat_cyc_sp; uint64_t stat_cyc_tx; +#ifdef QUEUE_STATS + /* Kernel -> Fastpath queue delay statistics */ + uint64_t stat_kin_cycles; + uint64_t stat_kin_count; +#endif + #endif }; @@ -123,6 +130,14 @@ struct controlplane_stats uint64_t stat_cyc_ac; uint64_t stat_cyc_kni; uint64_t stat_cyc_tcp; + + /* Fastpath -> Slowpath queuing delays */ + uint64_t stat_kout_cycles; + uint64_t stat_kout_count; + + /* Lib -> Slowpath queueing delays */ + uint64_t stat_appin_cycles; + uint64_t stat_appin_count; #endif }; diff --git a/tas/slow/appif.c b/tas/slow/appif.c index 95eb53c4..68f4c9fd 100644 --- a/tas/slow/appif.c +++ b/tas/slow/appif.c @@ -60,6 +60,7 @@ #include #include #include +#include /** epoll data for listening socket */ #define EP_LISTEN (NULL) @@ -136,7 +137,10 @@ unsigned appif_poll(void) uint16_t i; uint64_t rxq_offs[tas_info->cores_num], txq_offs[tas_info->cores_num]; uint64_t cnt = 1; - unsigned n = 0; + unsigned n = 0, m = 0; + + STATS_ADD(slowpath_ctx, ax_poll, 1); + STATS_ADD(slowpath_ctx, ac_poll, 1); /* add new applications to list */ while ((p = nbqueue_deq(&ux_to_poll)) != NULL) { @@ -169,6 +173,8 @@ unsigned appif_poll(void) if (ret <= 0) { perror("appif_poll: error writing to notify fd"); } + + m += (ret > 0 ? 1 : 0); } for (ctx = app->contexts; ctx != NULL; ctx = ctx->next) { @@ -179,6 +185,15 @@ unsigned appif_poll(void) } } + if (m == 0) + STATS_ADD(slowpath_ctx, ax_idle, 1); + + if (n == 0) + STATS_ADD(slowpath_ctx, ac_idle, 1); + + STATS_ADD(slowpath_ctx, ax_total, m); + STATS_ADD(slowpath_ctx, ac_total, n); + return n; } diff --git a/tas/slow/appif_ctx.c b/tas/slow/appif_ctx.c index 7b1843d7..6ddbc170 100644 --- a/tas/slow/appif_ctx.c +++ b/tas/slow/appif_ctx.c @@ -32,6 +32,7 @@ #include #include +#include #include "internal.h" #include "appif.h" @@ -48,14 +49,12 @@ static int kin_accept_conn(struct application *app, struct app_context *ctx, static int kin_req_scale(struct application *app, struct app_context *ctx, volatile struct kernel_appout *kin, volatile struct kernel_appin *kout); -#ifdef APPQUEUE_STATS -static uint64_t stats_appin_cycles = 0; -static uint64_t stats_appin_count = 0; - +#ifdef QUEUE_STATS void appqueue_stats_dump() { - fprintf(stderr, "appqin stats: cyc=%lu count=%lu\n", - stats_appin_cycles, stats_appin_count); + TAS_LOG(INFO, MAIN, "appqin stats: cyc=%lu count=%lu\n", + STATS_FETCH(slowpath_ctx, appin_cycles), + STATS_FETCH(slowpath_ctx, appin_count)); } #endif @@ -265,11 +264,11 @@ unsigned appif_ctx_poll(struct application *app, struct app_context *ctx) type = kin->type; MEM_BARRIER(); -#ifdef APPQUEUE_STATS +#ifdef QUEUE_STATS if (type != KERNEL_APPOUT_INVALID) { - stats_appin_cycles += (util_rdtsc() - kin->ts); - stats_appin_count += 1; + STATS_ADD(slowpath_ctx, appin_cycles, (util_rdtsc() - kin->ts)); + STATS_ADD(slowpath_ctx, appin_count, 1); } #endif diff --git a/tas/slow/cc.c b/tas/slow/cc.c index 9c84b198..6c116536 100644 --- a/tas/slow/cc.c +++ b/tas/slow/cc.c @@ -28,6 +28,7 @@ #include #include +#include #include "internal.h" #define CONF_MSS 1400 @@ -91,6 +92,8 @@ unsigned cc_poll(uint32_t cur_ts) uint32_t last; unsigned n = 0; + STATS_ADD(slowpath_ctx, cc_poll, 1); + diff_ts = cur_ts - last_ts; if (0 && diff_ts < config.cc_control_granularity) return 0; @@ -169,6 +172,11 @@ unsigned cc_poll(uint32_t cur_ts) next_conn = c; last_ts = cur_ts; + + if (n == 0) + STATS_ADD(slowpath_ctx, cc_empty, 1); + + STATS_ADD(slowpath_ctx, cc_total, n); return n; } diff --git a/tas/slow/kernel.c b/tas/slow/kernel.c index f0ca41a2..6ca51d48 100644 --- a/tas/slow/kernel.c +++ b/tas/slow/kernel.c @@ -43,16 +43,11 @@ void flexnic_loadmon(uint32_t cur_ts); extern void dataplane_dump_stats(void); #endif -struct kernel_context -{ - struct controlplane_stats stats; -}; - -static struct kernel_context slowpath_ctx; +struct kernel_context* slowpath_ctx; -#ifdef APPQUEUE_STATS -uint64_t stats_kout_cycles = 0; -uint64_t stats_kout_count = 0; +#ifdef QUEUE_STATS +extern void appqueue_stats_dump(); +extern void kqueue_stats_dump(); #endif struct timeout_manager timeout_mgr; @@ -65,9 +60,9 @@ int kernel_notifyfd = 0; #ifdef CONTROLPLANE_STATS void controlplane_dump_stats(void) { - struct kernel_context *ctx = &slowpath_ctx; + struct kernel_context *ctx = slowpath_ctx; TAS_LOG(INFO, MAIN, "CP [%u]> (POLL, EMPTY, TOTAL)", 0); -/* + TAS_LOG(INFO, MAIN, "rx=(%"PRIu64",%"PRIu64",%"PRIu64") \n", STATS_FETCH(ctx, rx_poll), STATS_FETCH(ctx, rx_empty), @@ -84,15 +79,17 @@ void controlplane_dump_stats(void) STATS_FETCH(ctx, ac_poll), STATS_FETCH(ctx, ac_empty), STATS_FETCH(ctx, ac_total)); +/* TAS_LOG(INFO, MAIN, "kni=(%"PRIu64",%"PRIu64",%"PRIu64") \n", STATS_FETCH(ctx, kni_poll), STATS_FETCH(ctx, kni_empty), STATS_FETCH(ctx, kni_total)); +*/ TAS_LOG(INFO, MAIN, "tcp=(%"PRIu64",%"PRIu64",%"PRIu64") \n", STATS_FETCH(ctx, tcp_poll), STATS_FETCH(ctx, tcp_empty), STATS_FETCH(ctx, tcp_total)); -*/ + TAS_LOG(INFO, MAIN, "cyc=(%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64") \n", STATS_FETCH(ctx, cyc_rx), STATS_FETCH(ctx, cyc_cc), @@ -113,6 +110,8 @@ int slowpath_main(void) uint32_t last_print = 0; uint32_t loadmon_ts = 0; + slowpath_ctx = calloc(1, sizeof(struct kernel_context)); + kernel_notifyfd = eventfd(0, 0); assert(kernel_notifyfd != -1); @@ -176,7 +175,7 @@ int slowpath_main(void) signal_tas_ready(); - struct kernel_context *ctx = &slowpath_ctx; + struct kernel_context *ctx = slowpath_ctx; while (exited == 0) { unsigned n = 0; @@ -269,6 +268,10 @@ int slowpath_main(void) #ifdef PROFILING dataplane_dump_stats(); controlplane_dump_stats(); +#ifdef QUEUE_STATS + appqueue_stats_dump(); + kqueue_stats_dump(); +#endif #endif } last_print = cur_ts; diff --git a/tas/slow/nicif.c b/tas/slow/nicif.c index b6ac706c..894a9b33 100644 --- a/tas/slow/nicif.c +++ b/tas/slow/nicif.c @@ -33,6 +33,9 @@ #include #include #include +#include +#include +#include #include "internal.h" #include @@ -82,9 +85,15 @@ static volatile struct flextcp_pl_ktx **txq_base; static uint32_t txq_len; static uint32_t *txq_tail; -#ifdef APPQUEUE_STATS -extern uint64_t stats_kout_cycles; -extern uint64_t stats_kout_count; +#ifdef QUEUE_STATS +/* Fastpath -> Slowpath queue delay */ +void kqueue_stats_dump() +{ + TAS_LOG(INFO, MAIN, "kin stats: cyc=%lu count=%lu\n", + STATS_FETCH(slowpath_ctx, kout_cycles), + STATS_FETCH(slowpath_ctx, kout_count)); +} + #endif int nicif_init(void) @@ -118,6 +127,8 @@ unsigned nicif_poll(void) unsigned i, ret = 0/*, nonsuc = 0*/; int x; + STATS_ADD(slowpath_ctx, rx_poll, 1); + for (i = 0; i < 512; i++) { x = rxq_poll(); /*if (x == -1 && ++nonsuc > 2 * fn_cores) @@ -128,6 +139,10 @@ unsigned nicif_poll(void) ret += (x == -1 ? 0 : 1); } + if (ret == 0) + STATS_ADD(slowpath_ctx, rx_idle, 1); + + STATS_ADD(slowpath_ctx, rx_total, ret); return ret; } @@ -508,9 +523,9 @@ static inline int rxq_poll(void) if (type == FLEXTCP_PL_KRX_INVALID) { return -1; } -#ifdef APPQUEUE_STATS - stats_kout_cycles += (util_rdtsc() - krx->ts); - stats_kout_count += 1; +#ifdef QUEUE_STATS + STATS_ADD(slowpath_ctx, kout_cycles, (util_rdtsc() - krx->ts)); + STATS_ADD(slowpath_ctx, kout_count, 1); #endif /* update tail */ diff --git a/tas/slow/tcp.c b/tas/slow/tcp.c index 20b3a246..9c3c33bf 100644 --- a/tas/slow/tcp.c +++ b/tas/slow/tcp.c @@ -36,6 +36,7 @@ #include #include #include +#include #include "internal.h" #define TCP_MSS 1460 @@ -124,8 +125,11 @@ void tcp_poll(void) struct connection *conn; uint8_t *p; int ret; + unsigned n = 0; + STATS_ADD(slowpath_ctx, tcp_poll, 1); while ((p = nbqueue_deq(&conn_async_q)) != NULL) { + n += 1; conn = (struct connection *) (p - offsetof(struct connection, comp.el)); if (conn->status == CONN_ARP_PENDING) { if ((ret = conn->comp.status) != 0 || (ret = conn_arp_done(conn)) != 0) { @@ -141,6 +145,11 @@ void tcp_poll(void) fprintf(stderr, "tcp_poll: unexpected conn state %u\n", conn->status); } } + + if (n == 0) + STATS_ADD(slowpath_ctx, tcp_idle, 1); + + STATS_ADD(slowpath_ctx, tcp_total, n); } int tcp_open(struct app_context *ctx, uint64_t opaque, uint32_t remote_ip, From ed081954d6d78cf236b6132abda2d3196eb5bef4 Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Wed, 13 Nov 2019 12:59:51 -0600 Subject: [PATCH 08/18] Fix compilation errors --- tas/include/slowpath.h | 4 ++-- tas/include/stats.h | 14 ++++++-------- tas/slow/appif.c | 4 ++-- tas/slow/appif_ctx.c | 1 + tas/slow/kernel.c | 1 + tas/slow/nicif.c | 2 +- tas/slow/tcp.c | 2 +- 7 files changed, 14 insertions(+), 14 deletions(-) diff --git a/tas/include/slowpath.h b/tas/include/slowpath.h index 696f48d8..875f0e87 100644 --- a/tas/include/slowpath.h +++ b/tas/include/slowpath.h @@ -35,7 +35,7 @@ struct kernel_context extern struct kernel_context* slowpath_ctx; #ifdef CONTROLPLANE_STATS -void controlplane_dump_stats(void) +void controlplane_dump_stats(void); #endif -#endif /* ndef SLOWPATH_H_ */ \ No newline at end of file +#endif /* ndef SLOWPATH_H_ */ diff --git a/tas/include/stats.h b/tas/include/stats.h index 073b055f..d368a851 100644 --- a/tas/include/stats.h +++ b/tas/include/stats.h @@ -3,8 +3,6 @@ #include -#define PROFILING - #ifdef PROFILING #define DATAPLANE_STATS 1 #define CONTROLPLANE_STATS 1 @@ -95,32 +93,32 @@ struct controlplane_stats /* NIC RX */ uint64_t stat_rx_poll; - uint64_t stat_rx_idle; + uint64_t stat_rx_empty; uint64_t stat_rx_total; /* Congestion Control */ uint64_t stat_cc_poll; - uint64_t stat_cc_idle; + uint64_t stat_cc_empty; uint64_t stat_cc_total; /* Application */ uint64_t stat_ax_poll; - uint64_t stat_ax_idle; + uint64_t stat_ax_empty; uint64_t stat_ax_total; /* Application context */ uint64_t stat_ac_poll; - uint64_t stat_ac_idle; + uint64_t stat_ac_empty; uint64_t stat_ac_total; /* Kernel Native Interface */ uint64_t stat_kni_poll; - uint64_t stat_kni_idle; + uint64_t stat_kni_empty; uint64_t stat_kni_total; /* TCP States */ uint64_t stat_tcp_poll; - uint64_t stat_tcp_idle; + uint64_t stat_tcp_empty; uint64_t stat_tcp_total; /* Cycles consumed in processing by modules */ diff --git a/tas/slow/appif.c b/tas/slow/appif.c index 68f4c9fd..add1a182 100644 --- a/tas/slow/appif.c +++ b/tas/slow/appif.c @@ -186,10 +186,10 @@ unsigned appif_poll(void) } if (m == 0) - STATS_ADD(slowpath_ctx, ax_idle, 1); + STATS_ADD(slowpath_ctx, ax_empty, 1); if (n == 0) - STATS_ADD(slowpath_ctx, ac_idle, 1); + STATS_ADD(slowpath_ctx, ac_empty, 1); STATS_ADD(slowpath_ctx, ax_total, m); STATS_ADD(slowpath_ctx, ac_total, n); diff --git a/tas/slow/appif_ctx.c b/tas/slow/appif_ctx.c index 6ddbc170..4468e6ea 100644 --- a/tas/slow/appif_ctx.c +++ b/tas/slow/appif_ctx.c @@ -32,6 +32,7 @@ #include #include +#include #include #include "internal.h" #include "appif.h" diff --git a/tas/slow/kernel.c b/tas/slow/kernel.c index 6ca51d48..67da4d90 100644 --- a/tas/slow/kernel.c +++ b/tas/slow/kernel.c @@ -31,6 +31,7 @@ #include #include +#include #include #include "internal.h" #include diff --git a/tas/slow/nicif.c b/tas/slow/nicif.c index 894a9b33..6123dad6 100644 --- a/tas/slow/nicif.c +++ b/tas/slow/nicif.c @@ -140,7 +140,7 @@ unsigned nicif_poll(void) } if (ret == 0) - STATS_ADD(slowpath_ctx, rx_idle, 1); + STATS_ADD(slowpath_ctx, rx_empty, 1); STATS_ADD(slowpath_ctx, rx_total, ret); return ret; diff --git a/tas/slow/tcp.c b/tas/slow/tcp.c index 9c3c33bf..d73e8003 100644 --- a/tas/slow/tcp.c +++ b/tas/slow/tcp.c @@ -147,7 +147,7 @@ void tcp_poll(void) } if (n == 0) - STATS_ADD(slowpath_ctx, tcp_idle, 1); + STATS_ADD(slowpath_ctx, tcp_empty, 1); STATS_ADD(slowpath_ctx, tcp_total, n); } From 72d6888d5d736f8272eb2253c52a0098ae73d0cf Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Fri, 15 Nov 2019 21:58:51 -0600 Subject: [PATCH 09/18] Fix Application Context Poll cycle calculation --- tas/slow/appif.c | 3 +++ 1 file changed, 3 insertions(+) diff --git a/tas/slow/appif.c b/tas/slow/appif.c index add1a182..e1c9eeea 100644 --- a/tas/slow/appif.c +++ b/tas/slow/appif.c @@ -181,7 +181,10 @@ unsigned appif_poll(void) if (ctx->ready == 0) { continue; } + STATS_TS(ac_begin); n += appif_ctx_poll(app, ctx); + STATS_TS(ac_end); + STATS_ADD(slowpath_ctx, cyc_ac, ac_end - ac_begin); } } From 4f9118dec23bb7671a5a0d780a4c1b41ffed5ce8 Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Fri, 15 Nov 2019 22:01:40 -0600 Subject: [PATCH 10/18] Fix compile error --- tas/include/stats.h | 1 + 1 file changed, 1 insertion(+) diff --git a/tas/include/stats.h b/tas/include/stats.h index d368a851..fe19f432 100644 --- a/tas/include/stats.h +++ b/tas/include/stats.h @@ -2,6 +2,7 @@ #define TASSTATS_H_ #include +#include #ifdef PROFILING #define DATAPLANE_STATS 1 From 95e7932e7e5c0957f98ca69c8ca9e905008c6119 Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Sat, 16 Nov 2019 18:51:38 -0600 Subject: [PATCH 11/18] Timestamp app to kernel --- lib/tas/conn.c | 4 ++++ lib/tas/kernel.c | 1 + 2 files changed, 5 insertions(+) diff --git a/lib/tas/conn.c b/lib/tas/conn.c index f9c25038..b4641539 100644 --- a/lib/tas/conn.c +++ b/lib/tas/conn.c @@ -74,6 +74,7 @@ int flextcp_listen_open(struct flextcp_context *ctx, kin->data.listen_open.flags = f; MEM_BARRIER(); kin->type = KERNEL_APPOUT_LISTEN_OPEN; + kin->ts = util_rdtsc(); flextcp_kernel_kick(); pos = pos + 1; @@ -109,6 +110,7 @@ int flextcp_listen_accept(struct flextcp_context *ctx, kin->data.accept_conn.local_port = lst->local_port; MEM_BARRIER(); kin->type = KERNEL_APPOUT_ACCEPT_CONN; + kin->ts = util_rdtsc(); flextcp_kernel_kick(); pos = pos + 1; @@ -210,6 +212,7 @@ int flextcp_connection_close(struct flextcp_context *ctx, kin->data.conn_close.flags = f; MEM_BARRIER(); kin->type = KERNEL_APPOUT_CONN_CLOSE; + kin->ts = util_rdtsc(); flextcp_kernel_kick(); pos = pos + 1; @@ -416,6 +419,7 @@ int flextcp_connection_move(struct flextcp_context *ctx, kin->data.conn_move.opaque = OPAQUE(conn); MEM_BARRIER(); kin->type = KERNEL_APPOUT_CONN_MOVE; + kin->ts = util_rdtsc(); flextcp_kernel_kick(); pos = pos + 1; diff --git a/lib/tas/kernel.c b/lib/tas/kernel.c index d029fc62..52881b02 100644 --- a/lib/tas/kernel.c +++ b/lib/tas/kernel.c @@ -273,6 +273,7 @@ int flextcp_kernel_reqscale(struct flextcp_context *ctx, uint32_t cores) kin->data.req_scale.num_cores = cores; MEM_BARRIER(); kin->type = KERNEL_APPOUT_REQ_SCALE; + kin->ts = util_rdtsc(); flextcp_kernel_kick(); pos = pos + 1; From 7bd26f02e4b9b1ad216513b4cf5344725c7f0b00 Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Sat, 16 Nov 2019 18:58:41 -0600 Subject: [PATCH 12/18] Speedup Congestion Control iterations --- tas/slow/cc.c | 16 +++++++--------- tas/slow/internal.h | 1 + 2 files changed, 8 insertions(+), 9 deletions(-) diff --git a/tas/slow/cc.c b/tas/slow/cc.c index 6c116536..6beae806 100644 --- a/tas/slow/cc.c +++ b/tas/slow/cc.c @@ -183,6 +183,7 @@ unsigned cc_poll(uint32_t cur_ts) void cc_conn_init(struct connection *conn) { conn->cc_next = cc_conns; + conn->cc_prev = NULL; cc_conns = conn; conn->cc_last_ts = cur_ts; @@ -216,8 +217,6 @@ void cc_conn_init(struct connection *conn) void cc_conn_remove(struct connection *conn) { - struct connection *cp = NULL; - if (next_conn == conn) { next_conn = conn->cc_next; } @@ -225,14 +224,13 @@ void cc_conn_remove(struct connection *conn) if (cc_conns == conn) { cc_conns = conn->cc_next; } else { - for (cp = cc_conns; cp != NULL && cp->cc_next != conn; - cp = cp->cc_next); - if (cp == NULL) { - fprintf(stderr, "conn_unregister: connection not found\n"); - abort(); - } + struct connection *c_prev = conn->cc_prev; + struct connection *c_next = conn->cc_next; - cp->cc_next = conn->cc_next; + if (c_prev != NULL) + c_prev->cc_next = c_next; + if (c_next != NULL) + c_next->cc_prev = c_prev; } } diff --git a/tas/slow/internal.h b/tas/slow/internal.h index 69ab9d4d..aba9c161 100644 --- a/tas/slow/internal.h +++ b/tas/slow/internal.h @@ -527,6 +527,7 @@ struct connection { uint32_t ts_tx_pending; /** Linked list for CC connection list. */ struct connection *cc_next; + struct connection *cc_prev; /**@}*/ /** Linked list in hash table. */ From f90649678bb9a5c4a211d43555fe2962e81e4214 Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Sat, 16 Nov 2019 19:41:28 -0600 Subject: [PATCH 13/18] Fix errors with SLOWPATH -> APP queuing delay profiling Signed-off-by: Rajath Shashidhara --- tas/slow/appif_ctx.c | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/tas/slow/appif_ctx.c b/tas/slow/appif_ctx.c index 4468e6ea..3fdf04dc 100644 --- a/tas/slow/appif_ctx.c +++ b/tas/slow/appif_ctx.c @@ -326,7 +326,6 @@ unsigned appif_ctx_poll(struct application *app, struct app_context *ctx) /* update kout queue position if the entry was used */ if (kout_inc > 0) { - kout->ts = util_rdtsc(); kout_pos += kout_inc; if (kout_pos >= ctx->kout_len) { kout_pos = 0; @@ -358,6 +357,7 @@ static int kin_conn_open(struct application *app, struct app_context *ctx, kout->data.conn_opened.opaque = kin->data.conn_open.opaque; kout->data.conn_opened.status = -1; MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_CONN_OPENED; appif_ctx_kick(ctx); return 1; @@ -407,6 +407,7 @@ static int kin_conn_move(struct application *app, struct app_context *ctx, kout->data.status.opaque = kin->data.conn_move.opaque; kout->data.status.status = 0; MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_STATUS_CONN_MOVE; appif_ctx_kick(ctx); return 1; @@ -451,6 +452,7 @@ static int kin_conn_close(struct application *app, struct app_context *ctx, kout->data.status.opaque = kin->data.conn_close.opaque; kout->data.status.status = -1; MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_STATUS_CONN_CLOSE; appif_ctx_kick(ctx); return 1; @@ -485,6 +487,7 @@ static int kin_listen_open(struct application *app, struct app_context *ctx, kout->data.status.opaque = kin->data.listen_open.opaque; kout->data.status.status = -1; MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_STATUS_LISTEN_OPEN; appif_ctx_kick(ctx); return 1; @@ -518,6 +521,7 @@ static int kin_accept_conn(struct application *app, struct app_context *ctx, kout->data.accept_connection.status = -1; MEM_BARRIER(); kout->type = KERNEL_APPIN_ACCEPTED_CONN; + kout->ts = util_rdtsc(); appif_ctx_kick(ctx); return 1; } From 03321a31f74bca42b009f9759a90cb22b6828fd7 Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Sat, 16 Nov 2019 20:17:06 -0600 Subject: [PATCH 14/18] Reduce connection traversal using doubly-linked list Signed-off-by: Rajath Shashidhara --- tas/slow/appif_ctx.c | 22 ++++++++++++++-------- tas/slow/cc.c | 1 + tas/slow/internal.h | 1 + 3 files changed, 16 insertions(+), 8 deletions(-) diff --git a/tas/slow/appif_ctx.c b/tas/slow/appif_ctx.c index 3fdf04dc..e3790048 100644 --- a/tas/slow/appif_ctx.c +++ b/tas/slow/appif_ctx.c @@ -124,7 +124,6 @@ void appif_conn_closed(struct connection *c, int status) { struct app_context *ctx = c->ctx; struct application *app = ctx->app; - struct connection *c_i; volatile struct kernel_appin *kout = ctx->kout_base; uint32_t kout_pos = ctx->kout_pos; @@ -153,14 +152,15 @@ void appif_conn_closed(struct connection *c, int status) /* remove from app connection list */ if (app->conns == c) { app->conns = c->app_next; + c->app_prev = NULL; } else { - for (c_i = app->conns; c_i != NULL && c_i->app_next != c; - c_i = c_i->app_next); - if (c_i == NULL) { - fprintf(stderr, "appif_conn_closed: connection not found\n"); - abort(); - } - c_i->app_next = c->app_next; + struct connection* c_prev = c->app_prev; + struct connection* c_next = c->app_next; + + if (c_prev != NULL) + c_prev->app_next = c->app_next; + if (c_next != NULL) + c_next->app_prev = c->app_prev; } } @@ -227,6 +227,9 @@ void appif_accept_conn(struct connection *c, int status) kout->data.accept_connection.fn_core = c->fn_core; c->app_next = app->conns; + c->app_prev = NULL; + if (app->conns != NULL) + app->conns->app_prev = c; app->conns = c; } else { tcp_destroy(c); @@ -349,6 +352,9 @@ static int kin_conn_open(struct application *app, struct app_context *ctx, } conn->app_next = app->conns; + conn->app_prev = NULL; + if (app->conns != NULL) + app->conns->app_prev = conn; app->conns = conn; return 0; diff --git a/tas/slow/cc.c b/tas/slow/cc.c index 6beae806..3622a2e6 100644 --- a/tas/slow/cc.c +++ b/tas/slow/cc.c @@ -223,6 +223,7 @@ void cc_conn_remove(struct connection *conn) if (cc_conns == conn) { cc_conns = conn->cc_next; + conn->cc_prev = NULL; } else { struct connection *c_prev = conn->cc_prev; struct connection *c_next = conn->cc_next; diff --git a/tas/slow/internal.h b/tas/slow/internal.h index aba9c161..480858b7 100644 --- a/tas/slow/internal.h +++ b/tas/slow/internal.h @@ -425,6 +425,7 @@ struct connection { struct app_context *new_ctx; /** Link list pointer for application connections. */ struct connection *app_next; + struct connection *app_prev; /** Doorbell id. */ uint32_t db_id; /**@}*/ From 0c1d5893dc2f6a12798b373821aa5082480ce66c Mon Sep 17 00:00:00 2001 From: Rajath Shashidhara Date: Sat, 16 Nov 2019 20:40:33 -0600 Subject: [PATCH 15/18] Optimize connection lookup time Signed-off-by: Rajath Shashidhara --- tas/slow/appif_ctx.c | 35 +++++++++++++++-------------------- tas/slow/tcp.c | 21 +++++++++++++++++++++ 2 files changed, 36 insertions(+), 20 deletions(-) diff --git a/tas/slow/appif_ctx.c b/tas/slow/appif_ctx.c index e3790048..cd2cfc55 100644 --- a/tas/slow/appif_ctx.c +++ b/tas/slow/appif_ctx.c @@ -49,6 +49,9 @@ static int kin_accept_conn(struct application *app, struct app_context *ctx, volatile struct kernel_appout *kin, volatile struct kernel_appin *kout); static int kin_req_scale(struct application *app, struct app_context *ctx, volatile struct kernel_appout *kin, volatile struct kernel_appin *kout); +extern struct connection *conn_ht_lookup(uint64_t opaque, uint32_t local_ip, + uint32_t remote_ip, uint16_t local_port, uint16_t remote_port); + #ifdef QUEUE_STATS void appqueue_stats_dump() @@ -375,16 +378,12 @@ static int kin_conn_move(struct application *app, struct app_context *ctx, struct connection *conn; struct app_context *new_ctx; - for (conn = app->conns; conn != NULL; conn = conn->app_next) { - if (conn->local_ip == kin->data.conn_move.local_ip && - conn->remote_ip == kin->data.conn_move.remote_ip && - conn->local_port == kin->data.conn_move.local_port && - conn->remote_port == kin->data.conn_move.remote_port && - conn->opaque == kin->data.conn_move.opaque) - { - break; - } - } + conn = conn_ht_lookup(kin->data.conn_move.opaque, + kin->data.conn_move.local_ip, + kin->data.conn_move.remote_ip, + kin->data.conn_move.local_port, + kin->data.conn_move.remote_port); + if (conn == NULL) { fprintf(stderr, "kin_conn_move: connection not found\n"); goto error; @@ -432,16 +431,12 @@ static int kin_conn_close(struct application *app, struct app_context *ctx, { struct connection *conn; - for (conn = app->conns; conn != NULL; conn = conn->app_next) { - if (conn->local_ip == kin->data.conn_close.local_ip && - conn->remote_ip == kin->data.conn_close.remote_ip && - conn->local_port == kin->data.conn_close.local_port && - conn->remote_port == kin->data.conn_close.remote_port && - conn->opaque == kin->data.conn_close.opaque) - { - break; - } - } + conn = conn_ht_lookup(kin->data.conn_move.opaque, + kin->data.conn_move.local_ip, + kin->data.conn_move.remote_ip, + kin->data.conn_move.local_port, + kin->data.conn_move.remote_port); + if (conn == NULL) { fprintf(stderr, "kin_conn_close: connection not found\n"); goto error; diff --git a/tas/slow/tcp.c b/tas/slow/tcp.c index d73e8003..125ee5e7 100644 --- a/tas/slow/tcp.c +++ b/tas/slow/tcp.c @@ -1136,3 +1136,24 @@ static inline int parse_options(const struct pkt_tcp *p, uint16_t len, return 0; } + +struct connection *conn_ht_lookup(uint64_t opaque, uint32_t local_ip, + uint32_t remote_ip, uint16_t local_port, uint16_t remote_port) +{ + uint32_t h; + struct connection *c; + + h = conn_hash(local_ip, remote_ip, + local_port, remote_port) % TCP_HTSIZE; + + for (c = tcp_hashtable[h]; c != NULL; c = c->ht_next) { + if (remote_ip == c->remote_ip && + local_port == c->local_port && + remote_port == c->remote_port && + opaque == c->opaque) + { + return c; + } + } + return NULL; +} From 0bbe913f3681fb2f663cb32acc0b249bbed6b38d Mon Sep 17 00:00:00 2001 From: Piyush Jain Date: Wed, 13 Nov 2019 23:24:26 +0000 Subject: [PATCH 16/18] Remove connection from application connection list before tcp_destroy. Minor stat print changes --- tas/fast/fastemu.c | 2 +- tas/slow/appif_ctx.c | 14 ++++++++++++++ tas/slow/kernel.c | 6 +++--- tas/tas.c | 2 +- 4 files changed, 19 insertions(+), 5 deletions(-) diff --git a/tas/fast/fastemu.c b/tas/fast/fastemu.c index 127d8b54..cdef3e2e 100644 --- a/tas/fast/fastemu.c +++ b/tas/fast/fastemu.c @@ -225,7 +225,7 @@ void dataplane_dump_stats(void) if (ctx == NULL) continue; - TAS_LOG(INFO, MAIN, "DP [%u]> (POLL, EMPTY, TOTAL)", i); + TAS_LOG(INFO, MAIN, "DP [%u]> (POLL, EMPTY, TOTAL)\n", i); TAS_LOG(INFO, MAIN, "qm=(%"PRIu64",%"PRIu64",%"PRIu64") \n", STATS_ATOMIC_FETCH(ctx, qm_poll), STATS_ATOMIC_FETCH(ctx, qm_empty), diff --git a/tas/slow/appif_ctx.c b/tas/slow/appif_ctx.c index cd2cfc55..263380e7 100644 --- a/tas/slow/appif_ctx.c +++ b/tas/slow/appif_ctx.c @@ -108,6 +108,20 @@ void appif_conn_opened(struct connection *c, int status) kout->data.conn_opened.flow_id = c->flow_id; kout->data.conn_opened.fn_core = c->fn_core; } else { + /* remove from app connection list */ + struct application *app = ctx->app; + if (app->conns == c) { + app->conns = c->app_next; + } else { + struct connection *c_crwl; + for (c_crwl = app->conns; c_crwl != NULL && c_crwl->app_next != c; + c_crwl = c_crwl->app_next); + if (c_crwl == NULL) { + fprintf(stderr, "appif_conn_closed: connection not found\n"); + abort(); + } + c_crwl->app_next = c->app_next; + } tcp_destroy(c); } diff --git a/tas/slow/kernel.c b/tas/slow/kernel.c index 67da4d90..eeda6863 100644 --- a/tas/slow/kernel.c +++ b/tas/slow/kernel.c @@ -61,8 +61,8 @@ int kernel_notifyfd = 0; #ifdef CONTROLPLANE_STATS void controlplane_dump_stats(void) { - struct kernel_context *ctx = slowpath_ctx; - TAS_LOG(INFO, MAIN, "CP [%u]> (POLL, EMPTY, TOTAL)", 0); + struct kernel_context *ctx = &slowpath_ctx; + TAS_LOG(INFO, MAIN, "CP [%u]> (POLL, EMPTY, TOTAL)\n", 0); TAS_LOG(INFO, MAIN, "rx=(%"PRIu64",%"PRIu64",%"PRIu64") \n", STATS_FETCH(ctx, rx_poll), @@ -260,7 +260,7 @@ int slowpath_main(void) startwait = 0; } - if (cur_ts - last_print >= 1000000) { + if (cur_ts - last_print >= 10000000) { if (!config.quiet) { printf("stats: drops=%"PRIu64" k_rexmit=%"PRIu64" ecn=%"PRIu64" acks=%" PRIu64"\n", kstats.drops, kstats.kernel_rexmit, kstats.ecn_marked, diff --git a/tas/tas.c b/tas/tas.c index 04c4a77a..06aade37 100644 --- a/tas/tas.c +++ b/tas/tas.c @@ -89,7 +89,7 @@ int main(int argc, char *argv[]) } /* initialize dpdk */ - rte_log_set_global_level(RTE_LOG_ERR); + rte_log_set_global_level(RTE_LOG_INFO); if (rte_eal_init(config.dpdk_argc, config.dpdk_argv) < 0) { fprintf(stderr, "dpdk init failed\n"); goto error_exit; From 3a8a970cf02cf7c39330af7b1f0c5dd0f60c0d0b Mon Sep 17 00:00:00 2001 From: Piyush Jain Date: Sat, 16 Nov 2019 20:16:39 +0000 Subject: [PATCH 17/18] Stats log change --- tas/fast/fast_flows.c | 4 ++-- tas/fast/fastemu.c | 25 +++++++++++++++++++------ tas/include/stats.h | 20 ++++++++++++++++++++ tas/slow/appif_ctx.c | 23 ++++++++++++++++++++--- tas/slow/cc.c | 4 ++++ tas/slow/kernel.c | 30 +++++++++++++++++++++++++++++- tas/slow/nicif.c | 16 ++++++++++++++-- tas/slow/tcp.c | 21 +++++++++++++++++++-- 8 files changed, 127 insertions(+), 16 deletions(-) diff --git a/tas/fast/fast_flows.c b/tas/fast/fast_flows.c index 8eed685d..c0cc3a6a 100644 --- a/tas/fast/fast_flows.c +++ b/tas/fast/fast_flows.c @@ -354,8 +354,8 @@ int fast_flows_packet(struct dataplane_context *ctx, /* for SYN/SYN-ACK we'll let the kernel handle them out of band */ no_permanent_sp = 1; } else { - fprintf(stderr, "dma_krx_pkt_fastpath: slow path because of flags (%x)\n", - TCPH_FLAGS(&p->tcp)); + //fprintf(stderr, "dma_krx_pkt_fastpath: slow path because of flags (%x)\n", + // TCPH_FLAGS(&p->tcp)); } goto slowpath; } diff --git a/tas/fast/fastemu.c b/tas/fast/fastemu.c index cdef3e2e..01898ba2 100644 --- a/tas/fast/fastemu.c +++ b/tas/fast/fastemu.c @@ -144,19 +144,22 @@ void dataplane_loop(struct dataplane_context *ctx) STATS_TS(start); n += poll_rx(ctx, ts); STATS_TS(rx); + STATS_ATOMIC_ADD(ctx, cyc_rx, rx - start); + tx_flush(ctx); STATS_TS(acktx); STATS_ATOMIC_ADD(ctx, cyc_tx, acktx - rx); n += poll_qman_fwd(ctx, ts); - STATS_ATOMIC_ADD(ctx, cyc_rx, rx - start); + STATS_TS(poll_qman_start); n += poll_qman(ctx, ts); - STATS_TS(qm); - STATS_ATOMIC_ADD(ctx, cyc_qm, qm - rx); + STATS_TS(poll_qman_end); + STATS_ATOMIC_ADD(ctx, cyc_qm, poll_qman_end - poll_qman_start); + n += poll_queues(ctx, ts); STATS_TS(qs); - STATS_ATOMIC_ADD(ctx, cyc_qs, qs - qm); + STATS_ATOMIC_ADD(ctx, cyc_qs, qs - poll_qman_end); n += poll_kernel(ctx, ts); STATS_TS(sp); STATS_ATOMIC_ADD(ctx, cyc_sp, sp - qs); @@ -252,10 +255,12 @@ void dataplane_dump_stats(void) STATS_ATOMIC_FETCH(ctx, cyc_qs), STATS_ATOMIC_FETCH(ctx, cyc_sp), STATS_ATOMIC_FETCH(ctx, cyc_tx)); + #ifdef QUEUE_STATS - TAS_LOG(INFO, MAIN, "kin=(%"PRIu64",%"PRIu64") \n", + TAS_LOG(INFO, MAIN, "slow -> fast (%"PRIu64",%"PRIu64") avg_queuing_delay=%lF\n", STATS_ATOMIC_FETCH(ctx, kin_cycles), - STATS_ATOMIC_FETCH(ctx, kin_count)); + STATS_ATOMIC_FETCH(ctx, kin_count), + ((double) STATS_ATOMIC_FETCH(ctx, kin_cycles))/ STATS_ATOMIC_FETCH(ctx, kin_count)); #endif } } @@ -394,6 +399,8 @@ static unsigned poll_kernel(struct dataplane_context *ctx, uint32_t ts) uint16_t max, k = 0; int ret; + STATS_ADD(ctx, sp_poll, 1); + max = BATCH_SIZE; if (TXBUF_SIZE - ctx->tx_num < max) max = TXBUF_SIZE - ctx->tx_num; @@ -440,8 +447,11 @@ static unsigned poll_qman(struct dataplane_context *ctx, uint32_t ts) /* allocate buffers contents */ max = bufcache_prealloc(ctx, max, &handles); + //STATS_TS(start_qman_poll); /* poll queue manager */ ret = qman_poll(&ctx->qman, max, q_ids, q_bytes); + //STATS_TS(end_qman_poll); + if (ret <= 0) { STATS_ADD(ctx, qm_empty, 1); return 0; @@ -467,7 +477,10 @@ static unsigned poll_qman(struct dataplane_context *ctx, uint32_t ts) fast_flows_qman_pfbufs(ctx, q_ids, ret); for (i = 0; i < ret; i++) { + //STATS_TS(start_fast_flows_qman); use = fast_flows_qman(ctx, q_ids[i], handles[off], ts); + //STATS_TS(end_fast_flows_qman); + //STATS_ATOMIC_ADD(ctx, cyc_fast_flows_qman, ); if (use == 0) off++; diff --git a/tas/include/stats.h b/tas/include/stats.h index fe19f432..d68cab98 100644 --- a/tas/include/stats.h +++ b/tas/include/stats.h @@ -122,6 +122,26 @@ struct controlplane_stats uint64_t stat_tcp_empty; uint64_t stat_tcp_total; + /* Accept States */ + uint64_t stat_cyc_ta; + uint64_t stat_cyc_la; + uint64_t stat_cyc_kac; + + /* Kernel app_if task cycles */ + uint64_t stat_cyc_kclose; + uint64_t stat_cyc_kmove; + uint64_t stat_cyc_klopen; + uint64_t stat_cyc_kreq_scale; + + /* Close sub task cycles */ + uint64_t stat_cyc_fs_lock; + uint64_t stat_cyc_flow_slot_clear; + uint64_t stat_cyc_tcp_close; + uint64_t stat_cyc_conn_close_iter; + uint64_t stat_conn_close_cnt; + uint64_t stat_cyc_cc_remove; + uint64_t stat_cyc_timeout_arm; + /* Cycles consumed in processing by modules */ uint64_t stat_cyc_rx; uint64_t stat_cyc_cc; diff --git a/tas/slow/appif_ctx.c b/tas/slow/appif_ctx.c index 263380e7..cd3eee3f 100644 --- a/tas/slow/appif_ctx.c +++ b/tas/slow/appif_ctx.c @@ -56,9 +56,10 @@ extern struct connection *conn_ht_lookup(uint64_t opaque, uint32_t local_ip, #ifdef QUEUE_STATS void appqueue_stats_dump() { - TAS_LOG(INFO, MAIN, "appqin stats: cyc=%lu count=%lu\n", + TAS_LOG(INFO, MAIN, "app -> slow stats: cyc=%lu count=%lu avg_queuing_delay=%lf\n", STATS_FETCH(slowpath_ctx, appin_cycles), - STATS_FETCH(slowpath_ctx, appin_count)); + STATS_FETCH(slowpath_ctx, appin_count), + (double) STATS_FETCH(slowpath_ctx, appin_cycles)/ STATS_FETCH(slowpath_ctx, appin_count)); } #endif @@ -267,6 +268,7 @@ void appif_accept_conn(struct connection *c, int status) unsigned appif_ctx_poll(struct application *app, struct app_context *ctx) { + STATS_TS(start); volatile struct kernel_appout *kin = ctx->kin_base; volatile struct kernel_appin *kout = ctx->kout_base; uint32_t kin_pos = ctx->kin_pos; @@ -306,26 +308,37 @@ unsigned appif_ctx_poll(struct application *app, struct app_context *ctx) case KERNEL_APPOUT_CONN_MOVE: /* connection move request */ kout_inc += kin_conn_move(app, ctx, kin, kout); + STATS_TS(end_move); + STATS_ADD(slowpath_ctx, cyc_kmove, end_move-start); break; case KERNEL_APPOUT_CONN_CLOSE: /* connection close request */ kout_inc += kin_conn_close(app, ctx, kin, kout); + STATS_TS(end_close); + STATS_ADD(slowpath_ctx, cyc_kclose, end_close-start); break; case KERNEL_APPOUT_LISTEN_OPEN: /* listen request */ kout_inc += kin_listen_open(app, ctx, kin, kout); + STATS_TS(end_lopen); + STATS_ADD(slowpath_ctx, cyc_klopen, end_lopen-start); break; case KERNEL_APPOUT_ACCEPT_CONN: /* accept request */ + (void) app; kout_inc += kin_accept_conn(app, ctx, kin, kout); + STATS_TS(end); + STATS_ADD(slowpath_ctx, cyc_kac, end-start); break; case KERNEL_APPOUT_REQ_SCALE: /* scaling request */ kout_inc += kin_req_scale(app, ctx, kin, kout); + STATS_TS(end_req_scale); + STATS_ADD(slowpath_ctx, cyc_kreq_scale, end_req_scale-start); break; case KERNEL_APPOUT_LISTEN_CLOSE: @@ -445,11 +458,15 @@ static int kin_conn_close(struct application *app, struct app_context *ctx, { struct connection *conn; + STATS_TS(conn_close_iter_start); conn = conn_ht_lookup(kin->data.conn_move.opaque, kin->data.conn_move.local_ip, kin->data.conn_move.remote_ip, kin->data.conn_move.local_port, kin->data.conn_move.remote_port); + STATS_TS(conn_close_iter_end); + STATS_ADD(slowpath_ctx, cyc_conn_close_iter, conn_close_iter_end - conn_close_iter_start); + STATS_ADD(slowpath_ctx, conn_close_cnt, 1); if (conn == NULL) { fprintf(stderr, "kin_conn_close: connection not found\n"); @@ -464,6 +481,7 @@ static int kin_conn_close(struct application *app, struct app_context *ctx, return 0; error: + fprintf(stderr, "Error in kin_conn_close\n"); kout->data.status.opaque = kin->data.conn_close.opaque; kout->data.status.status = -1; MEM_BARRIER(); @@ -521,7 +539,6 @@ static int kin_accept_conn(struct application *app, struct app_context *ctx, break; } } - if (tcp_accept(ctx, kin->data.accept_conn.conn_opaque, listen, ctx->doorbell->id) != 0) { diff --git a/tas/slow/cc.c b/tas/slow/cc.c index 3622a2e6..263e93ff 100644 --- a/tas/slow/cc.c +++ b/tas/slow/cc.c @@ -217,6 +217,8 @@ void cc_conn_init(struct connection *conn) void cc_conn_remove(struct connection *conn) { + STATS_TS(cc_start); + if (next_conn == conn) { next_conn = conn->cc_next; } @@ -233,6 +235,8 @@ void cc_conn_remove(struct connection *conn) if (c_next != NULL) c_next->cc_prev = c_prev; } + STATS_TS(cc_end); + STATS_ADD(slowpath_ctx, cyc_cc_remove, cc_end - cc_start); } static inline void issue_retransmits(struct connection *c, diff --git a/tas/slow/kernel.c b/tas/slow/kernel.c index eeda6863..43c18b8d 100644 --- a/tas/slow/kernel.c +++ b/tas/slow/kernel.c @@ -61,7 +61,7 @@ int kernel_notifyfd = 0; #ifdef CONTROLPLANE_STATS void controlplane_dump_stats(void) { - struct kernel_context *ctx = &slowpath_ctx; + struct kernel_context *ctx = slowpath_ctx; TAS_LOG(INFO, MAIN, "CP [%u]> (POLL, EMPTY, TOTAL)\n", 0); TAS_LOG(INFO, MAIN, "rx=(%"PRIu64",%"PRIu64",%"PRIu64") \n", @@ -90,6 +90,34 @@ void controlplane_dump_stats(void) STATS_FETCH(ctx, tcp_poll), STATS_FETCH(ctx, tcp_empty), STATS_FETCH(ctx, tcp_total)); + TAS_LOG(INFO, MAIN, "accept=(%"PRIu64",%"PRIu64",%"PRIu64") \n", + STATS_FETCH(ctx, cyc_ta), + STATS_FETCH(ctx, cyc_la), + STATS_FETCH(ctx, cyc_kac)); + TAS_LOG(INFO, MAIN, "close=(%"PRIu64") \n", + STATS_FETCH(ctx, cyc_kclose)); + TAS_LOG(INFO, MAIN, "cyc_kmove=(%"PRIu64") \n", + STATS_FETCH(ctx, cyc_klopen)); + TAS_LOG(INFO, MAIN, "cyc_klopen=(%"PRIu64") \n", + STATS_FETCH(ctx, cyc_klopen)); + TAS_LOG(INFO, MAIN, "cyc_klopen=(%"PRIu64") \n", + STATS_FETCH(ctx, cyc_klopen)); + TAS_LOG(INFO, MAIN, "cyc_fs_lock=(%"PRIu64") \n", + STATS_FETCH(ctx, cyc_fs_lock)); + TAS_LOG(INFO, MAIN, "stat_cyc_flow_slot_clear=(%"PRIu64") \n", + STATS_FETCH(ctx, cyc_flow_slot_clear)); + TAS_LOG(INFO, MAIN, "stat_cyc_tcp_close=(%"PRIu64") \n", + STATS_FETCH(ctx, cyc_tcp_close)); + TAS_LOG(INFO, MAIN, "stat_cyc_conn_close_iter=(%"PRIu64") \n", + STATS_FETCH(ctx, cyc_conn_close_iter)); + TAS_LOG(INFO, MAIN, "stat_conn_close_cnt=(%"PRIu64") \n", + STATS_FETCH(ctx, conn_close_cnt)); + TAS_LOG(INFO, MAIN, "conn_close_iter_per_close=%lF \n", + ((double) STATS_FETCH(ctx, cyc_conn_close_iter))/STATS_FETCH(ctx, conn_close_cnt)); + TAS_LOG(INFO, MAIN, "cc_conn_remove=(%"PRIu64") \n", + STATS_FETCH(ctx, cyc_cc_remove)); + TAS_LOG(INFO, MAIN, "cyc_timeout_arm=(%"PRIu64") \n", + STATS_FETCH(ctx, cyc_timeout_arm)); TAS_LOG(INFO, MAIN, "cyc=(%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64") \n", STATS_FETCH(ctx, cyc_rx), diff --git a/tas/slow/nicif.c b/tas/slow/nicif.c index 6123dad6..30d5f5af 100644 --- a/tas/slow/nicif.c +++ b/tas/slow/nicif.c @@ -89,9 +89,10 @@ static uint32_t *txq_tail; /* Fastpath -> Slowpath queue delay */ void kqueue_stats_dump() { - TAS_LOG(INFO, MAIN, "kin stats: cyc=%lu count=%lu\n", + TAS_LOG(INFO, MAIN, "fast -> slow stats: cyc=%lu count=%lu avg_queuing_delay=%lF\n", STATS_FETCH(slowpath_ctx, kout_cycles), - STATS_FETCH(slowpath_ctx, kout_count)); + STATS_FETCH(slowpath_ctx, kout_count), + ((double) STATS_FETCH(slowpath_ctx, kout_cycles))/STATS_FETCH(slowpath_ctx, kout_count)); } #endif @@ -270,9 +271,13 @@ int nicif_connection_add(uint32_t db, uint64_t mac_remote, uint32_t ip_local, int nicif_connection_disable(uint32_t f_id, uint32_t *tx_seq, uint32_t *rx_seq, int *tx_closed, int *rx_closed) { + //STATS_TS(nic_if_conn_disable_start); struct flextcp_pl_flowst *fs = &fp_state->flowst[f_id]; + STATS_TS(start); util_spin_lock(&fs->lock); + STATS_TS(end); + STATS_ADD(slowpath_ctx, cyc_fs_lock, end - start); *tx_seq = fs->tx_next_seq; *rx_seq = fs->rx_next_seq; @@ -284,8 +289,15 @@ int nicif_connection_disable(uint32_t f_id, uint32_t *tx_seq, uint32_t *rx_seq, util_spin_unlock(&fs->lock); + + STATS_TS(flow_slot_clear_start); flow_slot_clear(f_id, fs->local_ip, fs->local_port, fs->remote_ip, fs->remote_port); + STATS_TS(flow_slot_clear_end); + STATS_ADD(slowpath_ctx, cyc_flow_slot_clear, flow_slot_clear_end - flow_slot_clear_start); + + //STATS_TS(nic_if_conn_disable_end); + //STATS_ADD(slowpath_ctx, cyc_nic_if_conn_disable, nic_if_conn_disable_end - nic_if_conn_disable_start); return 0; } diff --git a/tas/slow/tcp.c b/tas/slow/tcp.c index 125ee5e7..31dbe99f 100644 --- a/tas/slow/tcp.c +++ b/tas/slow/tcp.c @@ -336,6 +336,7 @@ int tcp_accept(struct app_context *ctx, uint64_t opaque, { struct connection *conn; + STATS_TS(start); /* allocate listener struct */ if ((conn = conn_alloc()) == NULL) { fprintf(stderr, "tcp_accept: conn_alloc failed\n"); @@ -356,6 +357,8 @@ int tcp_accept(struct app_context *ctx, uint64_t opaque, if (listen->backlog_used > 0) { listener_accept(listen); } + STATS_TS(end); + STATS_ADD(slowpath_ctx, cyc_ta, end - start); return 0; } @@ -403,6 +406,7 @@ int tcp_packet(const void *pkt, uint16_t len, uint32_t fn_core, int tcp_close(struct connection *conn) { + STATS_TS(tcp_close_start); uint32_t tx_seq, rx_seq; int tx_c, rx_c; @@ -432,8 +436,15 @@ int tcp_close(struct connection *conn) /* set timer to free connection state */ assert(conn->to_armed == 0); + + STATS_TS(timeout_arm_start); util_timeout_arm(&timeout_mgr, &conn->to, 10000, TO_TCP_CLOSED); + STATS_TS(timeout_arm_end); + + STATS_ADD(slowpath_ctx, cyc_timeout_arm, timeout_arm_end - timeout_arm_start); conn->to_armed = 1; + STATS_TS(tcp_close_end); + STATS_ADD(slowpath_ctx, cyc_tcp_close, tcp_close_end - tcp_close_start); return 0; } @@ -460,7 +471,7 @@ void tcp_timeout(struct timeout *to, enum timeout_type type) abort(); } if (c->status != CONN_SYN_SENT) { - fprintf(stderr, "tcp_timeout: unexpected connection state (%u)\n", c->status); + //fprintf(stderr, "tcp_timeout: unexpected connection state (%u)\n", c->status); abort(); } @@ -523,7 +534,8 @@ static void conn_packet(struct connection *c, const struct pkt_tcp *p, * why necessary*/ send_control(c, TCP_ACK, 1, 0, 0); } else { - fprintf(stderr, "tcp_packet: unexpected connection state %u\n", c->status); + //fprintf(stderr, "tcp_packet: unexpected connection state %u\n", c->status); + tcp_close(c); } } @@ -904,6 +916,7 @@ static void listener_packet(struct listener *l, const struct pkt_tcp *p, static void listener_accept(struct listener *l) { + STATS_TS(start); struct connection *c = l->wait_conns; struct backlog_slot *bls; const struct pkt_tcp *p; @@ -974,6 +987,10 @@ static void listener_accept(struct listener *l) if (l->backlog_pos >= l->backlog_len) { l->backlog_pos -= l->backlog_len; } + + util_spin_unlock(&l->lock); + STATS_TS(end); + STATS_ADD(slowpath_ctx, cyc_la, end - start); } static inline int send_control_raw(uint64_t remote_mac, uint32_t remote_ip, From 227af346d73a863610af381a9f5f87297f8ddad1 Mon Sep 17 00:00:00 2001 From: Piyush Jain Date: Sat, 16 Nov 2019 21:58:25 +0000 Subject: [PATCH 18/18] Minor stat changes --- lib/tas/init.c | 5 +++-- tas/slow/appif_ctx.c | 3 +++ tas/slow/tcp.c | 1 - 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/lib/tas/init.c b/lib/tas/init.c index 68c0c95c..7bd68eee 100644 --- a/lib/tas/init.c +++ b/lib/tas/init.c @@ -153,8 +153,9 @@ static uint64_t stats_appout_count = 0; void appqueue_stats_dump() { - fprintf(stderr, "appqout stats: cyc=%lu count=%lu\n", - stats_appout_cycles, stats_appout_count); + fprintf(stderr, "slow -> app stats: cyc=%lu count=%lu avg_queuing_delay=%lF\n", + stats_appout_cycles, stats_appout_count, + ((double) stats_appout_cycles/ stats_appout_count)); } #endif diff --git a/tas/slow/appif_ctx.c b/tas/slow/appif_ctx.c index cd3eee3f..cae3b964 100644 --- a/tas/slow/appif_ctx.c +++ b/tas/slow/appif_ctx.c @@ -448,6 +448,7 @@ static int kin_conn_move(struct application *app, struct app_context *ctx, kout->data.status.opaque = kin->data.conn_move.opaque; kout->data.status.status = -1; MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_STATUS_CONN_MOVE; appif_ctx_kick(ctx); return 1; @@ -511,6 +512,7 @@ static int kin_listen_open(struct application *app, struct app_context *ctx, kout->data.status.opaque = kin->data.listen_open.opaque; kout->data.status.status = 0; MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_STATUS_LISTEN_OPEN; appif_ctx_kick(ctx); @@ -552,6 +554,7 @@ static int kin_accept_conn(struct application *app, struct app_context *ctx, kout->data.accept_connection.opaque = kin->data.accept_conn.conn_opaque; kout->data.accept_connection.status = -1; MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_ACCEPTED_CONN; kout->ts = util_rdtsc(); appif_ctx_kick(ctx); diff --git a/tas/slow/tcp.c b/tas/slow/tcp.c index 31dbe99f..a7dcbb9c 100644 --- a/tas/slow/tcp.c +++ b/tas/slow/tcp.c @@ -988,7 +988,6 @@ static void listener_accept(struct listener *l) l->backlog_pos -= l->backlog_len; } - util_spin_unlock(&l->lock); STATS_TS(end); STATS_ADD(slowpath_ctx, cyc_la, end - start); }