diff --git a/include/gatekeeper_log_ratelimit.h b/include/gatekeeper_log_ratelimit.h index 96cb1d0c..9af47242 100644 --- a/include/gatekeeper_log_ratelimit.h +++ b/include/gatekeeper_log_ratelimit.h @@ -83,19 +83,12 @@ int gatekeeper_log_ratelimit(uint32_t level, uint32_t logtype, #endif __attribute__((format(printf, 3, 4))); -int gatekeeper_log_main(uint32_t level, uint32_t logtype, - const char *format, ...) -#ifdef __GNUC__ -#if (__GNUC__ > 4 || (__GNUC__ == 4 && __GNUC_MINOR__ > 2)) - __attribute__((cold)) -#endif -#endif - __attribute__((format(printf, 3, 4))); - /* Functions to set the log level for each functional block as well as lcore. */ int set_log_level_per_block(const char *block_name, uint32_t log_level); int set_log_level_per_lcore(unsigned int lcore_id, uint32_t log_level); +#define LOG_BLOCK_NAME_MAX_LEN (16) + struct log_ratelimit_state { uint64_t interval_cycles; uint32_t burst; @@ -103,28 +96,19 @@ struct log_ratelimit_state { uint32_t suppressed; uint64_t end; rte_atomic32_t log_level; - char block_name[16]; + char block_name[LOG_BLOCK_NAME_MAX_LEN]; } __rte_cache_aligned; -struct log_thread_time { +struct log_thread_info { + bool thread_name_initiated; + char thread_name[2 * LOG_BLOCK_NAME_MAX_LEN]; char str_date_time[32]; uint64_t update_time_at; }; -/* - * Only use these variables in file lib/log_ratelimit.c and in macros - * G_LOG() and MAIN_LOG(). - */ -RTE_DECLARE_PER_LCORE(struct log_thread_time, _log_thread_time); +/* Only use these variables in file lib/log_ratelimit.c and in macro G_LOG(). */ +RTE_DECLARE_PER_LCORE(struct log_thread_info, _log_thread_info); extern struct log_ratelimit_state log_ratelimit_states[RTE_MAX_LCORE]; extern bool log_ratelimit_enabled; -/* Get the block name for the corresponding lcore. */ -static inline const char *get_block_name(unsigned int lcore_id) -{ - return lcore_id < RTE_MAX_LCORE - ? log_ratelimit_states[lcore_id].block_name - : "NO-lcore"; -} - #endif /* _GATEKEEPER_LOG_RATELIMIT_H_ */ diff --git a/include/gatekeeper_main.h b/include/gatekeeper_main.h index 69aa322f..8e271e0a 100644 --- a/include/gatekeeper_main.h +++ b/include/gatekeeper_main.h @@ -34,39 +34,18 @@ #include "list.h" #define BLOCK_LOGTYPE RTE_LOGTYPE_USER1 -#define G_LOG_PREFIX "%s/%u %s %s " -#define G_LOG_MAIN "Main" +#define G_LOG_PREFIX "%s %s %s " #define G_LOG(level, fmt, ...) \ - do { \ - unsigned int __g_log_lcore_id = rte_lcore_id(); \ - gatekeeper_log_ratelimit(RTE_LOG_ ## level, \ - BLOCK_LOGTYPE, G_LOG_PREFIX fmt, \ - likely(log_ratelimit_enabled) \ - ? log_ratelimit_states[__g_log_lcore_id]\ - .block_name \ - : G_LOG_MAIN, \ - __g_log_lcore_id, \ - RTE_PER_LCORE(_log_thread_time).str_date_time, \ - #level \ - __VA_OPT__(,) __VA_ARGS__); \ - } while (0) + gatekeeper_log_ratelimit(RTE_LOG_ ## level, BLOCK_LOGTYPE, \ + G_LOG_PREFIX fmt, \ + RTE_PER_LCORE(_log_thread_info).thread_name, \ + RTE_PER_LCORE(_log_thread_info).str_date_time, \ + #level \ + __VA_OPT__(,) __VA_ARGS__) \ #define G_LOG_CHECK(level) check_log_allowed(RTE_LOG_ ## level) -/* - * This macro should only be called in contexts other than logical cores - * because it is independent of functional blocks and is not rate limited. - * - * From logical cores, call G_LOG(). - */ -#define MAIN_LOG(level, fmt, ...) \ - gatekeeper_log_main(RTE_LOG_ ## level, BLOCK_LOGTYPE, \ - G_LOG_PREFIX fmt, G_LOG_MAIN, rte_gettid(), \ - RTE_PER_LCORE(_log_thread_time).str_date_time, \ - #level \ - __VA_OPT__(,) __VA_ARGS__) - extern volatile int exiting; #define ONE_SEC_IN_NANO_SEC (1000000000L) diff --git a/lib/log_ratelimit.c b/lib/log_ratelimit.c index fff5f9a9..38c12b81 100644 --- a/lib/log_ratelimit.c +++ b/lib/log_ratelimit.c @@ -27,7 +27,7 @@ #include "gatekeeper_main.h" #include "gatekeeper_log_ratelimit.h" -RTE_DEFINE_PER_LCORE(struct log_thread_time, _log_thread_time); +RTE_DEFINE_PER_LCORE(struct log_thread_info, _log_thread_info); struct log_ratelimit_state log_ratelimit_states[RTE_MAX_LCORE]; bool log_ratelimit_enabled; @@ -40,7 +40,13 @@ log_ratelimit_enable(void) bool check_log_allowed(uint32_t level) { - struct log_ratelimit_state *lrs = &log_ratelimit_states[rte_lcore_id()]; + unsigned int lcore = rte_lcore_id(); + struct log_ratelimit_state *lrs; + + if (unlikely(lcore >= RTE_MAX_LCORE)) + return true; + + lrs = &log_ratelimit_states[lcore]; return level <= (uint32_t)rte_atomic32_read(&lrs->log_level); } @@ -49,15 +55,15 @@ check_log_allowed(uint32_t level) static void update_str_date_time(uint64_t now) { - struct log_thread_time *ttime = &RTE_PER_LCORE(_log_thread_time); + struct log_thread_info *tinfo = &RTE_PER_LCORE(_log_thread_info); struct timespec tp; struct tm *p_tm, time_info; uint64_t diff_ns; int ret; - RTE_BUILD_BUG_ON(sizeof(NO_TIME_STR) > sizeof(ttime->str_date_time)); + RTE_BUILD_BUG_ON(sizeof(NO_TIME_STR) > sizeof(tinfo->str_date_time)); - if (likely(now < ttime->update_time_at)) { + if (likely(now < tinfo->update_time_at)) { /* Fast path, that is, high log rate. */ return; } @@ -74,7 +80,7 @@ update_str_date_time(uint64_t now) if (unlikely(p_tm != &time_info)) goto no_time; - ret = strftime(ttime->str_date_time, sizeof(ttime->str_date_time), + ret = strftime(tinfo->str_date_time, sizeof(tinfo->str_date_time), "%Y-%m-%d %H:%M:%S", &time_info); if (unlikely(ret == 0)) goto no_time; @@ -84,12 +90,12 @@ update_str_date_time(uint64_t now) no_tp: tp.tv_nsec = 0; no_time: - strcpy(ttime->str_date_time, NO_TIME_STR); + strcpy(tinfo->str_date_time, NO_TIME_STR); next_update: diff_ns = likely(tp.tv_nsec >= 0 && tp.tv_nsec < ONE_SEC_IN_NANO_SEC) ? (ONE_SEC_IN_NANO_SEC - tp.tv_nsec) : ONE_SEC_IN_NANO_SEC; /* C library bug! */ - ttime->update_time_at = + tinfo->update_time_at = now + (typeof(now))round(diff_ns * cycles_per_ns); } @@ -98,11 +104,11 @@ log_ratelimit_reset(struct log_ratelimit_state *lrs, uint64_t now) { lrs->printed = 0; if (lrs->suppressed > 0) { + struct log_thread_info *tinfo = + &RTE_PER_LCORE(_log_thread_info); update_str_date_time(now); - rte_log(RTE_LOG_NOTICE, BLOCK_LOGTYPE, - G_LOG_PREFIX "%u log entries were suppressed during the last ratelimit interval\n", - lrs->block_name, rte_lcore_id(), - RTE_PER_LCORE(_log_thread_time).str_date_time, + rte_log(RTE_LOG_NOTICE, BLOCK_LOGTYPE, G_LOG_PREFIX "%u log entries were suppressed during the last ratelimit interval\n", + tinfo->thread_name, tinfo->str_date_time, "NOTICE", lrs->suppressed); } lrs->suppressed = 0; @@ -160,12 +166,51 @@ log_ratelimit_allow(struct log_ratelimit_state *lrs, uint64_t now) return false; } +static void +name_thread(bool overwrite_lcore_name) +{ + struct log_thread_info *tinfo = &RTE_PER_LCORE(_log_thread_info); + const size_t thread_name_len = sizeof(tinfo->thread_name); + unsigned int lcore; + uint32_t id; + const char *name; + int ret; + + lcore = rte_lcore_id(); + if (likely(lcore < RTE_MAX_LCORE)) { + id = lcore; + if (unlikely(overwrite_lcore_name)) + name = "Main"; + else if (likely(log_ratelimit_states[lcore].block_name[0] != + '\0')) + name = log_ratelimit_states[lcore].block_name; + else + name = "lcore"; + } else { + id = rte_gettid(); + name = "thread"; + } + + ret = snprintf(tinfo->thread_name, thread_name_len, "%s/%u", name, id); + if (likely(ret > 0 && (typeof(thread_name_len))ret < thread_name_len)) + return; /* Success. */ + + /* Failsafe. */ + strncpy(tinfo->thread_name, name, thread_name_len); + if (unlikely(tinfo->thread_name[thread_name_len - 1] != '\0')) { + /* Failsafer. */ + tinfo->thread_name[thread_name_len - 1] = '\0'; + } +} + int gatekeeper_log_ratelimit(uint32_t level, uint32_t logtype, const char *format, ...) { + struct log_thread_info *tinfo = &RTE_PER_LCORE(_log_thread_info); uint64_t now = rte_rdtsc(); /* Freeze current time. */ - struct log_ratelimit_state *lrs = &log_ratelimit_states[rte_lcore_id()]; + unsigned int lcore; + struct log_ratelimit_state *lrs; va_list ap; int ret; @@ -173,9 +218,23 @@ gatekeeper_log_ratelimit(uint32_t level, uint32_t logtype, * unlikely() reason: @log_ratelimit_enabled is only false during * startup. */ - if (unlikely(!log_ratelimit_enabled)) + if (unlikely(!log_ratelimit_enabled)) { + if (unlikely(tinfo->thread_name[0] == '\0')) + name_thread(true); goto log; + } + if (unlikely(!tinfo->thread_name_initiated)) { + name_thread(false); + tinfo->thread_name_initiated = true; + } + + lcore = rte_lcore_id(); + /* unlikely() reason: most of the log comes from functional blocks. */ + if (unlikely(lcore >= RTE_MAX_LCORE)) + goto log; + + lrs = &log_ratelimit_states[lcore]; if (level <= (uint32_t)rte_atomic32_read(&lrs->log_level) && log_ratelimit_allow(lrs, now)) goto log; @@ -190,19 +249,6 @@ gatekeeper_log_ratelimit(uint32_t level, uint32_t logtype, return ret; } -int -gatekeeper_log_main(uint32_t level, uint32_t logtype, const char *format, ...) -{ - va_list ap; - int ret; - - update_str_date_time(rte_rdtsc()); - va_start(ap, format); - ret = rte_vlog(level, logtype, format, ap); - va_end(ap); - return ret; -} - int set_log_level_per_block(const char *block_name, uint32_t log_level) { @@ -222,7 +268,7 @@ int set_log_level_per_lcore(unsigned int lcore_id, uint32_t log_level) { if (lcore_id >= RTE_MAX_LCORE) { - return -1; + return -EINVAL; } rte_atomic32_set(&log_ratelimit_states[lcore_id].log_level, log_level); return 0; diff --git a/lib/net.c b/lib/net.c index eeaa9bd4..5c5207f2 100644 --- a/lib/net.c +++ b/lib/net.c @@ -1700,11 +1700,6 @@ log_if_name(char *if_name, size_t len, const struct gatekeeper_if *iface, } } -/* - * ATTENTION: This function is called in the interrupt host thread, - * which is not associated to an lcore, therefore it must call MAIN_LOG() - * instead of G_LOG(). - */ static void get_str_members(char *str_members, size_t size, uint16_t *members, uint16_t count) @@ -1720,13 +1715,13 @@ get_str_members(char *str_members, size_t size, uint16_t *members, int ret = snprintf(str_members + total, remainder, "%u%s", members[i], i + 1 < count ? ", " : ""); if (unlikely(ret < 0)) { - MAIN_LOG(ERR, "%s(): snprintf() failed (errno=%i): %s\n", + G_LOG(ERR, "%s(): snprintf() failed (errno=%i): %s\n", __func__, errno, strerror(errno)); return; } total += ret; if (unlikely((size_t)ret >= remainder)) { - MAIN_LOG(CRIT, "%s(): bug: str_members' size must be more than %u bytes\n", + G_LOG(CRIT, "%s(): bug: str_members' size must be more than %u bytes\n", __func__, total + 1 /* Accounting for '\0'. */); str_members[size - 1] = '\0'; return; @@ -1737,8 +1732,7 @@ get_str_members(char *str_members, size_t size, uint16_t *members, #define STR_ERROR_MEMBERS "ERROR" /* * ATTENTION: This function is called in the interrupt host thread, - * which is not associated to an lcore, therefore it must call MAIN_LOG() - * instead of G_LOG(). + * which is not associated to an lcore. */ static int lsc_event_callback(uint16_t port_id, enum rte_eth_event_type event, @@ -1755,14 +1749,14 @@ lsc_event_callback(uint16_t port_id, enum rte_eth_event_type event, log_if_name(if_name, sizeof(if_name), iface, port_id); if (unlikely(event != RTE_ETH_EVENT_INTR_LSC)) { - MAIN_LOG(CRIT, "%s(%s): bug: unexpected event %i\n", + G_LOG(CRIT, "%s(%s): bug: unexpected event %i\n", __func__, if_name, event); return -EFAULT; } ret = rte_eth_link_get_nowait(port_id, &link); if (unlikely(ret < 0)) { - MAIN_LOG(ERR, "%s(%s): cannot get link status (errno=%i): %s\n", + G_LOG(ERR, "%s(%s): cannot get link status (errno=%i): %s\n", __func__, if_name, -ret, rte_strerror(-ret)); return ret; } @@ -1770,7 +1764,7 @@ lsc_event_callback(uint16_t port_id, enum rte_eth_event_type event, ret = rte_eth_link_to_str(link_status_text, sizeof(link_status_text), &link); if (unlikely(ret < 0)) { - MAIN_LOG(ERR, "%s(%s): cannot get status string (errno=%i): %s\n", + G_LOG(ERR, "%s(%s): cannot get status string (errno=%i): %s\n", __func__, if_name, -ret, rte_strerror(-ret)); return ret; } @@ -1783,19 +1777,19 @@ lsc_event_callback(uint16_t port_id, enum rte_eth_event_type event, if (unlikely(ret < 0)) { RTE_BUILD_BUG_ON(sizeof(STR_ERROR_MEMBERS) > sizeof(str_members)); - MAIN_LOG(ERR, "%s(%s): cannot get active members (errno=%i): %s\n", + G_LOG(ERR, "%s(%s): cannot get active members (errno=%i): %s\n", __func__, if_name, -ret, rte_strerror(-ret)); strcpy(str_members, STR_ERROR_MEMBERS); } else { get_str_members(str_members, sizeof(str_members), members, ret); } - MAIN_LOG(NOTICE, "%s(%s): active members: %s; %s\n", + G_LOG(NOTICE, "%s(%s): active members: %s; %s\n", __func__, if_name, str_members, link_status_text); return 0; } - MAIN_LOG(NOTICE, "%s(%s): %s\n", __func__, if_name, link_status_text); + G_LOG(NOTICE, "%s(%s): %s\n", __func__, if_name, link_status_text); if (iface_bonded(iface)) { /*