Skip to content

Commit

Permalink
log: merge MAIN_LOG() into G_LOG()
Browse files Browse the repository at this point in the history 
This commit drops MAIN_LOG() and makes calling G_LOG() in non-lcore
contexts safe because it is very error prone to identify when one
should use MAIN_LOG() instead of G_LOG(). For example,
lib/net.c:lsc_event_callback(), which runs in a non-lcore context,
calls log_if_name(). But log_if_name() uses G_LOG() because
it is also called in lcore contexts.
  • Loading branch information
@AltraMayor
AltraMayor committed Jun 7, 2024
1 parent cc1d98d commit 290d4a2
Show file tree
Hide file tree
Showing 4 changed files with 98 additions and 95 deletions.
32 changes: 8 additions & 24 deletions include/gatekeeper_log_ratelimit.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -83,48 +83,32 @@ 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;
uint32_t printed;
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_ */
35 changes: 7 additions & 28 deletions include/gatekeeper_main.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
102 changes: 74 additions & 28 deletions lib/log_ratelimit.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -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);
}

Expand All @@ -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;
}
Expand All @@ -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;
Expand All @@ -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);
}

Expand All @@ -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;
Expand Down Expand Up @@ -160,22 +166,75 @@ 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;

/*
* 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;
Expand All @@ -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)
{
Expand All @@ -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;
Expand Down
24 changes: 9 additions & 15 deletions lib/net.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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;
Expand All @@ -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,
Expand All @@ -1755,22 +1749,22 @@ 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;
}

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;
}
Expand All @@ -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)) {
/*
Expand Down

0 comments on commit 290d4a2

Please sign in to comment.