Logger process trigger

doc/subsystems/logging/logger.rst

@@ -109,6 +109,14 @@ be processed by printk. Longer strings are trimmed.
 the log macro call. Note that it can lead to errors when logger is used in the
 interrupt context.
 
+:option:`CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD`: When number of buffered log
+messages reaches the threshold dedicated thread (see :cpp:func:`log_thread_set`)
+is waken up. If :option:`CONFIG_LOG_PROCESS_THREAD` is enabled then this
+threshold is used by the internal thread.
+
+:option:`CONFIG_LOG_PROCESS_THREAD`: When enabled, logger is creating own thread
+which handles log processing.
+
 :option:`CONFIG_LOG_BUFFER_SIZE`: Number of bytes dedicated for the logger
 message pool. Single message capable of storing standard log with up to 3
 arguments or hexdump message with 12 bytes of data take 32 bytes.
@@ -221,6 +229,13 @@ be used to change maximal severity level for given module. Module is identified
 by source ID and domain ID. Source ID can be retrieved if source name is known
 by iterating through all registered sources.
 
+If logger is processed from a thread then it is possible to enable a feature
+which will wake up processing thread when certain amount of log messages are
+buffered (see :option:`CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD`). It is also
+possible to enable internal logger thread (see
+:option:`CONFIG_LOG_PROCESS_THREAD`). In that case logger thread is initialized
+and log messages are processed implicitly.
+
 .. _log_panic:
 
 Logger panic

include/logging/log_ctrl.h

@@ -42,6 +42,17 @@ void log_core_init(void);
  */
 void log_init(void);
 
+/**
+ * @brief Function for providing thread which is processing logs.
+ *
+ * See CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD.
+ *
+ * @note Function has asserts and has no effect when CONFIG_LOG_PROCESS is set.
+ *
+ * @param process_tid Process thread id. Used to wake up the thread.
+ */
+void log_thread_set(k_tid_t process_tid);
+
 /**
  * @brief Function for providing timestamp function.
  *
@@ -72,6 +83,13 @@ void log_panic(void);
  */
 bool log_process(bool bypass);
 
+/**
+ * @brief Return number of buffered log messages.
+ *
+ * @return Number of currently buffered log messages.
+ */
+u32_t log_buffered_cnt(void);
+
 /** @brief Get number of independent logger sources (modules and instances)
  *
  * @param domain_id Domain ID.

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",
-					cnt * timestamp_freq() / window);
+	per_sec = (cnt * timestamp_freq()) / window;
+	printk("Estimated logging capabilities: %d messages/second\n", per_sec);
 }
 
 static void external_log_system_showcase(void)
@@ -190,12 +194,18 @@ static void external_log_system_showcase(void)
 	ext_log_system_foo();
 }
 
-void main(void)
+static void wait_on_log_flushed(void)
 {
-	LOG_INIT();
+	while (log_buffered_cnt()) {
+		k_sleep(5);
+	}
+}
 
-	int err = log_set_timestamp_func(timestamp_get, timestamp_freq());
-	(void)err;
+void log_demo_thread(void *dummy1, void *dummy2, void *dummy3)
+{
+	k_sleep(100);
+
+	(void)log_set_timestamp_func(timestamp_get, timestamp_freq());
 
 	module_logging_showcase();
 
@@ -216,21 +226,21 @@ void main(void)
 		       log_source_id_get(INST2_NAME),
 		       CONFIG_LOG_DEFAULT_LEVEL);
 
-	while (true == LOG_PROCESS()) {
-	}
+	wait_on_log_flushed();
 
 	severity_levels_showcase();
 
-	while (true == LOG_PROCESS()) {
-	}
+	wait_on_log_flushed();
 
 	performance_showcase();
 
-	while (true == LOG_PROCESS()) {
-	}
+	wait_on_log_flushed();
 
 	external_log_system_showcase();
 
-	while (true == LOG_PROCESS()) {
-	}
+	wait_on_log_flushed();
 }
+
+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,54 @@ 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
-	  the context of the log entry (e.g. high priority interrupt). When enabled
-	  LOG_BUFFER_SIZE can be reduced. Logger backends must support exclusive
-	  access to work flawlessly in that mode because one log operation can be
-	  interrupted by another one in higher priority context.
+	  performance of the system since time consuming operations are
+	  performed in the context of the log entry (e.g. high priority
+	  interrupt). When enabled LOG_BUFFER_SIZE can be reduced. Logger
+	  backends must support exclusive access to work flawlessly in that mode
+	  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."
+	default 0
+	help
+	  When number of buffered messages reaches the threshold thread is waken
+	  up. Log processing thread ID is provided during log initialization.
+	  Set 0 to disable the feature. If LOG_PROCESS_THREAD is enabled then
+	  this threshold is used by the internal thread.
+
+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).
+
+if LOG_PROCESS_THREAD
+
+config LOG_PROCESS_THREAD_SLEEP_MS
+	int "Set internal log processing thread sleep period"
+	default 1000
+	help
+	  Log processing thread sleeps for requested period given in
+	  milliseconds. When waken up, thread process any buffered messages.
+
+config LOG_PROCESS_THREAD_PRIO
+	int "Priority of the log internal thread"
+	default -2
+	help
+	  Change with care since log processing can be time consuming thus it
+	  should be on low priority.
+
+config LOG_PROCESS_THREAD_STACK_SIZE
+	int "Stack size for the internal log processing thread"
+	default 768
+	help
+	  Set the internal stack size for log processing thread.
+
+endif
 
 config LOG_BUFFER_SIZE
 	int "Number of bytes dedicated for the logger internal buffer."

subsys/logging/log_core.c

@@ -13,6 +13,7 @@
 #include <assert.h>
 #include <atomic.h>
 #include <stdio.h>
+#include <atomic.h>
 
 #ifndef CONFIG_LOG_PRINTK_MAX_STRING_LENGTH
 #define CONFIG_LOG_PRINTK_MAX_STRING_LENGTH 1
@@ -26,6 +27,8 @@ LOG_BACKEND_UART_DEFINE(log_backend_uart);
 static struct log_list_t list;
 static atomic_t initialized;
 static bool panic_mode;
+static atomic_t buffered_cnt;
+static k_tid_t proc_tid;
 
 static u32_t dummy_timestamp(void);
 static timestamp_get_t timestamp_func = dummy_timestamp;
@@ -38,9 +41,22 @@ static u32_t dummy_timestamp(void)
 static inline void msg_finalize(struct log_msg *msg,
 				struct log_msg_ids src_level)
 {
+	unsigned int key;
+
 	msg->hdr.ids = src_level;
 	msg->hdr.timestamp = timestamp_func();
-	unsigned int key = irq_lock();
+
+	atomic_inc(&buffered_cnt);
+
+	if (!IS_ENABLED(CONFIG_LOG_INPLACE_PROCESS) &&
+	    CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) {
+		if (buffered_cnt == CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD &&
+		    proc_tid) {
+			k_wakeup(proc_tid);
+		}
+	}
+
+	key = irq_lock();
 
 	log_list_add_tail(&list, msg);
 
@@ -223,6 +239,27 @@ void log_init(void)
 #endif
 }
 
+static void thread_set(k_tid_t process_tid)
+{
+	proc_tid = process_tid;
+
+	if (!IS_ENABLED(CONFIG_LOG_INPLACE_PROCESS) &&
+	    CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD &&
+	    process_tid &&
+	    buffered_cnt >= CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) {
+		k_wakeup(proc_tid);
+	}
+}
+
+void log_thread_set(k_tid_t process_tid)
+{
+	if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
+		assert(0);
+	} else {
+		thread_set(process_tid);
+	}
+}
+
 int log_set_timestamp_func(timestamp_get_t timestamp_getter, u32_t freq)
 {
 	if (!timestamp_getter) {
@@ -297,12 +334,18 @@ bool log_process(bool bypass)
 	irq_unlock(key);
 
 	if (msg != NULL) {
+		atomic_dec(&buffered_cnt);
 		msg_process(msg, bypass);
 	}
 
 	return (log_list_head_peek(&list) != NULL);
 }
 
+u32_t log_buffered_cnt(void)
+{
+	return buffered_cnt;
+}
+
 u32_t log_src_cnt_get(u32_t domain_id)
 {
 	return log_sources_count();
@@ -413,3 +456,21 @@ u32_t log_filter_get(struct log_backend const *const backend,
 		return log_compiled_level_get(src_id);
 	}
 }
+
+#ifdef CONFIG_LOG_PROCESS_THREAD
+static void log_process_thread_func(void *dummy1, void *dummy2, void *dummy3)
+{
+	log_init();
+	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, CONFIG_LOG_PROCESS_THREAD_STACK_SIZE,
+		log_process_thread_func, NULL, NULL, NULL,
+		CONFIG_LOG_PROCESS_THREAD_PRIO, 0, K_NO_WAIT);
+#endif /* CONFIG_LOG_PROCESS_THREAD */