diff --git a/Makefile b/Makefile index 506c2426..1565531b 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 @@ -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+= -DCONNECTION_STATS -DQUEUE_STATS -DPROFILING 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/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/lib/sockets/context.c b/lib/sockets/context.c index 6bca2e1e..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, @@ -145,6 +149,27 @@ int flextcp_sockctx_poll(struct flextcp_context *ctx) } } +#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) + { + 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; + +#ifdef QUEUE_STATS + appqueue_stats_dump(); +#endif + } +#endif + return num; } @@ -174,6 +199,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 +243,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 +270,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 +464,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..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; @@ -145,6 +147,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; @@ -209,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; @@ -415,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/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..7bd68eee 100644 --- a/lib/tas/init.c +++ b/lib/tas/init.c @@ -147,6 +147,17 @@ int flextcp_context_create(struct flextcp_context *ctx) #include int debug_flextcp_on = 0; +#ifdef QUEUE_STATS +static uint64_t stats_appout_cycles = 0; +static uint64_t stats_appout_count = 0; + +void appqueue_stats_dump() +{ + 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 static int kernel_poll(struct flextcp_context *ctx, int num, struct flextcp_event *events, int *used) @@ -164,6 +175,13 @@ static int kernel_poll(struct flextcp_context *ctx, int num, type = kout->type; MEM_BARRIER(); +#ifdef QUEUE_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/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; 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/fast_kernel.c b/tas/fast/fast_kernel.c index 2c11926f..5b1a6050 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 QUEUE_STATS + if (ktx->type != 0) + { + STATS_ATOMIC_ADD(ctx, kin_cycles, (util_rdtsc() - ktx->ts)); + STATS_ATOMIC_ADD(ctx, 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/fast/fastemu.c b/tas/fast/fastemu.c index 5dbb63f2..01898ba2 100644 --- a/tas/fast/fastemu.c +++ b/tas/fast/fastemu.c @@ -32,27 +32,11 @@ #include #include +#include #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)); @@ -143,6 +127,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; @@ -158,21 +144,30 @@ 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_TSADD(ctx, cyc_rx, rx - start); + STATS_TS(poll_qman_start); n += poll_qman(ctx, ts); - STATS_TS(qm); - STATS_TSADD(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_TSADD(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); /* flush transmit buffer */ tx_flush(ctx); + STATS_TS(tx); + STATS_ATOMIC_ADD(ctx, cyc_tx, tx - sp); if (ctx->id == 0) poll_scale(ctx); @@ -181,38 +176,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; @@ -222,11 +218,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; @@ -234,21 +225,50 @@ void dataplane_dump_stats(void) for (i = 0; i < fp_cores_max; i++) { ctx = ctxs[i]; - fprintf(stderr, "dp stats %u: " - "qm=(%"PRIu64",%"PRIu64",%"PRIu64") " - "rx=(%"PRIu64",%"PRIu64",%"PRIu64") " - "qs=(%"PRIu64",%"PRIu64",%"PRIu64") " - "cyc=(%"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_cyc_db), read_stat(&ctx->stat_cyc_qm), - read_stat(&ctx->stat_cyc_rx), read_stat(&ctx->stat_cyc_qs)); + if (ctx == NULL) + continue; + + 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), + 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)); + +#ifdef QUEUE_STATS + 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), + ((double) STATS_ATOMIC_FETCH(ctx, kin_cycles))/ STATS_ATOMIC_FETCH(ctx, kin_count)); +#endif } } +#else +void dataplane_dump_stats(void) +{ + return; +} #endif static unsigned poll_rx(struct dataplane_context *ctx, uint32_t ts) @@ -367,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; } @@ -379,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; @@ -389,7 +411,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) @@ -401,6 +423,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; } @@ -421,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; @@ -448,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++; @@ -547,6 +579,8 @@ static inline void tx_flush(struct dataplane_context *ctx) return; } + STATS_ATOMIC_ADD(ctx, tx_poll, 1); + /* try to send out packets */ ret = network_send(&ctx->net, ctx->tx_num, ctx->tx_handles); @@ -560,6 +594,10 @@ static inline void tx_flush(struct dataplane_context *ctx) } ctx->tx_num -= ret; } + + STATS_ATOMIC_ADD(ctx, tx_total, ret); + if (ret == 0) + 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 b2f9f21f..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,26 +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_cyc_db; - uint64_t stat_cyc_qm; - uint64_t stat_cyc_rx; - uint64_t stat_cyc_qs; -#endif + struct dataplane_stats stats; }; extern struct dataplane_context **ctxs; diff --git a/tas/include/slowpath.h b/tas/include/slowpath.h new file mode 100644 index 00000000..875f0e87 --- /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_ */ diff --git a/tas/include/stats.h b/tas/include/stats.h new file mode 100644 index 00000000..d68cab98 --- /dev/null +++ b/tas/include/stats.h @@ -0,0 +1,163 @@ +#ifndef TASSTATS_H_ +#define TASSTATS_H_ + +#include +#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; + +#ifdef QUEUE_STATS + /* Kernel -> Fastpath queue delay statistics */ + uint64_t stat_kin_cycles; + uint64_t stat_kin_count; +#endif + +#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_empty; + uint64_t stat_rx_total; + + /* Congestion Control */ + uint64_t stat_cc_poll; + uint64_t stat_cc_empty; + uint64_t stat_cc_total; + + /* Application */ + uint64_t stat_ax_poll; + uint64_t stat_ax_empty; + uint64_t stat_ax_total; + + /* Application context */ + uint64_t stat_ac_poll; + uint64_t stat_ac_empty; + uint64_t stat_ac_total; + + /* Kernel Native Interface */ + uint64_t stat_kni_poll; + uint64_t stat_kni_empty; + uint64_t stat_kni_total; + + /* TCP States */ + uint64_t stat_tcp_poll; + 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; + uint64_t stat_cyc_ax; + 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 +}; + +#endif /* TASSTATS_H_ */ diff --git a/tas/slow/appif.c b/tas/slow/appif.c index 95eb53c4..e1c9eeea 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,16 +173,30 @@ 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) { 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); } } + if (m == 0) + STATS_ADD(slowpath_ctx, ax_empty, 1); + + if (n == 0) + STATS_ADD(slowpath_ctx, ac_empty, 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 2a827bee..cae3b964 100644 --- a/tas/slow/appif_ctx.c +++ b/tas/slow/appif_ctx.c @@ -32,6 +32,8 @@ #include #include +#include +#include #include "internal.h" #include "appif.h" @@ -47,6 +49,19 @@ 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() +{ + 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), + (double) STATS_FETCH(slowpath_ctx, appin_cycles)/ STATS_FETCH(slowpath_ctx, appin_count)); +} +#endif static void appif_ctx_kick(struct app_context *ctx) { @@ -94,10 +109,25 @@ 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); } MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_CONN_OPENED; appif_ctx_kick(ctx); @@ -112,7 +142,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; @@ -128,6 +157,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); @@ -140,14 +170,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; } } @@ -170,6 +201,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); @@ -213,12 +245,16 @@ 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); } MEM_BARRIER(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_ACCEPTED_CONN; appif_ctx_kick(ctx); @@ -232,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; @@ -250,6 +287,14 @@ unsigned appif_ctx_poll(struct application *app, struct app_context *ctx) type = kin->type; MEM_BARRIER(); +#ifdef QUEUE_STATS + if (type != KERNEL_APPOUT_INVALID) + { + STATS_ADD(slowpath_ctx, appin_cycles, (util_rdtsc() - kin->ts)); + STATS_ADD(slowpath_ctx, appin_count, 1); + } +#endif + switch (type) { case KERNEL_APPOUT_INVALID: /* nothing yet */ @@ -263,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: @@ -326,6 +382,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; @@ -334,6 +393,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; @@ -345,16 +405,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; @@ -383,6 +439,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; @@ -391,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; @@ -401,16 +459,16 @@ 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; - } - } + 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"); goto error; @@ -424,9 +482,11 @@ 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(); + kout->ts = util_rdtsc(); kout->type = KERNEL_APPIN_STATUS_CONN_CLOSE; appif_ctx_kick(ctx); return 1; @@ -452,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); @@ -461,6 +522,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; @@ -479,7 +541,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) { @@ -493,7 +554,9 @@ 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); return 1; } diff --git a/tas/slow/cc.c b/tas/slow/cc.c index 9c84b198..263e93ff 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,12 +172,18 @@ 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; } 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; @@ -208,7 +217,7 @@ void cc_conn_init(struct connection *conn) void cc_conn_remove(struct connection *conn) { - struct connection *cp = NULL; + STATS_TS(cc_start); if (next_conn == conn) { next_conn = conn->cc_next; @@ -216,16 +225,18 @@ void cc_conn_remove(struct connection *conn) if (cc_conns == conn) { cc_conns = conn->cc_next; + conn->cc_prev = NULL; } 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; } + 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/internal.h b/tas/slow/internal.h index 2721a088..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; /**@}*/ @@ -527,6 +528,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. */ @@ -541,6 +543,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 3f687e01..43c18b8d 100644 --- a/tas/slow/kernel.c +++ b/tas/slow/kernel.c @@ -31,12 +31,25 @@ #include #include +#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); void flexnic_loadmon(uint32_t cur_ts); +#ifdef DATAPLANE_STATS +extern void dataplane_dump_stats(void); +#endif + +struct kernel_context* slowpath_ctx; + +#ifdef QUEUE_STATS +extern void appqueue_stats_dump(); +extern void kqueue_stats_dump(); +#endif struct timeout_manager timeout_mgr; static int exited = 0; @@ -45,11 +58,89 @@ 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)\n", 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, "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), + 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; uint32_t loadmon_ts = 0; + slowpath_ctx = calloc(1, sizeof(struct kernel_context)); + kernel_notifyfd = eventfd(0, 0); assert(kernel_notifyfd != -1); @@ -113,15 +204,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) { @@ -131,63 +236,72 @@ 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; } - 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, kstats.acks); fflush(stdout); +#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 5e62db4e..30d5f5af 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,6 +85,18 @@ static volatile struct flextcp_pl_ktx **txq_base; static uint32_t txq_len; static uint32_t *txq_tail; +#ifdef QUEUE_STATS +/* Fastpath -> Slowpath queue delay */ +void kqueue_stats_dump() +{ + 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), + ((double) STATS_FETCH(slowpath_ctx, kout_cycles))/STATS_FETCH(slowpath_ctx, kout_count)); +} + +#endif + int nicif_init(void) { rte_hash_crc_init_alg(); @@ -113,6 +128,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) @@ -123,6 +140,10 @@ unsigned nicif_poll(void) ret += (x == -1 ? 0 : 1); } + if (ret == 0) + STATS_ADD(slowpath_ctx, rx_empty, 1); + + STATS_ADD(slowpath_ctx, rx_total, ret); return ret; } @@ -250,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; @@ -264,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; } @@ -341,6 +373,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 +404,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 +535,10 @@ static inline int rxq_poll(void) if (type == FLEXTCP_PL_KRX_INVALID) { return -1; } +#ifdef QUEUE_STATS + STATS_ADD(slowpath_ctx, kout_cycles, (util_rdtsc() - krx->ts)); + STATS_ADD(slowpath_ctx, kout_count, 1); +#endif /* update tail */ tail = tail + 1; diff --git a/tas/slow/tcp.c b/tas/slow/tcp.c index 54e58174..a7dcbb9c 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_empty, 1); + + STATS_ADD(slowpath_ctx, tcp_total, n); } int tcp_open(struct app_context *ctx, uint64_t opaque, uint32_t remote_ip, @@ -149,6 +158,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 +193,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 +206,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"); @@ -323,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"); @@ -343,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; } @@ -390,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; @@ -419,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; } @@ -447,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(); } @@ -510,14 +534,15 @@ 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); } } 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 +604,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 +613,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 +631,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; } @@ -891,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; @@ -961,6 +987,9 @@ static void listener_accept(struct listener *l) if (l->backlog_pos >= l->backlog_len) { l->backlog_pos -= l->backlog_len; } + + 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, @@ -1123,3 +1152,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; +} 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;