logging: add minimal implementation

The log mechanism, even in immediate mode, adds somewhere
between 1K-2K of footprint to applications that use it.

We want to standardize the logging APIs for all logging
within the kernel, but need to not let platforms with
very constrained RAM/ROM in the dust.

This patch introduces CONFIG_LOG_MINIMAL, which is a very
thin wrapper to printk(). It supports the APIs expressed
in logging/log.h.

This will be the new default for test cases.

Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

include/logging/log.h

@@ -28,12 +28,6 @@ extern "C" {
  * @{
  */
 
-#define LOG_LEVEL_NONE 0
-#define LOG_LEVEL_ERR  1
-#define LOG_LEVEL_WRN  2
-#define LOG_LEVEL_INF  3
-#define LOG_LEVEL_DBG  4
-
 /**
  * @brief Writes an ERROR level message to the log.
  *
@@ -247,6 +241,7 @@ extern "C" {
 #define LOG_INST_HEXDUMP_DBG(_log_inst, _data, _length, _str)	\
 	Z_LOG_HEXDUMP_INSTANCE(LOG_LEVEL_DBG, _log_inst, _data, _length, _str)
 
+#ifndef CONFIG_LOG_MINIMAL
 /**
  * @brief Writes an formatted string to the log.
  *
@@ -266,13 +261,29 @@ void log_printk(const char *fmt, va_list ap);
  * Logger allocates a buffer and copies input string returning a pointer to the
  * copy. Logger ensures that buffer is freed when logger message is freed.
  *
+ * Depending on configuration, this function may do nothing and just pass
+ * along the supplied string pointer. Do not rely on this function to always
+ * make a copy!
+ *
  * @param str Transient string.
  *
  * @return Copy of the string or default string if buffer could not be
  *	   allocated. String may be truncated if input string does not fit in
- *	   a buffer from the pool (see CONFIG_LOG_STRDUP_MAX_STRING).
+ *	   a buffer from the pool (see CONFIG_LOG_STRDUP_MAX_STRING). In
+ *	   some configurations, the original string pointer is returned.
  */
 char *log_strdup(const char *str);
+#else
+static inline void log_printk(const char *fmt, va_list ap)
+{
+	vprintk(fmt, ap);
+}
+
+static inline char *log_strdup(const char *str)
+{
+	return (char *)str;
+}
+#endif /* CONFIG_LOG_MINIMAL */
 
 #ifdef __cplusplus
 }

include/logging/log_core.h

@@ -13,6 +13,13 @@
 #include <stdarg.h>
 #include <syscall.h>
 #include <sys/util.h>
+#include <sys/printk.h>
+
+#define LOG_LEVEL_NONE 0
+#define LOG_LEVEL_ERR  1
+#define LOG_LEVEL_WRN  2
+#define LOG_LEVEL_INF  3
+#define LOG_LEVEL_DBG  4
 
 #ifdef __cplusplus
 extern "C" {
@@ -20,10 +27,13 @@ extern "C" {
 
 #ifndef CONFIG_LOG
 #define CONFIG_LOG_DEFAULT_LEVEL 0
-#define CONFIG_LOG_DOMAIN_ID 0
 #define CONFIG_LOG_MAX_LEVEL 0
 #endif
 
+#if !defined(CONFIG_LOG) || defined(CONFIG_LOG_MINIMAL)
+#define CONFIG_LOG_DOMAIN_ID 0
+#endif
+
 #define LOG_FUNCTION_PREFIX_MASK \
 	(((u32_t)IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_ERR) << \
 	  LOG_LEVEL_ERR) | \
@@ -210,35 +220,67 @@ extern "C" {
 	)								    \
 	))
 
+/******************************************************************************/
+/****************** Defiinitions used by minimal logging **********************/
+/******************************************************************************/
+void log_minimal_hexdump_print(int level, const char *data, size_t size);
+
+#define Z_LOG_TO_PRINTK(_level, fmt, ...) do {				     \
+		printk("%c: " fmt "\n", z_log_minimal_level_to_char(_level), \
+			##__VA_ARGS__);					     \
+	} while (false)
+
+static inline char z_log_minimal_level_to_char(int level)
+{
+	switch (level) {
+	case LOG_LEVEL_ERR:
+		return 'E';
+	case LOG_LEVEL_WRN:
+		return 'W';
+	case LOG_LEVEL_INF:
+		return 'I';
+	case LOG_LEVEL_DBG:
+		return 'D';
+	default:
+		return '?';
+	}
+}
 /******************************************************************************/
 /****************** Macros for standard logging *******************************/
 /******************************************************************************/
-#define __LOG(_level, _id, _filter, ...)				    \
+#define __LOG(_level, _id, _filter, ...)				       \
-	do {								    \
+	do {								       \
-		bool is_user_context = _is_user_context();		    \
+		bool is_user_context = _is_user_context();		       \
-									    \
+									       \
-		if (Z_LOG_CONST_LEVEL_CHECK(_level) &&			    \
+		if (Z_LOG_CONST_LEVEL_CHECK(_level)) {			       \
-		    (is_user_context ||					    \
+			if (IS_ENABLED(CONFIG_LOG_MINIMAL)) {		       \
-		     (_level <= LOG_RUNTIME_FILTER(_filter)))) {	    \
+				Z_LOG_TO_PRINTK(_level, __VA_ARGS__);	       \
-			struct log_msg_ids src_level = {		    \
+			} else if (is_user_context ||			       \
-				.level = _level,			    \
+				   (_level <= LOG_RUNTIME_FILTER(_filter))) {  \
-				.domain_id = CONFIG_LOG_DOMAIN_ID,	    \
+				struct log_msg_ids src_level = {	       \
-				.source_id = _id			    \
+					.level = _level,		       \
-			};						    \
+					.domain_id = CONFIG_LOG_DOMAIN_ID,     \
-									    \
+					.source_id = _id		       \
-			if ((BIT(_level) & LOG_FUNCTION_PREFIX_MASK) != 0U) {\
+				};					       \
-				__LOG_INTERNAL(is_user_context, src_level,  \
+									       \
-						Z_LOG_STR(__VA_ARGS__));    \
+				if ((BIT(_level) &			       \
-			} else {					    \
+				     LOG_FUNCTION_PREFIX_MASK) != 0U) {        \
-				__LOG_INTERNAL(is_user_context, src_level,  \
+					__LOG_INTERNAL(is_user_context,	       \
-						__VA_ARGS__);		    \
+						       src_level,	       \
-			}						    \
+						       Z_LOG_STR(__VA_ARGS__));\
-		} else if (false) {					    \
+				} else {				       \
-			/* Arguments checker present but never evaluated.*/ \
+					__LOG_INTERNAL(is_user_context,	       \
-			/* Placed here to ensure that __VA_ARGS__ are*/     \
+						       src_level,	       \
-			/* evaluated once when log is enabled.*/	    \
+						       __VA_ARGS__);	       \
-			log_printf_arg_checker(__VA_ARGS__);		    \
+				}					       \
-		}							    \
+			}						       \
+		}							       \
+		if (false) {						       \
+			/* Arguments checker present but never evaluated.*/    \
+			/* Placed here to ensure that __VA_ARGS__ are*/        \
+			/* evaluated once when log is enabled.*/	       \
+			log_printf_arg_checker(__VA_ARGS__);		       \
+		}							       \
 	} while (false)
 
 #define Z_LOG(_level, ...)			       \
@@ -259,29 +301,35 @@ extern "C" {
 /******************************************************************************/
 /****************** Macros for hexdump logging ********************************/
 /******************************************************************************/
-#define __LOG_HEXDUMP(_level, _id, _filter, _data, _length, _str)	      \
+#define __LOG_HEXDUMP(_level, _id, _filter, _data, _length, _str)	       \
-	do {								      \
+	do {								       \
-		bool is_user_context = _is_user_context();		      \
+		bool is_user_context = _is_user_context();		       \
-									      \
+									       \
-		if (Z_LOG_CONST_LEVEL_CHECK(_level) &&			      \
+		if (Z_LOG_CONST_LEVEL_CHECK(_level)) {			       \
-		    (is_user_context ||					      \
+			if (IS_ENABLED(CONFIG_LOG_MINIMAL)) {		       \
-		     (_level <= LOG_RUNTIME_FILTER(_filter)))) {	      \
+				Z_LOG_TO_PRINTK(_level, "%s", _str);	       \
-			struct log_msg_ids src_level = {		      \
+				log_minimal_hexdump_print(_level, _data,       \
-				.level = _level,			      \
+							  _length);	       \
-				.source_id = _id,			      \
+			} else if (is_user_context ||			       \
-				.domain_id = CONFIG_LOG_DOMAIN_ID	      \
+				   (_level <= LOG_RUNTIME_FILTER(_filter))) {  \
-			};						      \
+				struct log_msg_ids src_level = {	       \
-									      \
+					.level = _level,		       \
-			if (is_user_context) {				      \
+					.source_id = _id,		       \
-				log_hexdump_from_user(src_level, _str,	      \
+					.domain_id = CONFIG_LOG_DOMAIN_ID      \
-						      _data, _length);	      \
+				};					       \
-			} else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {	      \
+									       \
-				log_hexdump_sync(src_level, _str,	      \
+				if (is_user_context) {			       \
-						 _data, _length);	      \
+					log_hexdump_from_user(src_level, _str, \
-			} else {					      \
+							      _data, _length); \
-				log_hexdump(_str, _data, _length, src_level); \
+				} else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \
-			}						      \
+					log_hexdump_sync(src_level, _str,      \
-		}							      \
+							 _data, _length);      \
+				} else {				       \
+					log_hexdump(_str, _data, _length,      \
+						    src_level);		       \
+				}					       \
+			}						       \
+		}							       \
 	} while (false)
 
 #define Z_LOG_HEXDUMP(_level, _data, _length, _str)	       \

include/logging/log_ctrl.h

@@ -169,7 +169,7 @@ void log_backend_enable(struct log_backend const *const backend,
  */
 void log_backend_disable(struct log_backend const *const backend);
 
-#if defined(CONFIG_LOG)
+#if defined(CONFIG_LOG) && !defined(CONFIG_LOG_MINIMAL)
 #define LOG_CORE_INIT() log_core_init()
 #define LOG_INIT() log_init()
 #define LOG_PANIC() log_panic()

subsys/logging/CMakeLists.txt

@@ -1,49 +1,53 @@
 # SPDX-License-Identifier: Apache-2.0
 
-zephyr_sources_ifdef(
+if(NOT CONFIG_LOG_MINIMAL)
-  CONFIG_LOG
+  zephyr_sources_ifdef(
-  log_list.c
+    CONFIG_LOG
-  log_core.c
+    log_list.c
-  log_msg.c
+    log_core.c
-  log_output.c
+    log_msg.c
+    log_output.c
   )
 
-zephyr_sources_ifdef(
+  zephyr_sources_ifdef(
-  CONFIG_LOG_BACKEND_UART
+    CONFIG_LOG_BACKEND_UART
-  log_backend_uart.c
+    log_backend_uart.c
   )
 
-zephyr_sources_ifdef(
+  zephyr_sources_ifdef(
-  CONFIG_LOG_CMDS
+    CONFIG_LOG_CMDS
-  log_cmds.c
+    log_cmds.c
   )
 
-zephyr_sources_ifdef(
+  zephyr_sources_ifdef(
-  CONFIG_LOG_BACKEND_NATIVE_POSIX
+    CONFIG_LOG_BACKEND_NATIVE_POSIX
-  log_backend_native_posix.c
+    log_backend_native_posix.c
   )
 
-zephyr_sources_ifdef(
+  zephyr_sources_ifdef(
-  CONFIG_LOG_BACKEND_XTENSA_SIM
+    CONFIG_LOG_BACKEND_XTENSA_SIM
-  log_backend_xtensa_sim.c
+    log_backend_xtensa_sim.c
   )
 
-zephyr_sources_ifdef(
+  zephyr_sources_ifdef(
-  CONFIG_LOG_BACKEND_NET
+    CONFIG_LOG_BACKEND_NET
-  log_backend_net.c
+    log_backend_net.c
   )
 
-zephyr_sources_ifdef(
+  zephyr_sources_ifdef(
-  CONFIG_LOG_BACKEND_RTT
+    CONFIG_LOG_BACKEND_RTT
-  log_backend_rtt.c
+    log_backend_rtt.c
-)
+  )
 
-zephyr_sources_ifdef(
+  zephyr_sources_ifdef(
-  CONFIG_LOG_BACKEND_SWO
+    CONFIG_LOG_BACKEND_SWO
-  log_backend_swo.c
+    log_backend_swo.c
-)
+  )
 
-zephyr_sources_ifdef(
+  zephyr_sources_ifdef(
-  CONFIG_LOG_BACKEND_QEMU_X86_64
+    CONFIG_LOG_BACKEND_QEMU_X86_64
-  log_backend_qemu_x86_64.c
+    log_backend_qemu_x86_64.c
-)
+  )
+else()
+  zephyr_sources(log_minimal.c)
+endif()

subsys/logging/Kconfig

@@ -13,9 +13,21 @@ menuconfig LOG
 
 if LOG
 
+config LOG_MINIMAL
+	bool "Enable minimal-footprint logging"
+	imply PRINTK
+	help
+	  Enable minimal logging implementation. This has very little footprint
+	  overhead on top of the printk() implementation for standard
+	  logging macros. Hexdump macros are also supported, with a small
+	  amount of code pulled in if used. Build time filtering is supported,
+	  but not runtime filtering. There are no timestamps, prefixes,
+	  colors, or asynchronous logging, and all messages are simply
+	  sent to printk().
+
 config LOG_RUNTIME_FILTERING
 	bool "Enable runtime reconfiguration of the logger"
-	depends on !LOG_FRONTEND
+	depends on !LOG_FRONTEND && !LOG_MINIMAL
 	help
 	  Allow runtime configuration of maximal, independent severity
 	  level for instance.
@@ -69,6 +81,8 @@ config LOG_MAX_LEVEL
 	  - 3 INFO, maximal level set to LOG_LEVEL_INFO
 	  - 4 DEBUG, maximal level set to LOG_LEVEL_DBG
 
+if !LOG_MINIMAL
+
 menu "Prepend log message with function name"
 	depends on !LOG_FRONTEND
 
@@ -477,4 +491,5 @@ config LOG_BACKEND_FORMAT_TIMESTAMP
 	help
 	  When enabled timestamp is formatted to hh:mm:ss:ms,us.
 
+endif # LOG_MINIMAL
 endif # LOG

subsys/logging/log_minimal.c

@@ -0,0 +1,50 @@
+/*
+ * Copyright (c) 2019 Intel Corporation.
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+#include <sys/printk.h>
+#include <ctype.h>
+#include <logging/log.h>
+
+#define HEXDUMP_BYTES_IN_LINE 8
+
+static void minimal_hexdump_line_print(const char *data, size_t length)
+{
+	for (int i = 0; i < HEXDUMP_BYTES_IN_LINE; i++) {
+		if (i < length) {
+			printk("%02x ", data[i] & 0xFF);
+		} else {
+			printk("   ");
+		}
+	}
+
+	printk("|");
+
+	for (int i = 0; i < HEXDUMP_BYTES_IN_LINE; i++) {
+		if (i < length) {
+			char c = data[i];
+
+			printk("%c", isprint((int)c) ? c : '.');
+		} else {
+			printk(" ");
+		}
+	}
+	printk("\n");
+}
+
+void log_minimal_hexdump_print(int level, const char *data, size_t size)
+{
+	while (size > 0) {
+		printk("%c: ", z_log_minimal_level_to_char(level));
+		minimal_hexdump_line_print(data, size);
+
+		if (size < HEXDUMP_BYTES_IN_LINE) {
+			break;
+		}
+
+		size -= HEXDUMP_BYTES_IN_LINE;
+		data += HEXDUMP_BYTES_IN_LINE;
+	}
+}

subsys/testsuite/Kconfig

@@ -83,11 +83,11 @@ config TEST_LOGGING_DEFAULTS
 	bool "Enable test case logging defaults"
 	depends on TEST
 	select LOG
-	select LOG_IMMEDIATE
+	select LOG_MINIMAL
 	default y
 	help
 	  Option which implements default policy of enabling logging in
-	  immediate mode for all test cases. For tests that need alternate
+	  minimal mode for all test cases. For tests that need alternate
 	  logging configuration, or no logging at all, disable this
 	  in the project-level defconfig.