doc: subsys: logging: internal thread and thread wake up

Documenting new logger features: waking up processing thread
and internal logger processing thread.

Signed-off-by: Krzysztof Chruscinski <[email protected]>

Author: nordic-krch

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

@@ -47,7 +47,9 @@ void log_init(void);
  *
  * See CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD.
  *
- * @param process_tid Process thread id. Used to wake up the thread
+ * @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);
 
@@ -81,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/src/main.c

@@ -194,11 +194,19 @@ static void external_log_system_showcase(void)
 	ext_log_system_foo();
 }
 
+static void wait_on_log_flushed(void)
+{
+	while (log_buffered_cnt()) {
+		k_sleep(5);
+	}
+}
+
 void log_demo_thread(void *dummy1, void *dummy2, void *dummy3)
 {
-	const u32_t sleep_period = CONFIG_LOG_PROCESS_THREAD_SLEEP_MS + 100;
+	k_sleep(100);
 
 	(void)log_set_timestamp_func(timestamp_get, timestamp_freq());
+
 	module_logging_showcase();
 
 	instance_logging_showcase();
@@ -218,20 +226,19 @@ void log_demo_thread(void *dummy1, void *dummy2, void *dummy3)
 		       log_source_id_get(INST2_NAME),
 		       CONFIG_LOG_DEFAULT_LEVEL);
 
-	/* Ensuring that log thread will process. */
-	k_sleep(sleep_period);
+	wait_on_log_flushed();
 
 	severity_levels_showcase();
-	/* Ensuring that log thread will process. */
-	k_sleep(sleep_period);
+
+	wait_on_log_flushed();
 
 	performance_showcase();
-	/* Ensuring that log thread will process. */
-	k_sleep(sleep_period);
+
+	wait_on_log_flushed();
 
 	external_log_system_showcase();
-	/* Ensuring that log thread will process. */
-	k_sleep(sleep_period);
+
+	wait_on_log_flushed();
 }
 
 K_THREAD_DEFINE(log_demo_thread_id, STACKSIZE, log_demo_thread,

subsys/logging/Kconfig

@@ -214,7 +214,8 @@ config LOG_PROCESS_TRIGGER_THRESHOLD
 	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.
+	  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"
@@ -225,14 +226,30 @@ config LOG_PROCESS_THREAD
 	  number of buffered messages exceeds the threshold (see
 	  LOG_PROCESS_TRIGGER_THR).
 
+if LOG_PROCESS_THREAD
+
 config LOG_PROCESS_THREAD_SLEEP_MS
-	int "Set log processing thread sleep period"
-	depends on LOG_PROCESS_THREAD
+	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."
 	default 1024

subsys/logging/log_core.c

@@ -46,9 +46,10 @@ static inline void msg_finalize(struct log_msg *msg,
 	msg->hdr.ids = src_level;
 	msg->hdr.timestamp = timestamp_func();
 
+	atomic_inc(&buffered_cnt);
+
 	if (!IS_ENABLED(CONFIG_LOG_INPLACE_PROCESS) &&
 	    CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) {
-		atomic_inc(&buffered_cnt);
 		if (buffered_cnt == CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD &&
 		    proc_tid) {
 			k_wakeup(proc_tid);
@@ -224,7 +225,6 @@ void log_init(void)
 	timestamp_func = timestamp_get;
 	log_output_timestamp_freq_set(CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC);
 
-
 	/* Assign ids to backends. */
 	for (i = 0; i < log_backend_count_get(); i++) {
 		log_backend_id_set(log_backend_get(i),
@@ -239,7 +239,7 @@ void log_init(void)
 #endif
 }
 
-void log_thread_set(k_tid_t process_tid)
+static void thread_set(k_tid_t process_tid)
 {
 	proc_tid = process_tid;
 
@@ -251,6 +251,15 @@ void log_thread_set(k_tid_t process_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) {
@@ -332,6 +341,11 @@ bool log_process(bool 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();
@@ -444,13 +458,10 @@ u32_t log_filter_get(struct log_backend const *const backend,
 }
 
 #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());
+	thread_set(k_current_get());
 
 	while (1) {
 		if (log_process(false) == false) {
@@ -459,7 +470,7 @@ static void log_process_thread_func(void *dummy1, void *dummy2, void *dummy3)
 	}
 }
 
-K_THREAD_DEFINE(log_process_thread, STACKSIZE, log_process_thread_func,
-		NULL, NULL, NULL,
-		K_LOWEST_APPLICATION_THREAD_PRIO, 0, K_NO_WAIT);
+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 */