From 8fd1a2bfacf928d86fe1b76fc1cd80b3a21cb2cc Mon Sep 17 00:00:00 2001 From: yangchen Date: Thu, 13 Jun 2024 18:31:42 +0800 Subject: [PATCH] optimized latency distribution dotting --- src/common/gazelle_dfx_msg.h | 10 ++++--- src/lstack/core/lstack_lwip.c | 4 +++ src/lstack/core/lstack_protocol_stack.c | 8 +++--- src/lstack/core/lstack_stack_stat.c | 36 +++++++++++++++++++++---- src/lstack/core/lstack_thread_rpc.c | 3 ++- src/lstack/include/lstack_stack_stat.h | 7 ++++- src/lstack/include/lstack_thread_rpc.h | 2 -- src/ltran/ltran_dfx.c | 17 +++++++----- 8 files changed, 63 insertions(+), 24 deletions(-) diff --git a/src/common/gazelle_dfx_msg.h b/src/common/gazelle_dfx_msg.h index cad7978..696daf2 100644 --- a/src/common/gazelle_dfx_msg.h +++ b/src/common/gazelle_dfx_msg.h @@ -69,10 +69,11 @@ enum GAZELLE_STAT_MODE { }; enum GAZELLE_LATENCY_TYPE { - GAZELLE_LATENCY_READ_LWIP, // t0 -> t1 - GAZELLE_LATENCY_READ_APP_CALL, // t1 -> t2 - GAZELLE_LATENCY_READ_LSTACK, // t2 -> t3 - GAZELLE_LATENCY_READ_MAX, // t0 -> t3 + GAZELLE_LATENCY_INTO_MBOX, // t0 -> t1 + GAZELLE_LATENCY_READ_LWIP, // t1 -> t2 + GAZELLE_LATENCY_READ_APP_CALL, // t2 -> t3 + GAZELLE_LATENCY_READ_LSTACK, // t3 -> t4 + GAZELLE_LATENCY_READ_MAX, // t0 -> t4 GAZELLE_LATENCY_WRITE_INTO_RING, // t0 -> t1 GAZELLE_LATENCY_WRITE_LWIP, // t1 -> t2 @@ -80,6 +81,7 @@ enum GAZELLE_LATENCY_TYPE { GAZELLE_LATENCY_WRITE_MAX, // t0 -> t3 GAZELLE_LATENCY_WRITE_RPC_MSG, // rpc_call_send + GAZELLE_LATENCY_RECVMBOX_READY, // ready to read from recvmbox GAZELLE_LATENCY_MAX, }; diff --git a/src/lstack/core/lstack_lwip.c b/src/lstack/core/lstack_lwip.c index 628319c..153c5cc 100644 --- a/src/lstack/core/lstack_lwip.c +++ b/src/lstack/core/lstack_lwip.c @@ -1104,6 +1104,10 @@ void do_lwip_read_recvlist(struct protocol_stack *stack, uint32_t max_num) continue; } + if (get_protocol_stack_group()->latency_start) { + calculate_sock_latency(&sock->stack->latency, sock, GAZELLE_LATENCY_RECVMBOX_READY); + } + ssize_t len = 0; if (NETCONN_IS_UDP(sock)) { len = lwip_recv(sock->conn->callback_arg.socket, NULL, SSIZE_MAX, 0); diff --git a/src/lstack/core/lstack_protocol_stack.c b/src/lstack/core/lstack_protocol_stack.c index 98d6549..74e543d 100644 --- a/src/lstack/core/lstack_protocol_stack.c +++ b/src/lstack/core/lstack_protocol_stack.c @@ -882,10 +882,6 @@ void stack_send(struct rpc_msg *msg) struct protocol_stack *stack = get_protocol_stack(); int replenish_again; - if (get_protocol_stack_group()->latency_start) { - calculate_rpcmsg_latency(&stack->latency, msg, GAZELLE_LATENCY_WRITE_RPC_MSG); - } - struct lwip_sock *sock = get_socket(fd); if (sock == NULL) { msg->result = -1; @@ -893,6 +889,10 @@ void stack_send(struct rpc_msg *msg) return; } + if (get_protocol_stack_group()->latency_start) { + calculate_sock_latency(&stack->latency, sock, GAZELLE_LATENCY_WRITE_RPC_MSG); + } + replenish_again = do_lwip_send(stack, sock->conn->callback_arg.socket, sock, len, 0); if (replenish_again < 0) { __sync_fetch_and_sub(&sock->call_num, 1); diff --git a/src/lstack/core/lstack_stack_stat.c b/src/lstack/core/lstack_stack_stat.c index e430195..a1bd44d 100644 --- a/src/lstack/core/lstack_stack_stat.c +++ b/src/lstack/core/lstack_stack_stat.c @@ -15,6 +15,7 @@ #include #include #include +#include #include "lstack_cfg.h" #include "lstack_ethdev.h" @@ -67,21 +68,46 @@ void time_stamp_transfer_pbuf(struct pbuf *pbuf_old, struct pbuf *pbuf_new) } } -void time_stamp_into_rpcmsg(struct rpc_msg *msg) +void time_stamp_into_rpcmsg(struct lwip_sock *sock) { - msg->time_stamp = get_current_time(); + sock->stamp.rpc_time_stamp = get_current_time(); } -void calculate_rpcmsg_latency(struct gazelle_stack_latency *stack_latency, struct rpc_msg *msg, +void time_stamp_into_recvmbox(struct lwip_sock *sock) +{ + sock->stamp.mbox_time_stamp = get_current_time(); +} + +void time_stamp_record(int fd, struct pbuf *pbuf) +{ + struct lwip_sock *sock = get_socket_by_fd(fd); + + if (get_protocol_stack_group()->latency_start && pbuf != NULL) { + calculate_lstack_latency(&sock->stack->latency, pbuf, GAZELLE_LATENCY_INTO_MBOX, 0); + time_stamp_into_recvmbox(sock); + } +} + +void calculate_sock_latency(struct gazelle_stack_latency *stack_latency, struct lwip_sock *sock, enum GAZELLE_LATENCY_TYPE type) { uint64_t latency; + uint64_t stamp; struct stack_latency *latency_stat; - if (msg == NULL || msg->time_stamp < stack_latency->start_time || type >= GAZELLE_LATENCY_MAX) { + + if (type == GAZELLE_LATENCY_WRITE_RPC_MSG) { + stamp = sock->stamp.rpc_time_stamp; + } else if (type == GAZELLE_LATENCY_RECVMBOX_READY) { + stamp = sock->stamp.mbox_time_stamp; + } else { + return; + } + + if (stamp < stack_latency->start_time) { return; } - latency = get_current_time() - msg->time_stamp; + latency = get_current_time() - stamp; latency_stat = &stack_latency->latency[type]; latency_stat->latency_total += latency; diff --git a/src/lstack/core/lstack_thread_rpc.c b/src/lstack/core/lstack_thread_rpc.c index b98ba84..04bdc3a 100644 --- a/src/lstack/core/lstack_thread_rpc.c +++ b/src/lstack/core/lstack_thread_rpc.c @@ -10,6 +10,7 @@ * See the Mulan PSL v2 for more details. */ #include +#include #include #include "lstack_log.h" @@ -471,7 +472,7 @@ int32_t rpc_call_send(rpc_queue *queue, int fd, const void *buf, size_t len, int } if (get_protocol_stack_group()->latency_start) { - time_stamp_into_rpcmsg(msg); + time_stamp_into_rpcmsg(get_socket_by_fd(fd)); } msg->args[MSG_ARG_0].i = fd; diff --git a/src/lstack/include/lstack_stack_stat.h b/src/lstack/include/lstack_stack_stat.h index 939189e..f0d3d5d 100644 --- a/src/lstack/include/lstack_stack_stat.h +++ b/src/lstack/include/lstack_stack_stat.h @@ -22,11 +22,14 @@ struct protocol_stack; enum GAZELLE_LATENCY_TYPE; enum GAZELLE_STAT_MODE; struct gazelle_stat_msg_request; +struct lwip_sock; void calculate_lstack_latency(struct gazelle_stack_latency *stack_latency, const struct pbuf *pbuf, enum GAZELLE_LATENCY_TYPE type, uint64_t time_record); void calculate_rpcmsg_latency(struct gazelle_stack_latency *stack_latency, struct rpc_msg *msg, enum GAZELLE_LATENCY_TYPE type); +void calculate_sock_latency(struct gazelle_stack_latency *stack_latency, struct lwip_sock *sock, + enum GAZELLE_LATENCY_TYPE type); void stack_stat_init(void); int handle_stack_cmd(int fd, struct gazelle_stat_msg_request *msg); int handle_dpdk_cmd(int fd, enum GAZELLE_STAT_MODE stat_mode); @@ -35,6 +38,8 @@ void lstack_get_low_power_info(struct gazelle_stat_low_power_info *low_power_inf void unregister_wakeup(struct protocol_stack *stack, struct wakeup_poll *wakeup); void lstack_calculate_aggregate(int type, uint32_t len); void time_stamp_transfer_pbuf(struct pbuf *pbuf_old, struct pbuf *pbuf_new); -void time_stamp_into_rpcmsg(struct rpc_msg *msg); +void time_stamp_into_rpcmsg(struct lwip_sock *sock); +void time_stamp_into_recvmbox(struct lwip_sock *sock); +void time_stamp_record(int fd, struct pbuf *pbuf); #endif /* GAZELLE_STACK_STAT_H */ diff --git a/src/lstack/include/lstack_thread_rpc.h b/src/lstack/include/lstack_thread_rpc.h index 0c51848..276ebb2 100644 --- a/src/lstack/include/lstack_thread_rpc.h +++ b/src/lstack/include/lstack_thread_rpc.h @@ -58,8 +58,6 @@ struct rpc_msg { rpc_msg_func func; /* msg handle func hook */ union rpc_msg_arg args[RPM_MSG_ARG_SIZE]; /* resolve by type */ - - uint64_t time_stamp; /* rpc_call_* start time */ }; static inline void rpc_queue_init(rpc_queue *queue) diff --git a/src/ltran/ltran_dfx.c b/src/ltran/ltran_dfx.c index 319f7cd..4351891 100644 --- a/src/ltran/ltran_dfx.c +++ b/src/ltran/ltran_dfx.c @@ -899,11 +899,13 @@ static void gazelle_print_lstack_stat_latency(void *buf, const struct gazelle_st printf("Statistics of lstack latency pkts min(us) max(us) average(us)\n"); printf("Recv:\n"); - printf("range: t0--->t1\n%s", res[GAZELLE_LATENCY_READ_LWIP].latency_stat_result); - printf("range: t1--->t2\n%s", res[GAZELLE_LATENCY_READ_APP_CALL].latency_stat_result); - printf("range: t2--->t3\n%s", res[GAZELLE_LATENCY_READ_LSTACK].latency_stat_result); - printf("range: t0--->t3\n%s", res[GAZELLE_LATENCY_READ_MAX].latency_stat_result); - printf("t0: read from nic t1: into recv ring t2: app read start t3: app read end\n"); + + printf("range: t0--->t1\n%s", res[GAZELLE_LATENCY_INTO_MBOX].latency_stat_result); + printf("range: t1--->t2\n%s", res[GAZELLE_LATENCY_READ_LWIP].latency_stat_result); + printf("range: t2--->t3\n%s", res[GAZELLE_LATENCY_READ_APP_CALL].latency_stat_result); + printf("range: t3--->t4\n%s", res[GAZELLE_LATENCY_READ_LSTACK].latency_stat_result); + printf("range: t0--->t4\n%s", res[GAZELLE_LATENCY_READ_MAX].latency_stat_result); + printf("t0: read from nic t1: into recvmbox t2: into recvring t3: app read start t4: app read end\n"); printf("Send:\n"); printf("range: t0--->t1\n%s", res[GAZELLE_LATENCY_WRITE_INTO_RING].latency_stat_result); @@ -912,8 +914,9 @@ static void gazelle_print_lstack_stat_latency(void *buf, const struct gazelle_st printf("range: t0--->t3\n%s", res[GAZELLE_LATENCY_WRITE_MAX].latency_stat_result); printf("t0: app send t1: into send ring t2: out of send ring t3: send to nic\n"); - printf("Rpc:\n"); - printf("rpc_call_send \n%s", res[GAZELLE_LATENCY_WRITE_RPC_MSG].latency_stat_result); + printf("Others:\n"); + printf("rpc_call_send\n%s", res[GAZELLE_LATENCY_WRITE_RPC_MSG].latency_stat_result); + printf("ready to read from recvmbox\n%s", res[GAZELLE_LATENCY_RECVMBOX_READY].latency_stat_result); free(res); } -- 2.33.0