logging: Add internal thread for log processing

When enabled, logger is creating own thread which processes buffered
logs. When no logs to process, thread sleeps for configurable period.
Thread can be waken up if number of buffered log messages exceeds
configured threshold. Logging sample aligned to use new feature.

Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>

samples/subsys/logging/logger/prj.conf

@@ -1,4 +1,5 @@
 CONFIG_LOG=y
 CONFIG_LOG_RUNTIME_FILTERING=y
 CONFIG_LOG_BUFFER_SIZE=2048
-CONFIG_LOG_PRINTK=y
+CONFIG_LOG_PRINTK=y
+CONFIG_LOG_PROCESS_THREAD=y

samples/subsys/logging/logger/src/main.c

@@ -18,6 +18,9 @@
 #include <logging/log.h>
 LOG_MODULE_REGISTER();
 
+/* size of stack area used by each thread */
+#define STACKSIZE 1024
+
 extern void sample_module_func(void);
 
 #define INST1_NAME STRINGIFY(SAMPLE_INSTANCE_NAME.inst1)
@@ -157,28 +160,29 @@ static void severity_levels_showcase(void)
  */
 static void performance_showcase(void)
 {
+	volatile u32_t current_timestamp;
+	volatile u32_t start_timestamp;
+	u32_t per_sec;
+	u32_t cnt = 0;
+	u32_t window = 2;
 
 	printk("Logging performance showcase.\n");
 
-	volatile u32_t start_timestamp = timestamp_get();
+	start_timestamp = timestamp_get();
 
 	while (start_timestamp == timestamp_get()) {
 	}
 
 	start_timestamp = timestamp_get();
 
-	volatile u32_t current_timestamp;
-	u32_t cnt = 0;
-	u32_t window = 2;
-
 	do {
 		LOG_INF("performance test - log message %d", cnt);
 		cnt++;
 		current_timestamp = timestamp_get();
 	} while (current_timestamp < (start_timestamp + window));
 
-	printk("Estimated logging capabilities: %d messages/second\n",
+	per_sec = (cnt * timestamp_freq()) / window;
-					cnt * timestamp_freq() / window);
+	printk("Estimated logging capabilities: %d messages/second\n", per_sec);
 }
 
 static void external_log_system_showcase(void)
@@ -190,13 +194,11 @@ static void external_log_system_showcase(void)
 	ext_log_system_foo();
 }
 
-void main(void)
+void log_demo_thread(void *dummy1, void *dummy2, void *dummy3)
 {
-	LOG_INIT();
+	const u32_t sleep_period = CONFIG_LOG_PROCESS_THREAD_SLEEP_MS + 100;
-
-	int err = log_set_timestamp_func(timestamp_get, timestamp_freq());
-	(void)err;
 
+	(void)log_set_timestamp_func(timestamp_get, timestamp_freq());
 	module_logging_showcase();
 
 	instance_logging_showcase();
@@ -216,21 +218,22 @@ void main(void)
 		       log_source_id_get(INST2_NAME),
 		       CONFIG_LOG_DEFAULT_LEVEL);
 
-	while (true == LOG_PROCESS()) {
+	/* Ensuring that log thread will process. */
-	}
+	k_sleep(sleep_period);
 
 	severity_levels_showcase();
-
+	/* Ensuring that log thread will process. */
-	while (true == LOG_PROCESS()) {
+	k_sleep(sleep_period);
-	}
 
 	performance_showcase();
-
+	/* Ensuring that log thread will process. */
-	while (true == LOG_PROCESS()) {
+	k_sleep(sleep_period);
-	}
 
 	external_log_system_showcase();
-
+	/* Ensuring that log thread will process. */
-	while (true == LOG_PROCESS()) {
+	k_sleep(sleep_period);
-	}
 }
+
+K_THREAD_DEFINE(log_demo_thread_id, STACKSIZE, log_demo_thread,
+		NULL, NULL, NULL,
+		K_LOWEST_APPLICATION_THREAD_PRIO, 0, 1);

subsys/logging/Kconfig

@@ -201,11 +201,12 @@ config LOG_INPLACE_PROCESS
 	bool "Enable in place processing"
 	help
 	  When enabled log is processed in the context of the call. It impacts
-	  performance of the system since time consuming operations are performed in
+	  performance of the system since time consuming operations are
-	  the context of the log entry (e.g. high priority interrupt). When enabled
+	  performed in the context of the log entry (e.g. high priority
-	  LOG_BUFFER_SIZE can be reduced. Logger backends must support exclusive
+	  interrupt). When enabled LOG_BUFFER_SIZE can be reduced. Logger
-	  access to work flawlessly in that mode because one log operation can be
+	  backends must support exclusive access to work flawlessly in that mode
-	  interrupted by another one in higher priority context.
+	  because one log operation can be interrupted by another one in higher
+	  priority context.
 
 config LOG_PROCESS_TRIGGER_THRESHOLD
 	int "Amount of buffered logs which triggers processing thread."
@@ -215,6 +216,23 @@ config LOG_PROCESS_TRIGGER_THRESHOLD
 	  up. Log processing thread ID is provided during log initialization.
 	  Set 0 to disable the feature.
 
+config LOG_PROCESS_THREAD
+	bool "Enable internal thread for log processing"
+	depends on MULTITHREADING
+	help
+	  When enabled thread is created by the logger subsystem. Thread is
+	  waken up periodically (see LOG_PROCESS_THREAD_SLEEP_MS) and whenever
+	  number of buffered messages exceeds the threshold (see
+	  LOG_PROCESS_TRIGGER_THR).
+
+config LOG_PROCESS_THREAD_SLEEP_MS
+	int "Set log processing thread sleep period"
+	depends on LOG_PROCESS_THREAD
+	default 1000
+	help
+	  Log processing thread sleeps for requested period given in
+	  milliseconds. When waken up, thread process any buffered messages.
+
 config LOG_BUFFER_SIZE
 	int "Number of bytes dedicated for the logger internal buffer."
 	default 1024

subsys/logging/log_core.c

@@ -442,3 +442,24 @@ u32_t log_filter_get(struct log_backend const *const backend,
 		return log_compiled_level_get(src_id);
 	}
 }
+
+#ifdef CONFIG_LOG_PROCESS_THREAD
+
+#define STACKSIZE 768
+
+static void log_process_thread_func(void *dummy1, void *dummy2, void *dummy3)
+{
+	log_init();
+	log_thread_set(k_current_get());
+
+	while (1) {
+		if (log_process(false) == false) {
+			k_sleep(CONFIG_LOG_PROCESS_THREAD_SLEEP_MS);
+		}
+	}
+}
+
+K_THREAD_DEFINE(log_process_thread, STACKSIZE, log_process_thread_func,
+		NULL, NULL, NULL,
+		K_LOWEST_APPLICATION_THREAD_PRIO, 0, K_NO_WAIT);
+#endif /* CONFIG_LOG_PROCESS_THREAD */