From f5bf3b09371f079e66a905bdda37771d56f17e33 Mon Sep 17 00:00:00 2001 From: bowenliu Date: Sat, 20 Apr 2024 15:48:38 +0800 Subject: [PATCH] =?UTF-8?q?DMS=20TRACE=E8=83=BD=E5=8A=9BCBB=E9=80=82?= =?UTF-8?q?=E9=85=8D?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- src/cm_defines/cm_error.c | 3 ++ src/cm_mes/mes_interface_impl.c | 6 +++- src/cm_mes/mes_tcp.c | 9 ++--- src/cm_utils/cm_log.c | 16 ++++++++- src/cm_utils/cm_log.h | 63 +++++++++++++++++++++++++++++++++ 5 files changed, 91 insertions(+), 6 deletions(-) diff --git a/src/cm_defines/cm_error.c b/src/cm_defines/cm_error.c index d76a94c..9c37103 100644 --- a/src/cm_defines/cm_error.c +++ b/src/cm_defines/cm_error.c @@ -174,6 +174,7 @@ void cm_reset_error(void) { g_tls_error.code = 0; g_tls_error.message[0] = '\0'; + CM_SS_DYN_TRC_SET_TRACE_FLAG(CM_FALSE); } int cm_get_os_error(void) @@ -278,6 +279,8 @@ void cm_set_error(const char *file, uint32 line, cm_errno_t code, const char *fo va_list args; va_start(args, format); + CM_SS_DYN_TRC_SET_TRACE_FLAG(CM_TRUE); + if (g_error_handler == NULL) { cm_set_error_default(code, format, args); } else { diff --git a/src/cm_mes/mes_interface_impl.c b/src/cm_mes/mes_interface_impl.c index da48366..f6be6e6 100644 --- a/src/cm_mes/mes_interface_impl.c +++ b/src/cm_mes/mes_interface_impl.c @@ -318,6 +318,8 @@ int mes_get_response(ruid_type ruid, mes_msg_t* response, int timeout_ms) LOG_DEBUG_INF("[mes]room wait canceled by caller, ruid%llu:(%llu-%llu), room(%llu-%llu)", (uint64)ruid, (uint64)MES_RUID_GET_RID(ruid), (uint64)MES_RUID_GET_RSN(ruid), (uint64)room->room_index, (uint64)room->rsn); + LOG_DYNAMIC_TRACE("[MES][%llu][%llu-%llu]wait canceled", + (uint64)ruid, room->room_index, room->rsn); mes_protect_when_timeout(room); mes_free_room(room); return CM_SUCCESS; @@ -330,7 +332,9 @@ int mes_get_response(ruid_type ruid, mes_msg_t* response, int timeout_ms) // when timeout the ack msg may reach, so need do some check and protect. mes_protect_when_timeout(room); LOG_DEBUG_WAR("[mes]room wait timeout, ruid=%llu(%llu-%llu), INT=%u", - (uint64)ruid, (uint64)room->room_index, room->rsn, MES_WAITS_INTERRUPTED); + (uint64)ruid, (uint64)room->room_index, room->rsn, MES_WAITS_INTERRUPTED); + LOG_DYNAMIC_TRACE("[MES][%llu][%llu-%llu]RWT, INT=%u", + (uint64)ruid, (uint64)room->room_index, MES_WAITS_INTERRUPTED); mes_free_room(room); return ERR_MES_WAIT_OVERTIME; } diff --git a/src/cm_mes/mes_tcp.c b/src/cm_mes/mes_tcp.c index 265f9e9..6e73ee6 100644 --- a/src/cm_mes/mes_tcp.c +++ b/src/cm_mes/mes_tcp.c @@ -1007,10 +1007,11 @@ int mes_tcp_send_bufflist(mes_bufflist_t *buff_list) CM_ASSERT(MES_RUID_GET_RSN((head)->ruid) != 0); } - LOG_DEBUG_INF("[mes] Begin tcp send buffer, buff list cnt=%u, cmd=%u, ruid=%llu(%llu-%llu), src_inst=%u, " - "dst_inst=%u, size=%u, flags=%u, pipe version=%u, channel_id %u.", - buff_list->cnt, (head)->cmd, (uint64)head->ruid, (uint64)MES_RUID_GET_RID((head)->ruid), - (uint64)MES_RUID_GET_RSN((head)->ruid), (head)->src_inst, (head)->dst_inst, (head)->size, + LOG_DEBUG_INF("[mes][%llu(%llu-%llu)]tcpsndlist, cnt=%u, cmd=%u, src=%u, " + "dst=%u, sz=%u, flags=%u, pver=%u, cid %u.", + (uint64)head->ruid, (uint64)MES_RUID_GET_RID((head)->ruid), + (uint64)MES_RUID_GET_RSN((head)->ruid), buff_list->cnt, (head)->cmd, + (head)->src_inst, (head)->dst_inst, (head)->size, (head)->flags, version, MES_CHANNEL_ID(pipe->channel->id)); if (CS_DIFFERENT_ENDIAN(pipe->send_pipe.options)) { diff --git a/src/cm_utils/cm_log.c b/src/cm_utils/cm_log.c index d47de12..738bcfb 100644 --- a/src/cm_utils/cm_log.c +++ b/src/cm_utils/cm_log.c @@ -70,6 +70,12 @@ static log_file_handle_t g_logger[LOG_COUNT] = { .file_handle = CM_INVALID_FD, .file_inode = 0 }, [LOG_BLACKBOX] = { + .file_handle = CM_INVALID_FD, + .file_inode = 0 }, + [LOG_DMS_EVT_TRC] = { + .file_handle = CM_INVALID_FD, + .file_inode = 0 }, + [LOG_DMS_RFM_TRC] = { .file_handle = CM_INVALID_FD, .file_inode = 0 } }; @@ -750,7 +756,8 @@ static void cm_write_log_file(log_file_handle_t *log_file_handle, char *buf, uin // It is possible to fail because of the open file. if (log_file_handle->file_handle != CM_INVALID_FD && buf != NULL) { // Replace the string terminator '\0' with newline character '\n'. - if (log_file_handle->log_type != LOG_MEC && log_file_handle->log_type != LOG_BLACKBOX) { + if (log_file_handle->log_type != LOG_MEC && log_file_handle->log_type != LOG_BLACKBOX && + log_file_handle->log_type != LOG_DMS_RFM_TRC && log_file_handle->log_type != LOG_DMS_EVT_TRC) { buf[size] = '\n'; size++; } @@ -1520,6 +1527,13 @@ void cm_write_trace_log(uint64 tracekey, const char *format, ...) va_end(args); } +void cm_write_dynamic_trace_log(uint32 type, char* buf, uint32 size) +{ + log_file_handle_t *log_file_handle = &g_logger[type]; + + cm_stat_and_write_log(log_file_handle, buf, size, CM_TRUE, cm_write_log_file); +} + #define BLACKBOX_PRINT_LINE_LEN 16 #define BLACKBOX_PRINT_SPACE_LEN 4 #define BLACKBOX_MAX_PRINT_SIZE (SIZE_M(8)) diff --git a/src/cm_utils/cm_log.h b/src/cm_utils/cm_log.h index b5b5d4d..3eb7f89 100644 --- a/src/cm_utils/cm_log.h +++ b/src/cm_utils/cm_log.h @@ -50,6 +50,8 @@ typedef enum en_log_type { LOG_TRACE, LOG_PROFILE, LOG_BLACKBOX, + LOG_DMS_EVT_TRC, + LOG_DMS_RFM_TRC, LOG_COUNT // LOG COUNT } log_type_t; @@ -58,6 +60,14 @@ typedef void (*usr_cb_log_output_t)(int log_type, int log_level, const char *code_file_name, unsigned int code_line_num, const char *module_name, const char *format, ...); +typedef void (*usr_cb_log_trace_t)(int log_type, int log_level, + const char *code_file_name, unsigned int code_line_num, + const char *module_name, const char *format, ...); + +typedef void (*usr_cb_dyn_trc_set_flag_t)(unsigned char val); + +typedef unsigned char (*usr_cb_dyn_trc_log_t)(void); + typedef struct st_log_param { char log_home[CM_MAX_LOG_HOME_LEN]; char log_module_name[CM_MAX_LOG_MODULE_NAME]; @@ -72,6 +82,9 @@ typedef struct st_log_param { volatile uint64 max_audit_file_size; bool32 log_instance_startup; usr_cb_log_output_t log_write; + usr_cb_log_trace_t dyn_trace; + usr_cb_dyn_trc_set_flag_t dyn_trc_set_flag; + usr_cb_dyn_trc_log_t dyn_trc_trace_logs; volatile bool32 log_suppress_enable; char instance_name[CM_MAX_NAME_LEN]; volatile uint32 audit_level; @@ -120,6 +133,9 @@ log_param_t *cm_log_param_instance(void); #define LOG_MODULE_NAME (cm_log_param_instance()->log_module_name) +#define CM_DYNAMIC_TRACE_ENABLED (cm_log_param_instance()->dyn_trace != NULL) +#define CM_DYN_TRC_TRACE_LOGS (cm_log_param_instance()->dyn_trc_trace_logs()) + typedef struct st_log_file_handle { spinlock_t lock; char file_name[CM_FULL_PATH_BUFFER_SIZE]; // log file with the path @@ -161,6 +177,7 @@ void cm_write_alarm_log(uint32 warn_id, const char *format, ...) CM_CHECK_FMT(2, void cm_write_normal_log(log_type_t log_type, log_level_t log_level, const char *code_file_name, uint32 code_line_num, const char *module_name, bool32 need_rec_filelog, const char *format, ...) CM_CHECK_FMT(7, 8); void cm_write_trace_log(uint64 tracekey, const char *format, ...); +void cm_write_dynamic_trace_log(uint32 type, char* buf, uint32 size); void cm_fync_logfile(void); void cm_close_logfile(void); status_t cm_set_log_module_name(const char *module_name, int32 len); @@ -169,6 +186,14 @@ void cm_write_normal_log_common(log_type_t log_type, log_level_t log_level, cons void cm_write_blackbox_log(const char *format, ...) CM_CHECK_FMT(1, 2); status_t cm_recovery_log_file(log_type_t log_type); +#define LOG_DYNAMIC_TRACE(format, ...) \ + do { \ + if (CM_DYNAMIC_TRACE_ENABLED) { \ + cm_log_param_instance()->dyn_trace(LOG_DEBUG, LEVEL_INFO, (char *)__FILE_NAME__, (uint32)__LINE__, \ + LOG_MODULE_NAME, format, ##__VA_ARGS__); \ + }; \ + } while (0) + #define LOG_BLACKBOX_INF(format, ...) \ do { \ if (LOG_ON) { \ @@ -178,6 +203,10 @@ status_t cm_recovery_log_file(log_type_t log_type); #define LOG_DEBUG_INF(format, ...) \ do { \ + if (CM_DYNAMIC_TRACE_ENABLED && CM_DYN_TRC_TRACE_LOGS) { \ + cm_log_param_instance()->dyn_trace(LOG_DEBUG, LEVEL_INFO, (char *)__FILE_NAME__, (uint32)__LINE__, \ + LOG_MODULE_NAME, format, ##__VA_ARGS__); \ + } \ if (LOG_DEBUG_INF_ON) { \ if (LOG_REG_CB) { \ cm_log_param_instance()->log_write(LOG_DEBUG, LEVEL_INFO, (char *)__FILE_NAME__, (uint32)__LINE__, \ @@ -191,6 +220,10 @@ status_t cm_recovery_log_file(log_type_t log_type); #define LOG_DEBUG_WAR(format, ...) \ do { \ + if (CM_DYNAMIC_TRACE_ENABLED && CM_DYN_TRC_TRACE_LOGS) { \ + cm_log_param_instance()->dyn_trace(LOG_DEBUG, LEVEL_WARN, (char *)__FILE_NAME__, (uint32)__LINE__, \ + LOG_MODULE_NAME, format, ##__VA_ARGS__); \ + } \ if (LOG_DEBUG_WAR_ON) { \ if (LOG_REG_CB) { \ cm_log_param_instance()->log_write(LOG_DEBUG, LEVEL_WARN, (char *)__FILE_NAME__, (uint32)__LINE__, \ @@ -203,6 +236,10 @@ status_t cm_recovery_log_file(log_type_t log_type); } while (0) #define LOG_DEBUG_ERR(format, ...) \ do { \ + if (CM_DYNAMIC_TRACE_ENABLED) { \ + cm_log_param_instance()->dyn_trace(LOG_DEBUG, LEVEL_ERROR, (char *)__FILE_NAME__, (uint32)__LINE__, \ + LOG_MODULE_NAME, format, ##__VA_ARGS__); \ + } \ if (LOG_DEBUG_ERR_ON) { \ if (LOG_REG_CB) { \ cm_log_param_instance()->log_write(LOG_DEBUG, LEVEL_ERROR, (char *)__FILE_NAME__, (uint32)__LINE__, \ @@ -214,6 +251,13 @@ status_t cm_recovery_log_file(log_type_t log_type); } \ } while (0) +#define CM_SS_DYN_TRC_SET_TRACE_FLAG(val) \ + do { \ + if (CM_DYNAMIC_TRACE_ENABLED) { \ + cm_log_param_instance()->dyn_trc_set_flag(val); \ + } \ + } while (0) + // 10s print 5 times #define LOG_DEBUG_ERR_EX(format, ...) \ do { \ @@ -351,6 +395,16 @@ void cm_write_mec_log(const char *format, ...); } \ } while (0) +#define LOG_DMS_EVENT_TRACE(buf, size) \ + do { \ + cm_write_dynamic_trace_log(LOG_DMS_EVT_TRC, buf, size); \ + } while (0) + +#define LOG_DMS_REFORM_TRACE(buf, size) \ + do { \ + cm_write_dynamic_trace_log(LOG_DMS_RFM_TRC, buf, size); \ + } while (0) + #define LOG_PROFILE(format, ...) \ do { \ if (LOG_PROFILE_ON) { \ @@ -446,6 +500,15 @@ typedef enum st_warn_name { #define LOG_INHIBIT_LEVEL4 100000 // every 100000 logs record one log #define LOG_INHIBIT_LEVEL5 1000000 // every 1000000 logs record one log +#define LOG_DMS_EVENT_TRACE_INHIBIT(level, buf, size) \ + do { \ + static uint32 _log_inhibit_ = 0; \ + if (_log_inhibit_ % (level) == 0) { \ + LOG_DMS_EVENT_TRACE(buf, size); \ + } \ + _log_inhibit_++; \ + } while (0) + #define LOG_DEBUG_ERR_INHIBIT(level, format, ...) \ do { \ static uint32 _log_inhibit_ = 0; \ -- Gitee