log: merge MAIN_LOG() into G_LOG()

include/gatekeeper_log_ratelimit.h

@@ -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_ */

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)

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,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;
@@ -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;

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,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;
 	}
@@ -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)) {
 		/*