Skip to content

Commit

Permalink
lib/net: monitor state of the links
Browse files Browse the repository at this point in the history 
Having log entries reporting changes in the state of the links
eases diagnoses in production. This commit adds these log entries
through the Link State Change (LSC) interuption that most NICs
support. The information that a given NIC does not support
the LSC interuption is logged, but its link state is not monitored.

Since the callbacks of interuptions run in threads that are not
logical cores, this commit introduces the macro MAIN_LOG() to
Gatekeeper's log library to be used in these contexts.
  • Loading branch information
@AltraMayor
AltraMayor committed May 8, 2024
1 parent b3cac7f commit de9532c
Show file tree
Hide file tree
Showing 4 changed files with 333 additions and 44 deletions.
36 changes: 29 additions & 7 deletions include/gatekeeper_log_ratelimit.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -74,7 +74,17 @@ void log_ratelimit_state_init(unsigned int lcore_id, uint32_t interval,
* - 0: Success.
* - Negative on error.
*/
int rte_log_ratelimit(uint32_t level, uint32_t logtype, const char *format, ...)
int gatekeeper_log_ratelimit(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)));

int gatekeeper_main_log(uint32_t level, uint32_t logtype,
const char *format, ...)
#ifdef __GNUC__
#if (__GNUC__ > 4 || (__GNUC__ == 4 && __GNUC_MINOR__ > 2))
__attribute__((cold))
Expand All @@ -86,9 +96,6 @@ int rte_log_ratelimit(uint32_t level, uint32_t logtype, const char *format, ...)
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);

/* Get the block name for the corresponding lcore. */
const char *get_block_name(unsigned int lcore_id);

struct log_ratelimit_state {
uint64_t interval_cycles;
uint32_t burst;
Expand All @@ -97,12 +104,27 @@ struct log_ratelimit_state {
uint64_t end;
rte_atomic32_t log_level;
char block_name[16];
char str_date_time[32];
uint64_t update_time_at;
} __rte_cache_aligned;

/* Only use these variables in file lib/log_ratelimit.c and in macro G_LOG(). */
struct log_thread_time {
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);
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_ */
27 changes: 20 additions & 7 deletions include/gatekeeper_main.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -35,25 +35,38 @@

#define BLOCK_LOGTYPE RTE_LOGTYPE_USER1
#define G_LOG_PREFIX "%s/%u %s %s "
#define G_LOG_MAIN "Main"

#define G_LOG(level, fmt, ...) \
do { \
unsigned int __g_log_lcore_id = rte_lcore_id(); \
const struct log_ratelimit_state *__g_log_lrs = \
&log_ratelimit_states[__g_log_lcore_id]; \
rte_log_ratelimit(RTE_LOG_ ## level, BLOCK_LOGTYPE, \
G_LOG_PREFIX fmt, \
gatekeeper_log_ratelimit(RTE_LOG_ ## level, \
BLOCK_LOGTYPE, G_LOG_PREFIX fmt, \
likely(log_ratelimit_enabled) \
? __g_log_lrs->block_name \
: "Main", \
? log_ratelimit_states[__g_log_lcore_id]\
.block_name \
: G_LOG_MAIN, \
__g_log_lcore_id, \
__g_log_lrs->str_date_time, \
RTE_PER_LCORE(_log_thread_time).str_date_time, \
#level \
__VA_OPT__(,) __VA_ARGS__); \
} while (0)

#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_main_log(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
54 changes: 29 additions & 25 deletions lib/log_ratelimit.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,8 +27,8 @@
#include "gatekeeper_main.h"
#include "gatekeeper_log_ratelimit.h"

RTE_DEFINE_PER_LCORE(struct log_thread_time, _log_thread_time);
struct log_ratelimit_state log_ratelimit_states[RTE_MAX_LCORE];

bool log_ratelimit_enabled;

void
Expand All @@ -47,16 +47,17 @@ check_log_allowed(uint32_t level)
#define NO_TIME_STR "NO TIME"

static void
update_str_date_time(struct log_ratelimit_state *lrs, uint64_t now)
update_str_date_time(uint64_t now)
{
struct log_thread_time *ttime = &RTE_PER_LCORE(_log_thread_time);
struct timespec tp;
struct tm *p_tm, time_info;
uint64_t diff_ns;
int ret;

RTE_BUILD_BUG_ON(sizeof(NO_TIME_STR) > sizeof(lrs->str_date_time));
RTE_BUILD_BUG_ON(sizeof(NO_TIME_STR) > sizeof(ttime->str_date_time));

if (likely(now < lrs->update_time_at)) {
if (likely(now < ttime->update_time_at)) {
/* Fast path, that is, high log rate. */
return;
}
Expand All @@ -73,7 +74,7 @@ update_str_date_time(struct log_ratelimit_state *lrs, uint64_t now)
if (unlikely(p_tm != &time_info))
goto no_time;

ret = strftime(lrs->str_date_time, sizeof(lrs->str_date_time),
ret = strftime(ttime->str_date_time, sizeof(ttime->str_date_time),
"%Y-%m-%d %H:%M:%S", &time_info);
if (unlikely(ret == 0))
goto no_time;
Expand All @@ -83,23 +84,25 @@ update_str_date_time(struct log_ratelimit_state *lrs, uint64_t now)
no_tp:
tp.tv_nsec = 0;
no_time:
strcpy(lrs->str_date_time, NO_TIME_STR);
strcpy(ttime->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! */
lrs->update_time_at = now + (typeof(now))round(diff_ns * cycles_per_ns);
ttime->update_time_at =
now + (typeof(now))round(diff_ns * cycles_per_ns);
}

static void
log_ratelimit_reset(struct log_ratelimit_state *lrs, uint64_t now)
{
lrs->printed = 0;
if (lrs->suppressed > 0) {
update_str_date_time(lrs, now);
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(), lrs->str_date_time,
lrs->block_name, rte_lcore_id(),
RTE_PER_LCORE(_log_thread_time).str_date_time,
"NOTICE", lrs->suppressed);
}
lrs->suppressed = 0;
Expand All @@ -111,7 +114,6 @@ log_ratelimit_state_init(unsigned int lcore_id, uint32_t interval,
uint32_t burst, uint32_t log_level, const char *block_name)
{
struct log_ratelimit_state *lrs;
uint64_t now;

RTE_VERIFY(lcore_id < RTE_MAX_LCORE);

Expand All @@ -124,10 +126,7 @@ log_ratelimit_state_init(unsigned int lcore_id, uint32_t interval,
lrs->suppressed = 0;
rte_atomic32_set(&lrs->log_level, log_level);
strcpy(lrs->block_name, block_name);
lrs->str_date_time[0] = '\0';
now = rte_rdtsc();
lrs->update_time_at = now;
log_ratelimit_reset(lrs, now);
log_ratelimit_reset(lrs, rte_rdtsc());
}

/*
Expand Down Expand Up @@ -162,7 +161,8 @@ log_ratelimit_allow(struct log_ratelimit_state *lrs, uint64_t now)
}

int
rte_log_ratelimit(uint32_t level, uint32_t logtype, const char *format, ...)
gatekeeper_log_ratelimit(uint32_t level, uint32_t logtype,
const char *format, ...)
{
uint64_t now = rte_rdtsc(); /* Freeze current time. */
struct log_ratelimit_state *lrs = &log_ratelimit_states[rte_lcore_id()];
Expand All @@ -183,7 +183,20 @@ rte_log_ratelimit(uint32_t level, uint32_t logtype, const char *format, ...)
return 0;

log:
update_str_date_time(lrs, now);
update_str_date_time(now);
va_start(ap, format);
ret = rte_vlog(level, logtype, format, ap);
va_end(ap);
return ret;
}

int
gatekeeper_main_log(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);
Expand Down Expand Up @@ -214,12 +227,3 @@ set_log_level_per_lcore(unsigned int lcore_id, uint32_t log_level)
rte_atomic32_set(&log_ratelimit_states[lcore_id].log_level, log_level);
return 0;
}

const char *
get_block_name(unsigned int lcore_id)
{
if (lcore_id >= RTE_MAX_LCORE) {
return "invalid lcore";
}
return log_ratelimit_states[lcore_id].block_name;
}
Loading

0 comments on commit de9532c

Please sign in to comment.