kernel: Add thread events to kernel event logger

This adds a new event type to the kernel event logger that tracks
thread-related events: being added to the ready queue, pending a
thread, and exiting a thread.

It's the only event type that contains "subevents" and thus has a
non-void parameter in their respective _sys_k_event_logger_*()
function.  Luckily, as isn't the case with other events (such as IRQs
and thread switching), these functions are called from
platform-agnostic places, so there's no need to worry about changing
the assembly guts.

This is the first patch in a series adding support for better real-time
profiling of Zephyr applications.

Jira: ZEP-1463
Change-Id: I6d63607ba347f7a9cac3d016fef8f5a0a830e267
Signed-off-by: Leandro Pereira <leandro.pereira@intel.com>

include/logging/kernel_event_logger.h

@@ -23,6 +23,7 @@ extern "C" {
 #define KERNEL_EVENT_LOGGER_CONTEXT_SWITCH_EVENT_ID             0x0001
 #define KERNEL_EVENT_LOGGER_INTERRUPT_EVENT_ID                  0x0002
 #define KERNEL_EVENT_LOGGER_SLEEP_EVENT_ID                      0x0003
+#define KERNEL_EVENT_LOGGER_THREAD_EVENT_ID                     0x0004
 
 #ifndef _ASMLANGUAGE
 
@@ -33,14 +34,33 @@ extern int _sys_k_event_logger_mask;
 extern void _sys_k_event_logger_enter_sleep(void);
 extern void _sys_k_event_logger_exit_sleep(void);
 #else
-static inline void _sys_k_event_logger_enter_sleep(void) {};
+static inline void _sys_k_event_logger_enter_sleep(void) {}
-static inline void  _sys_k_event_logger_exit_sleep(void) {};
+static inline void _sys_k_event_logger_exit_sleep(void) {}
 #endif
 
 #ifdef CONFIG_KERNEL_EVENT_LOGGER_INTERRUPT
 extern void _sys_k_event_logger_interrupt(void);
 #else
-static inline void _sys_k_event_logger_interrupt(void) {};
+static inline void _sys_k_event_logger_interrupt(void) {}
+#endif
+
+#ifdef CONFIG_KERNEL_EVENT_LOGGER_THREAD
+#include <kernel.h>
+
+enum sys_k_event_logger_thread_event {
+	KERNEL_LOG_THREAD_EVENT_READYQ,
+	KERNEL_LOG_THREAD_EVENT_PEND,
+	KERNEL_LOG_THREAD_EVENT_EXIT,
+};
+
+extern void _sys_k_event_logger_thread_ready(struct k_thread *thread);
+extern void _sys_k_event_logger_thread_pend(struct k_thread *thread);
+extern void _sys_k_event_logger_thread_exit(struct k_thread *thread);
+#else
+static inline void _sys_k_event_logger_thread_create(void *thread) {}
+static inline void _sys_k_event_logger_thread_ready(void *thread) {}
+static inline void _sys_k_event_logger_thread_pend(void *thread) {}
+static inline void _sys_k_event_logger_thread_exit(void *thread) {}
 #endif
 
 /**

kernel/Kconfig.event_logger

@@ -70,6 +70,22 @@ config KERNEL_EVENT_LOGGER_SLEEP
 		- When the CPU went to sleep mode.
 		- When the CPU woke up.
 		- The ID of the interrupt that woke the CPU up.
+
+config KERNEL_EVENT_LOGGER_THREAD
+	bool
+	prompt "Thread event logging point"
+	default n
+	help
+	Enable thread event messages. These messages provide the following
+	information:
+
+		- When threads are marked as ready to be executed.
+		- When threads are marked as pending.
+		- When threads end.
+
+	Context switching messages should be enabled by enabling the
+	CONFIG_KERNEL_EVENT_LOGGER_CONTEXT_SWITCH setting instead.
+
 endmenu
 
 endif

kernel/include/ksched.h

@@ -9,6 +9,10 @@
 
 #include <kernel_structs.h>
 
+#ifdef CONFIG_KERNEL_EVENT_LOGGER
+#include <logging/kernel_event_logger.h>
+#endif /* CONFIG_KERNEL_EVENT_LOGGER */
+
 extern k_tid_t const _main_thread;
 extern k_tid_t const _idle_thread;
 
@@ -336,6 +340,10 @@ static inline int _is_thread_ready(struct k_thread *thread)
 static inline void _mark_thread_as_pending(struct k_thread *thread)
 {
 	thread->base.thread_state |= _THREAD_PENDING;
+
+#ifdef CONFIG_KERNEL_EVENT_LOGGER_THREAD
+	_sys_k_event_logger_thread_pend(thread);
+#endif
 }
 
 /* mark a thread as not pending in its TCS */
@@ -406,6 +414,10 @@ static inline void _ready_thread(struct k_thread *thread)
 	if (_is_thread_ready(thread)) {
 		_add_thread_to_ready_q(thread);
 	}
+
+#ifdef CONFIG_KERNEL_EVENT_LOGGER_THREAD
+	_sys_k_event_logger_thread_ready(thread);
+#endif
 }
 
 /**
@@ -416,6 +428,10 @@ static inline void _ready_thread(struct k_thread *thread)
 static inline void _mark_thread_as_dead(struct k_thread *thread)
 {
 	thread->base.thread_state |= _THREAD_DEAD;
+
+#ifdef CONFIG_KERNEL_EVENT_LOGGER_THREAD
+	_sys_k_event_logger_thread_exit(thread);
+#endif
 }
 
 /*

subsys/logging/kernel_event_logger.c

@@ -198,3 +198,37 @@ void _sys_k_event_logger_exit_sleep(void)
 	}
 }
 #endif /* CONFIG_KERNEL_EVENT_LOGGER_SLEEP */
+
+#ifdef CONFIG_KERNEL_EVENT_LOGGER_THREAD
+static void log_thread_event(enum sys_k_event_logger_thread_event event,
+			     struct k_thread *thread)
+{
+	uint32_t data[3];
+
+	if (!sys_k_must_log_event(KERNEL_EVENT_LOGGER_THREAD_EVENT_ID)) {
+		return;
+	}
+
+	data[0] = _sys_k_get_time();
+	data[1] = (uint32_t)(thread ? thread : _kernel.current);
+	data[2] = (uint32_t)event;
+
+	sys_k_event_logger_put(KERNEL_EVENT_LOGGER_THREAD_EVENT_ID, data,
+			       ARRAY_SIZE(data));
+}
+
+void _sys_k_event_logger_thread_ready(struct k_thread *thread)
+{
+	log_thread_event(KERNEL_LOG_THREAD_EVENT_READYQ, thread);
+}
+
+void _sys_k_event_logger_thread_pend(struct k_thread *thread)
+{
+	log_thread_event(KERNEL_LOG_THREAD_EVENT_PEND, thread);
+}
+
+void _sys_k_event_logger_thread_exit(struct k_thread *thread)
+{
+	log_thread_event(KERNEL_LOG_THREAD_EVENT_EXIT, thread);
+}
+#endif /* CONFIG_KERNEL_EVENT_LOGGER_THREAD */