log: default add time info(seconds) print.

Add and a api `mtl_set_log_prefix_formatter` to customize the log prefix formatter. App add "--log_time_ms" option to switch to a formatter with ms time accuracy. Signed-off-by: Frank Du <[email protected]>
OpenVisualCloud · Nov 10, 2023 · 8c1c1d8 · 8c1c1d8
1 parent 2b05554
commit 8c1c1d8
Show file tree

Hide file tree

Showing 6 changed files with 125 additions and 54 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -19,6 +19,7 @@
 * rtcp: add retransmit packet support for st20 sessions, see STxx_RX_FLAG_ENABLE_RTCP.
 * st2110: add ssrc support.
 * rss: add multi-core support.
+* log: default add time info print, and a api `mtl_set_log_prefix_formatter` to customize the log prefix formatter.
 
 ## Changelog for 23.08
 

diff --git a/app/src/args.c b/app/src/args.c
@@ -74,6 +74,7 @@ enum st_args_cmd {
   ST_ARG_RX_POOL_DATA_SIZE,
   ST_ARG_LOG_LEVEL,
   ST_ARG_LOG_FILE,
+  ST_ARG_LOG_TIME_MS,
   ST_ARG_NB_TX_DESC,
   ST_ARG_NB_RX_DESC,
   ST_ARG_DMA_DEV,
@@ -120,6 +121,17 @@ enum st_args_cmd {
   ST_ARG_MAX,
 };
 
+static void log_prefix_time_ms(char* buf, size_t sz) {
+  struct timespec ts;
+  struct tm tm;
+  char time_s_buf[64];
+
+  clock_gettime(CLOCK_REALTIME, &ts);
+  localtime_r(&ts.tv_sec, &tm);
+  strftime(time_s_buf, sizeof(time_s_buf), "%Y-%m-%d %H:%M:%S", &tm);
+  snprintf(buf, sz, "%s.%" PRIu64 ", ", time_s_buf, ts.tv_nsec / NS_PER_MS);
+}
+
 /*
 struct option {
    const char *name;
@@ -185,6 +197,7 @@ static struct option st_app_args_options[] = {
     {"promiscuous", no_argument, 0, ST_ARG_NIC_RX_PROMISCUOUS},
     {"log_level", required_argument, 0, ST_ARG_LOG_LEVEL},
     {"log_file", required_argument, 0, ST_ARG_LOG_FILE},
+    {"log_time_ms", no_argument, 0, ST_ARG_LOG_TIME_MS},
     {"ptp", no_argument, 0, ST_ARG_LIB_PTP},
     {"phc2sys", no_argument, 0, ST_ARG_LIB_PHC2SYS},
     {"ptp_sync_sys", no_argument, 0, ST_ARG_LIB_PTP_SYNC_SYS},
@@ -577,6 +590,9 @@ int st_app_parse_args(struct st_app_context* ctx, struct mtl_init_params* p, int
       case ST_ARG_LOG_FILE:
         st_set_mtl_log_file(ctx, optarg);
         break;
+      case ST_ARG_LOG_TIME_MS:
+        mtl_set_log_prefix_formatter(log_prefix_time_ms);
+        break;
       case ST_ARG_NB_TX_DESC:
         p->nb_tx_desc = atoi(optarg);
         break;

diff --git a/doc/run.md b/doc/run.md
@@ -345,8 +345,9 @@ packet egresses from the sender.
 --dhcp                               : debug option, enable DHCP for all ports.
 --virtio_user                        : debug option, enable virtio_user ports for control plane packets. Linux only, need to set capability for the app before running, `sudo setcap 'cap_net_admin+ep' ./build/app/RxTxApp`.
 --phc2sys                            : debug option, enable the built-in phc2sys function to sync the system time to our internal synced PTP time. Linux only, need to set capability for the app before running, `sudo setcap 'cap_sys_time+ep' ./build/app/RxTxApp`.
---ptp_sync_sys                       : debug option, enabling the synchronization of PTP time from MTL to the system time. On Linux, need to set capability for the app before running, `sudo setcap 'cap_sys_time+ep' ./build/app/RxTxApp`.
+--ptp_sync_sys                       : debug option, enabling the synchronization of PTP time from MTL to the system time in the application. On Linux, need to set capability for the app before running, `sudo setcap 'cap_sys_time+ep' ./build/app/RxTxApp`.
 --rss_sch_nb <number>                : debug option, set the schedulers(lcores) number for the RSS dispatch.
+--log_time_ms                        : debug option, enable a ms accuracy log printer by the api mtl_set_log_prefix_formatter.
 ```
 
 ## 6. Tests

diff --git a/include/mtl_api.h b/include/mtl_api.h
@@ -882,6 +882,27 @@ int mtl_set_log_level(mtl_handle mt, enum mtl_log_level level);
  */
 enum mtl_log_level mtl_get_log_level(mtl_handle mt);
 
+/**
+ * Set the log prefix user customized formatter.
+ *
+ * A example formatter is like below:
+ *   static void log_default_prefix(char* buf, size_t sz) {
+ *     time_t now;
+ *     struct tm tm;
+ *
+ *     time(&now);
+ *     localtime_r(&now, &tm);
+ *     strftime(buf, sz, "%Y-%m-%d %H:%M:%S, ", &tm);
+ *   }
+ *
+ * @param log_prefix_format_func
+ *   The log level define.
+ * @return
+ *   - 0: Success.
+ *   - <0: Error code.
+ */
+int mtl_set_log_prefix_formatter(void (*log_prefix_formatter)(char* buf, size_t buf_sz));
+
 /**
  * Enable or disable sleep mode for sch.
  *

diff --git a/lib/src/mt_log.h b/lib/src/mt_log.h
@@ -7,14 +7,23 @@
 #ifndef _MT_LIB_LOG_HEAD_H_
 #define _MT_LIB_LOG_HEAD_H_
 
+extern void (*g_mt_log_prefix_format)(char* buf, size_t sz);
+
 /* log define */
 #define RTE_LOGTYPE_MT (RTE_LOGTYPE_USER1)
 
+#define MT_LOG(l, t, format, ...)                        \
+  do {                                                   \
+    char __prefix[64];                                   \
+    g_mt_log_prefix_format(__prefix, sizeof(__prefix));  \
+    RTE_LOG(l, t, "%s" format, __prefix, ##__VA_ARGS__); \
+  } while (0)
+
 /* Debug-level messages */
 #ifdef DEBUG
-#define dbg(...)                     \
-  do {                               \
-    RTE_LOG(DEBUG, MT, __VA_ARGS__); \
+#define dbg(...)                    \
+  do {                              \
+    MT_LOG(DEBUG, MT, __VA_ARGS__); \
   } while (0)
 #else
 #define dbg(...) \
@@ -23,73 +32,73 @@
 #endif
 
 /* Informational */
-#define info(...)                   \
-  do {                              \
-    RTE_LOG(INFO, MT, __VA_ARGS__); \
+#define info(...)                  \
+  do {                             \
+    MT_LOG(INFO, MT, __VA_ARGS__); \
   } while (0)
-#define info_once(...)                \
-  do {                                \
-    static bool once = true;          \
-    if (once) {                       \
-      RTE_LOG(INFO, MT, __VA_ARGS__); \
-      once = false;                   \
-    }                                 \
+#define info_once(...)               \
+  do {                               \
+    static bool once = true;         \
+    if (once) {                      \
+      MT_LOG(INFO, MT, __VA_ARGS__); \
+      once = false;                  \
+    }                                \
   } while (0)
 
 /* Normal but significant condition. */
-#define notice(...)                   \
-  do {                                \
-    RTE_LOG(NOTICE, MT, __VA_ARGS__); \
+#define notice(...)                  \
+  do {                               \
+    MT_LOG(NOTICE, MT, __VA_ARGS__); \
   } while (0)
-#define notice_once(...)                \
-  do {                                  \
-    static bool once = true;            \
-    if (once) {                         \
-      RTE_LOG(NOTICE, MT, __VA_ARGS__); \
-      once = false;                     \
-    }                                   \
+#define notice_once(...)               \
+  do {                                 \
+    static bool once = true;           \
+    if (once) {                        \
+      MT_LOG(NOTICE, MT, __VA_ARGS__); \
+      once = false;                    \
+    }                                  \
   } while (0)
 
 /* Warning conditions. */
-#define warn(...)                               \
-  do {                                          \
-    RTE_LOG(WARNING, MT, "Warn: " __VA_ARGS__); \
+#define warn(...)                              \
+  do {                                         \
+    MT_LOG(WARNING, MT, "Warn: " __VA_ARGS__); \
   } while (0)
-#define warn_once(...)                            \
-  do {                                            \
-    static bool once = true;                      \
-    if (once) {                                   \
-      RTE_LOG(WARNING, MT, "Warn: " __VA_ARGS__); \
-      once = false;                               \
-    }                                             \
+#define warn_once(...)                           \
+  do {                                           \
+    static bool once = true;                     \
+    if (once) {                                  \
+      MT_LOG(WARNING, MT, "Warn: " __VA_ARGS__); \
+      once = false;                              \
+    }                                            \
   } while (0)
 
 /* Error conditions. */
-#define err(...)                             \
-  do {                                       \
-    RTE_LOG(ERR, MT, "Error: " __VA_ARGS__); \
+#define err(...)                            \
+  do {                                      \
+    MT_LOG(ERR, MT, "Error: " __VA_ARGS__); \
   } while (0)
-#define err_once(...)                          \
-  do {                                         \
-    static bool once = true;                   \
-    if (once) {                                \
-      RTE_LOG(ERR, MT, "Error: " __VA_ARGS__); \
-      once = false;                            \
-    }                                          \
+#define err_once(...)                         \
+  do {                                        \
+    static bool once = true;                  \
+    if (once) {                               \
+      MT_LOG(ERR, MT, "Error: " __VA_ARGS__); \
+      once = false;                           \
+    }                                         \
   } while (0)
 
 /* Critical conditions		*/
-#define critical(...)               \
-  do {                              \
-    RTE_LOG(CRIT, MT, __VA_ARGS__); \
+#define critical(...)              \
+  do {                             \
+    MT_LOG(CRIT, MT, __VA_ARGS__); \
   } while (0)
-#define critical_once(...)            \
-  do {                                \
-    static bool once = true;          \
-    if (once) {                       \
-      RTE_LOG(CRIT, MT, __VA_ARGS__); \
-      once = false;                   \
-    }                                 \
+#define critical_once(...)           \
+  do {                               \
+    static bool once = true;         \
+    if (once) {                      \
+      MT_LOG(CRIT, MT, __VA_ARGS__); \
+      once = false;                  \
+    }                                \
   } while (0)
 
 #endif
diff --git a/lib/src/mt_main.c b/lib/src/mt_main.c
@@ -23,6 +23,18 @@
 #include "st2110/pipeline/st_plugin.h"
 #include "udp/udp_rxq.h"
 
+static void log_default_prefix(char* buf, size_t sz) {
+  time_t now;
+  struct tm tm;
+
+  time(&now);
+  localtime_r(&now, &tm);
+  strftime(buf, sz, "%Y-%m-%d %H:%M:%S, ", &tm);
+}
+
+/* default log prefix format */
+void (*g_mt_log_prefix_format)(char* buf, size_t sz) = log_default_prefix;
+
 enum mtl_port mt_port_by_id(struct mtl_main_impl* impl, uint16_t port_id) {
   int num_ports = mt_num_ports(impl);
   int i;
@@ -1309,3 +1321,14 @@ bool mtl_pmd_is_dpdk_based(mtl_handle mt, enum mtl_port port) {
 int mtl_thread_setname(pthread_t tid, const char* name) {
   return rte_thread_setname(tid, name);
 }
+
+int mtl_set_log_prefix_formatter(void (*log_prefix_formatter)(char* buf, size_t buf_sz)) {
+  if (log_prefix_formatter) {
+    info("%s, new formatter %p\n", __func__, log_prefix_formatter);
+    g_mt_log_prefix_format = log_prefix_formatter;
+  } else {
+    info("%s, switch to default as user prefix is null\n", __func__);
+    g_mt_log_prefix_format = log_default_prefix;
+  }
+  return 0;
+}