From 286e9a267e2d106d05c5fec80a932ed605d4b006 Mon Sep 17 00:00:00 2001
From: yangchen <yangchen145@huawei.com>
Date: Mon, 1 Apr 2024 09:15:56 +0800
Subject: [PATCH] add latency nodes: READ_APP_CALL & WRITE_RPC_MSG

---
 src/common/dpdk_common.h                |  2 +
 src/common/gazelle_dfx_msg.h            | 18 ++++---
 src/lstack/core/lstack_lwip.c           | 23 ++++++---
 src/lstack/core/lstack_protocol_stack.c |  4 ++
 src/lstack/core/lstack_stack_stat.c     | 68 +++++++++++++++++++++----
 src/lstack/core/lstack_thread_rpc.c     |  8 ++-
 src/lstack/include/lstack_stack_stat.h  |  4 ++
 src/lstack/include/lstack_thread_rpc.h  |  2 +
 src/lstack/netif/lstack_ethdev.c        |  2 +-
 src/ltran/ltran_dfx.c                   | 21 ++++++--
 10 files changed, 124 insertions(+), 28 deletions(-)

diff --git a/src/common/dpdk_common.h b/src/common/dpdk_common.h
index cb41747..7a05342 100644
--- a/src/common/dpdk_common.h
+++ b/src/common/dpdk_common.h
@@ -19,6 +19,7 @@
 #include <lwip/pbuf.h>
 #include <lwip/dpdk_version.h>
 
+#include "gazelle_dfx_msg.h"
 #include "gazelle_opt.h"
 
 #define GAZELLE_KNI_NAME                     "kni"   // will be removed during dpdk update
@@ -33,6 +34,7 @@
 struct latency_timestamp {
         uint64_t stamp; // time stamp
         uint64_t check; // just for later vaild check
+        uint16_t stamp_seg[GAZELLE_LATENCY_MAX]; // time stamp segment
         uint16_t type;  // latency type
 };
 struct mbuf_private {
diff --git a/src/common/gazelle_dfx_msg.h b/src/common/gazelle_dfx_msg.h
index d7ba80f..c2ff760 100644
--- a/src/common/gazelle_dfx_msg.h
+++ b/src/common/gazelle_dfx_msg.h
@@ -62,17 +62,23 @@ enum GAZELLE_STAT_MODE {
     GAZELLE_STAT_FAULT_INJECT_SET,
     GAZELLE_STAT_FAULT_INJECT_UNSET,
 #endif /* GAZELLE_FAULT_INJECT_ENABLE */
-    
+
     GAZELLE_STAT_MODE_MAX,
 };
 
 enum GAZELLE_LATENCY_TYPE {
-    GAZELLE_LATENCY_READ_LWIP,
-    GAZELLE_LATENCY_READ_LSTACK,
-    GAZELLE_LATENCY_READ_MAX,
+    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_WRITE_INTO_RING, // t0 -> t1
+    GAZELLE_LATENCY_WRITE_LWIP,      // t1 -> t2
+    GAZELLE_LATENCY_WRITE_LSTACK,    // t2 -> t3
+    GAZELLE_LATENCY_WRITE_MAX,       // t0 -> t3
+
+    GAZELLE_LATENCY_WRITE_RPC_MSG,   // rpc_call_send
 
-    GAZELLE_LATENCY_WRITE_LWIP,
-    GAZELLE_LATENCY_WRITE_LSTACK,
     GAZELLE_LATENCY_MAX,
 };
 
diff --git a/src/lstack/core/lstack_lwip.c b/src/lstack/core/lstack_lwip.c
index a604a62..1d27938 100644
--- a/src/lstack/core/lstack_lwip.c
+++ b/src/lstack/core/lstack_lwip.c
@@ -259,12 +259,12 @@ struct pbuf *do_lwip_get_from_sendring(struct lwip_sock *sock, uint16_t remain_s
         gazelle_ring_sc_dequeue(sock->send_ring, (void **)&pbuf_used, size);
 
         for (uint32_t i = 0; get_protocol_stack_group()->latency_start && i < size; i++) {
-            calculate_lstack_latency(&sock->stack->latency, pbuf_used[i], GAZELLE_LATENCY_WRITE_LWIP);
+            calculate_lstack_latency(&sock->stack->latency, pbuf_used[i], GAZELLE_LATENCY_WRITE_LWIP, 0);
         }
     }
 
     if (get_protocol_stack_group()->latency_start) {
-        calculate_lstack_latency(&sock->stack->latency, pbuf, GAZELLE_LATENCY_WRITE_LWIP);
+        calculate_lstack_latency(&sock->stack->latency, pbuf, GAZELLE_LATENCY_WRITE_LWIP, 0);
     }
 
     sock->send_pre_del = pbuf;
@@ -362,6 +362,12 @@ static inline ssize_t app_buff_write(struct lwip_sock *sock, void *buf, size_t l
         }
     }
 
+    for (int i = 0; get_protocol_stack_group()->latency_start && i < write_num; i++) {
+        if (pbufs[i] != NULL) {
+            calculate_lstack_latency(&sock->stack->latency, pbufs[i], GAZELLE_LATENCY_WRITE_INTO_RING, 0);
+        }
+    }
+
     gazelle_ring_read_over(sock->send_ring);
 
     sock->remain_len = MBUF_MAX_DATA_LEN - pbufs[write_num - 1]->len;
@@ -611,7 +617,7 @@ ssize_t do_lwip_read_from_lwip(struct lwip_sock *sock, int32_t flags, u8_t apifl
 
     for (uint32_t i = 0; get_protocol_stack_group()->latency_start && i < read_count; i++) {
         if (pbufs[i] != NULL) {
-            calculate_lstack_latency(&sock->stack->latency, pbufs[i], GAZELLE_LATENCY_READ_LWIP);
+            calculate_lstack_latency(&sock->stack->latency, pbufs[i], GAZELLE_LATENCY_READ_LWIP, 0);
         }
     }
 
@@ -870,6 +876,7 @@ static bool recv_break_for_err(struct lwip_sock *sock)
 static int recv_ring_get_one(struct lwip_sock *sock, bool noblock, struct pbuf **pbuf)
 {
     int32_t expect = 1; // only get one pbuf
+    uint64_t time_stamp = get_current_time();
 
     if (sock->recv_lastdata != NULL) {
         *pbuf = sock->recv_lastdata;
@@ -888,7 +895,11 @@ static int recv_ring_get_one(struct lwip_sock *sock, bool noblock, struct pbuf *
             noblock = true;
         }
     }
-    
+
+    if (get_protocol_stack_group()->latency_start) {
+        calculate_lstack_latency(&sock->stack->latency, *pbuf, GAZELLE_LATENCY_READ_APP_CALL, time_stamp);
+    }
+
     return 0;
 }
 
@@ -954,7 +965,7 @@ static ssize_t recv_ring_tcp_read(struct lwip_sock *sock, void *buf, size_t len,
             }
 
             if (get_protocol_stack_group()->latency_start) {
-                calculate_lstack_latency(&sock->stack->latency, pbuf, GAZELLE_LATENCY_READ_LSTACK);
+                calculate_lstack_latency(&sock->stack->latency, pbuf, GAZELLE_LATENCY_READ_LSTACK, 0);
             }
 
             gazelle_ring_read_over(sock->recv_ring);
@@ -1001,7 +1012,7 @@ static ssize_t recv_ring_udp_read(struct lwip_sock *sock, void *buf, size_t len,
         sock->wakeup->stat.app_read_cnt++;
     }
     if (get_protocol_stack_group()->latency_start) {
-        calculate_lstack_latency(&sock->stack->latency, pbuf, GAZELLE_LATENCY_READ_LSTACK);
+        calculate_lstack_latency(&sock->stack->latency, pbuf, GAZELLE_LATENCY_READ_LSTACK, 0);
     }
 
     return copy_len;
diff --git a/src/lstack/core/lstack_protocol_stack.c b/src/lstack/core/lstack_protocol_stack.c
index 7c4af64..079bba0 100644
--- a/src/lstack/core/lstack_protocol_stack.c
+++ b/src/lstack/core/lstack_protocol_stack.c
@@ -876,6 +876,10 @@ 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;
diff --git a/src/lstack/core/lstack_stack_stat.c b/src/lstack/core/lstack_stack_stat.c
index 3e016b7..80d4998 100644
--- a/src/lstack/core/lstack_stack_stat.c
+++ b/src/lstack/core/lstack_stack_stat.c
@@ -62,16 +62,53 @@ void time_stamp_transfer_pbuf(struct pbuf *pbuf_old, struct pbuf *pbuf_new)
     lt_new->stamp = lt_old->stamp;
     lt_new->check = lt_old->check;
     lt_new->type = lt_old->type;
+    for (int i = 0; i < GAZELLE_LATENCY_MAX; i++) {
+        lt_new->stamp_seg[i] = lt_old->stamp_seg[i];
+    }
 }
 
-void calculate_lstack_latency(struct gazelle_stack_latency *stack_latency, const struct pbuf *pbuf,
+void time_stamp_into_rpcmsg(struct rpc_msg *msg)
+{
+    msg->time_stamp = get_current_time();
+}
+
+void calculate_rpcmsg_latency(struct gazelle_stack_latency *stack_latency, struct rpc_msg *msg,
     enum GAZELLE_LATENCY_TYPE type)
 {
     uint64_t latency;
-    uint16_t lt_type;
-    const struct latency_timestamp *lt;
+    struct stack_latency *latency_stat;
+    if (msg == NULL || msg->time_stamp < stack_latency->start_time || type >= GAZELLE_LATENCY_MAX) {
+        return;
+    }
+
+    latency = get_current_time() - msg->time_stamp;
+    latency_stat = &stack_latency->latency[type];
+
+    latency_stat->latency_total += latency;
+    latency_stat->latency_max = (latency_stat->latency_max > latency) ? latency_stat->latency_max : latency;
+    latency_stat->latency_min = (latency_stat->latency_min < latency) ? latency_stat->latency_min : latency;
+    latency_stat->latency_pkts++;
+}
+
+void calculate_latency_stat(struct gazelle_stack_latency *stack_latency, uint64_t latency,
+    enum GAZELLE_LATENCY_TYPE type)
+{
     struct stack_latency *latency_stat;
 
+    latency_stat = &stack_latency->latency[type];
+    latency_stat->latency_total += latency;
+    latency_stat->latency_max = (latency_stat->latency_max > latency) ? latency_stat->latency_max : latency;
+    latency_stat->latency_min = (latency_stat->latency_min < latency) ? latency_stat->latency_min : latency;
+    latency_stat->latency_pkts++;
+}
+
+void calculate_lstack_latency(struct gazelle_stack_latency *stack_latency, const struct pbuf *pbuf,
+    enum GAZELLE_LATENCY_TYPE type, uint64_t time_record)
+{
+    uint64_t latency;
+    uint16_t lt_type;
+    struct latency_timestamp *lt;
+
     if (pbuf == NULL || type >= GAZELLE_LATENCY_MAX) {
         return;
     }
@@ -82,13 +119,26 @@ void calculate_lstack_latency(struct gazelle_stack_latency *stack_latency, const
         return;
     }
 
-    latency = get_current_time() - lt->stamp;
-    latency_stat = &stack_latency->latency[type];
+    if (time_record == 0) {
+        lt->stamp_seg[type] = get_current_time() - lt->stamp;
+    } else {
+        lt->stamp_seg[type] = time_record > (lt->stamp_seg[type - 1] + lt->stamp) ?
+            (time_record - lt->stamp) : lt->stamp_seg[type - 1];
+    }
 
-    latency_stat->latency_total += latency;
-    latency_stat->latency_max = (latency_stat->latency_max > latency) ? latency_stat->latency_max : latency;
-    latency_stat->latency_min = (latency_stat->latency_min < latency) ? latency_stat->latency_min : latency;
-    latency_stat->latency_pkts++;
+    latency = lt->stamp_seg[type];
+    if (((lt_type == GAZELLE_LATENCY_RD && type > GAZELLE_LATENCY_READ_LWIP) ||
+        (lt_type == GAZELLE_LATENCY_WR && type > GAZELLE_LATENCY_WRITE_INTO_RING)) &&
+        latency >= lt->stamp_seg[type - 1]) {
+        latency -= lt->stamp_seg[type - 1];
+    }
+
+    /* calculate the time of the entire read/write process */
+    if (type == GAZELLE_LATENCY_READ_MAX - 1 || type == GAZELLE_LATENCY_WRITE_MAX - 1) {
+        calculate_latency_stat(stack_latency, lt->stamp_seg[type], type + 1);
+    }
+
+    calculate_latency_stat(stack_latency, latency, type);
 }
 
 void lstack_calculate_aggregate(int type, uint32_t len)
diff --git a/src/lstack/core/lstack_thread_rpc.c b/src/lstack/core/lstack_thread_rpc.c
index 20c5a43..30bd827 100644
--- a/src/lstack/core/lstack_thread_rpc.c
+++ b/src/lstack/core/lstack_thread_rpc.c
@@ -15,6 +15,8 @@
 #include "lstack_log.h"
 #include "lstack_dpdk.h"
 #include "lstack_rpc_proc.h"
+#include "lstack_stack_stat.h"
+#include "lstack_protocol_stack.h"
 #include "lstack_thread_rpc.h"
 
 static PER_THREAD struct rpc_msg_pool *g_rpc_pool = NULL;
@@ -467,11 +469,15 @@ int32_t rpc_call_send(rpc_queue *queue, int fd, const void *buf, size_t len, int
         return -1;
     }
 
+    if (get_protocol_stack_group()->latency_start) {
+        time_stamp_into_rpcmsg(msg);
+    }
+
     msg->args[MSG_ARG_0].i = fd;
     msg->args[MSG_ARG_1].size = len;
     msg->args[MSG_ARG_2].i = flags;
     msg->sync_flag = 0;
-    
+
     rpc_call(queue, msg);
 
     return 0;
diff --git a/src/lstack/include/lstack_stack_stat.h b/src/lstack/include/lstack_stack_stat.h
index 87951aa..f901982 100644
--- a/src/lstack/include/lstack_stack_stat.h
+++ b/src/lstack/include/lstack_stack_stat.h
@@ -15,6 +15,7 @@
 
 struct gazelle_stack_latency;
 struct pbuf;
+struct rpc_msg;
 struct gazelle_stat_low_power_info;
 struct wakeup_poll;
 struct protocol_stack;
@@ -22,6 +23,8 @@ enum GAZELLE_LATENCY_TYPE;
 enum GAZELLE_STAT_MODE;
 
 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 stack_stat_init(void);
 int handle_stack_cmd(int fd, enum GAZELLE_STAT_MODE stat_mode);
@@ -31,5 +34,6 @@ 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);
 
 #endif /* GAZELLE_STACK_STAT_H */
diff --git a/src/lstack/include/lstack_thread_rpc.h b/src/lstack/include/lstack_thread_rpc.h
index 4d89604..8e97c11 100644
--- a/src/lstack/include/lstack_thread_rpc.h
+++ b/src/lstack/include/lstack_thread_rpc.h
@@ -60,6 +60,8 @@ 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/lstack/netif/lstack_ethdev.c b/src/lstack/netif/lstack_ethdev.c
index 8fe11c4..23edc19 100644
--- a/src/lstack/netif/lstack_ethdev.c
+++ b/src/lstack/netif/lstack_ethdev.c
@@ -224,7 +224,7 @@ static err_t eth_dev_output(struct netif *netif, struct pbuf *pbuf)
         rte_mbuf_refcnt_update(mbuf, 1);
 
         if (get_protocol_stack_group()->latency_start) {
-            calculate_lstack_latency(&stack->latency, pbuf, GAZELLE_LATENCY_WRITE_LSTACK);
+            calculate_lstack_latency(&stack->latency, pbuf, GAZELLE_LATENCY_WRITE_LSTACK, 0);
         }
         pbuf = pbuf->next;
     }
diff --git a/src/ltran/ltran_dfx.c b/src/ltran/ltran_dfx.c
index 91c6063..79c172b 100644
--- a/src/ltran/ltran_dfx.c
+++ b/src/ltran/ltran_dfx.c
@@ -881,11 +881,22 @@ static void gazelle_print_lstack_stat_latency(void *buf, const struct gazelle_st
     gazelle_show_latency_result_total(buf, req_msg, res);
 
     printf("Statistics of lstack latency          pkts        min(us)     max(us)     average(us)\n");
-    printf("range: t0--->t3\n%s", res[GAZELLE_LATENCY_READ_LSTACK].latency_stat_result);
-    printf("range: t0--->t2\n%s", res[GAZELLE_LATENCY_READ_LWIP].latency_stat_result);
-    printf("range: t3--->t0\n%s", res[GAZELLE_LATENCY_WRITE_LSTACK].latency_stat_result);
-    printf("range: t2--->t0\n%s", res[GAZELLE_LATENCY_WRITE_LWIP].latency_stat_result);
-    printf("t0:read form/send to nic  t1:into/out of lstask queue  t2:into/out of app queue t3:app read/send\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("Send:\n");
+    printf("range: t0--->t1\n%s", res[GAZELLE_LATENCY_WRITE_INTO_RING].latency_stat_result);
+    printf("range: t1--->t2\n%s", res[GAZELLE_LATENCY_WRITE_LWIP].latency_stat_result);
+    printf("range: t2--->t3\n%s", res[GAZELLE_LATENCY_WRITE_LSTACK].latency_stat_result);
+    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);
 
     free(res);
 }
-- 
2.33.0