Tracing: Thread tracing

Add thread tracing hooks, default hooks, and documentation.

Signed-off-by: Torbjörn Leksell <torbjorn.leksell@percepio.com>

include/tracing/tracing.h

@@ -35,70 +35,6 @@
  * @defgroup tracing_apis Tracing APIs
  * @{
  */
-/**
- * @brief Called before a thread has been selected to run
- */
-#define sys_trace_thread_switched_out()
-
-/**
- * @brief Called after a thread has been selected to run
- */
-#define sys_trace_thread_switched_in()
-
-/**
- * @brief Called when setting priority of a thread
- * @param thread Thread structure
- */
-#define sys_trace_thread_priority_set(thread)
-
-/**
- * @brief Called when a thread is being created
- * @param thread Thread structure
- */
-#define sys_trace_thread_create(thread)
-
-/**
- * @brief Called when a thread is being aborted
- * @param thread Thread structure
- *
- */
-#define sys_trace_thread_abort(thread)
-
-/**
- * @brief Called when a thread is being suspended
- * @param thread Thread structure
- */
-#define sys_trace_thread_suspend(thread)
-
-/**
- * @brief Called when a thread is being resumed from suspension
- * @param thread Thread structure
- */
-#define sys_trace_thread_resume(thread)
-
-/**
- * @brief Called when a thread is ready to run
- * @param thread Thread structure
- */
-#define sys_trace_thread_ready(thread)
-
-/**
- * @brief Called when a thread is pending
- * @param thread Thread structure
- */
-#define sys_trace_thread_pend(thread)
-
-/**
- * @brief Provide information about specific thread
- * @param thread Thread structure
- */
-#define sys_trace_thread_info(thread)
-
-/**
- * @brief Called when a thread name is set
- * @param thread Thread structure
- */
-#define sys_trace_thread_name_set(thread)
 
 /**
  * @brief Called when entering an ISR
@@ -115,18 +51,6 @@
  */
 #define sys_trace_isr_exit_to_scheduler()
 
-/**
- * @brief Can be called with any id signifying a new call
- * @param id ID of the operation that was started
- */
-#define sys_trace_void(id)
-
-/**
- * @brief Can be called with any id signifying ending a call
- * @param id ID of the operation that was completed
- */
-#define sys_trace_end_call(id)
-
 /**
  * @brief Called when the cpu enters the idle state
  */
@@ -143,6 +67,253 @@
  */
 
 
+/**
+ * @brief Thread Tracing APIs
+ * @defgroup thread_tracing_apis Thread Tracing APIs
+ * @ingroup tracing_apis
+ * @{
+ */
+
+/**
+ * @brief Called when entering a k_thread_foreach call
+ */
+#define sys_port_trace_k_thread_foreach_enter()
+
+/**
+ * @brief Called when exiting a k_thread_foreach call
+ */
+#define sys_port_trace_k_thread_foreach_exit()
+
+/**
+ * @brief Called when entering a k_thread_foreach_unlocked
+ */
+#define sys_port_trace_k_thread_foreach_unlocked_enter()
+
+/**
+ * @brief Called when exiting a k_thread_foreach_unlocked
+ */
+#define sys_port_trace_k_thread_foreach_unlocked_exit()
+
+/**
+ * @brief Trace creating a Thread
+ * @param new_thread Thread object
+ */
+#define sys_port_trace_k_thread_create(new_thread)
+
+/**
+ * @brief Trace Thread entering user mode
+ */
+#define sys_port_trace_k_thread_user_mode_enter()
+
+/**
+ * @brief Called when entering a k_thread_join
+ * @param thread Thread object
+ * @param timeout Timeout period
+ */
+#define sys_port_trace_k_thread_join_enter(thread, timeout)
+
+/**
+ * @brief Called when k_thread_join blocks
+ * @param thread Thread object
+ * @param timeout Timeout period
+ */
+#define sys_port_trace_k_thread_join_blocking(thread, timeout)
+
+/**
+ * @brief Called when exiting k_thread_join
+ * @param thread Thread object
+ * @param timeout Timeout period
+ * @param ret Return value
+ */
+#define sys_port_trace_k_thread_join_exit(thread, timeout, ret)
+
+/**
+ * @brief Called when entering k_thread_sleep
+ * @param timeout Timeout period
+ */
+#define sys_port_trace_k_thread_sleep_enter(timeout)
+
+/**
+ * @brief Called when exiting k_thread_sleep
+ * @param timeout Timeout period
+ * @param ret Return value
+ */
+#define sys_port_trace_k_thread_sleep_exit(timeout, ret)
+
+/**
+ * @brief Called when entering k_thread_msleep
+ * @param ms Duration in milliseconds
+ */
+#define sys_port_trace_k_thread_msleep_enter(ms)
+
+/**
+ * @brief Called when exiting k_thread_msleep
+ * @param ms Duration in milliseconds
+ * @param ret Return value
+ */
+#define sys_port_trace_k_thread_msleep_exit(ms, ret)
+
+/**
+ * @brief Called when entering k_thread_usleep
+ * @param us Duration in microseconds
+ */
+#define sys_port_trace_k_thread_usleep_enter(us)
+
+/**
+ * @brief Called when exiting k_thread_usleep
+ * @param us Duration in microseconds
+ * @param ret Return value
+ */
+#define sys_port_trace_k_thread_usleep_exit(us, ret)
+
+/**
+ * @brief Called when entering k_thread_busy_wait
+ * @param usec_to_wait Duration in microseconds
+ */
+#define sys_port_trace_k_thread_busy_wait_enter(usec_to_wait)
+
+/**
+ * @brief Called when exiting k_thread_busy_wait
+ * @param usec_to_wait Duration in microseconds
+ */
+#define sys_port_trace_k_thread_busy_wait_exit(usec_to_wait)
+
+/**
+ * @brief Called when a thread yields
+ */
+#define sys_port_trace_k_thread_yield()
+
+/**
+ * @brief Called when a thread wakes up
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_wakeup(thread)
+
+/**
+ * @brief Called when a thread is started
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_start(thread)
+
+/**
+ * @brief Called when a thread is being aborted
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_abort(thread)
+
+/**
+ * @brief Called when setting priority of a thread
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_priority_set(thread)
+
+/**
+ * @brief Called when a thread is being suspended
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_suspend(thread)
+
+/**
+ * @brief Called when a thread is being resumed from suspension
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_resume(thread)
+
+/**
+ * @brief Called when the thread scheduler is locked
+ */
+#define sys_port_trace_k_thread_sched_lock()
+
+/**
+ * @brief Called when the thread sceduler is unlocked
+ */
+#define sys_port_trace_k_thread_sched_unlock()
+
+/**
+ * @brief Called when a thread name is set
+ * @param thread Thread object
+ * @param ret Return value
+ */
+#define sys_port_trace_k_thread_name_set(thread, ret)
+
+/**
+ * @brief Called before a thread has been selected to run
+ */
+#define sys_port_trace_k_thread_switched_out()
+
+/**
+ * @brief Called after a thread has been selected to run
+ */
+#define sys_port_trace_k_thread_switched_in()
+
+/**
+ * @brief Called when a thread is ready to run
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_ready(thread)
+
+/**
+ * @brief Called when a thread is pending
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_pend(thread)
+
+/**
+ * @brief Provide information about specific thread
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_info(thread)
+
+/**
+ * @brief Trace implicit thread wakup invocation by the scheduler
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_sched_wakeup(thread)
+
+/**
+ * @brief Trace implicit thread abort invocation by the scheduler
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_sched_abort(thread)
+
+/**
+ * @brief Trace implicit thread set priority invocation by the scheduler
+ * @param thread Thread object
+ * @param prio Thread priority
+ */
+#define sys_port_trace_k_thread_sched_priority_set(thread, prio)
+
+/**
+ * @brief Trace implicit thread ready invocation by the scheduler
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_sched_ready(thread)
+
+/**
+ * @brief Trace implicit thread pend invocation by the scheduler
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_sched_pend(thread)
+
+/**
+ * @brief Trace implicit thread resume invocation by the scheduler
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_sched_resume(thread)
+
+/**
+ * @brief Trace implicit thread suspend invocation by the scheduler
+ * @param thread Thread object
+ */
+#define sys_port_trace_k_thread_sched_suspend(thread)
+
+/**
+ * @}
+ */ /* end of thread_tracing_apis */
+
+
+
+
 /**
  * @brief Semaphore Tracing APIs
  * @defgroup sem_tracing_apis Semaphore Tracing APIs

kernel/include/ksched.h

@@ -141,13 +141,15 @@ static inline bool z_is_thread_queued(struct k_thread *thread)
 static inline void z_mark_thread_as_suspended(struct k_thread *thread)
 {
 	thread->base.thread_state |= _THREAD_SUSPENDED;
-	sys_trace_thread_suspend(thread);
+
+	SYS_PORT_TRACING_FUNC(k_thread, sched_suspend, thread);
 }
 
 static inline void z_mark_thread_as_not_suspended(struct k_thread *thread)
 {
 	thread->base.thread_state &= ~_THREAD_SUSPENDED;
-	sys_trace_thread_resume(thread);
+
+	SYS_PORT_TRACING_FUNC(k_thread, sched_resume, thread);
 }
 
 static inline void z_mark_thread_as_started(struct k_thread *thread)

kernel/sched.c

@@ -487,7 +487,8 @@ static void ready_thread(struct k_thread *thread)
 	 * run queue again
 	 */
 	if (!z_is_thread_queued(thread) && z_is_thread_ready(thread)) {
-		sys_trace_thread_ready(thread);
+		SYS_PORT_TRACING_OBJ_FUNC(k_thread, sched_ready, thread);
+
 		queue_thread(&_kernel.ready_q.runq, thread);
 		update_cache(0);
 #if defined(CONFIG_SMP) &&  defined(CONFIG_SCHED_IPI_SUPPORTED)
@@ -528,6 +529,8 @@ void z_sched_start(struct k_thread *thread)
 
 void z_impl_k_thread_suspend(struct k_thread *thread)
 {
+	SYS_PORT_TRACING_OBJ_FUNC_ENTER(k_thread, suspend, thread);
+
 	(void)z_abort_thread_timeout(thread);
 
 	LOCKED(&sched_spinlock) {
@@ -541,6 +544,8 @@ void z_impl_k_thread_suspend(struct k_thread *thread)
 	if (thread == _current) {
 		z_reschedule_unlocked();
 	}
+
+	SYS_PORT_TRACING_OBJ_FUNC_EXIT(k_thread, suspend, thread);
 }
 
 #ifdef CONFIG_USERSPACE
@@ -554,6 +559,8 @@ static inline void z_vrfy_k_thread_suspend(struct k_thread *thread)
 
 void z_impl_k_thread_resume(struct k_thread *thread)
 {
+	SYS_PORT_TRACING_OBJ_FUNC_ENTER(k_thread, resume, thread);
+
 	k_spinlock_key_t key = k_spin_lock(&sched_spinlock);
 
 	/* Do not try to resume a thread that was not suspended */
@@ -566,6 +573,8 @@ void z_impl_k_thread_resume(struct k_thread *thread)
 	ready_thread(thread);
 
 	z_reschedule(&sched_spinlock, key);
+
+	SYS_PORT_TRACING_OBJ_FUNC_EXIT(k_thread, resume, thread);
 }
 
 #ifdef CONFIG_USERSPACE
@@ -597,7 +606,8 @@ static void add_to_waitq_locked(struct k_thread *thread, _wait_q_t *wait_q)
 {
 	unready_thread(thread);
 	z_mark_thread_as_pending(thread);
-	sys_trace_thread_pend(thread);
+
+	SYS_PORT_TRACING_FUNC(k_thread, sched_pend, thread);
 
 	if (wait_q != NULL) {
 		thread->base.pended_on = wait_q;
@@ -760,7 +770,8 @@ bool z_set_prio(struct k_thread *thread, int prio)
 			thread->base.prio = prio;
 		}
 	}
-	sys_trace_thread_priority_set(thread);
+
+	SYS_PORT_TRACING_OBJ_FUNC(k_thread, sched_priority_set, thread, prio);
 
 	return need_sched;
 }
@@ -826,6 +837,8 @@ void z_reschedule_irqlock(uint32_t key)
 void k_sched_lock(void)
 {
 	LOCKED(&sched_spinlock) {
+		SYS_PORT_TRACING_FUNC(k_thread, sched_lock);
+
 		z_sched_lock();
 	}
 }
@@ -844,6 +857,8 @@ void k_sched_unlock(void)
 	LOG_DBG("scheduler unlocked (%p:%d)",
 		_current, _current->base.sched_locked);
 
+	SYS_PORT_TRACING_FUNC(k_thread, sched_unlock);
+
 	z_reschedule_unlocked();
 #endif
 }
@@ -1184,6 +1199,8 @@ void z_impl_k_yield(void)
 {
 	__ASSERT(!arch_is_in_isr(), "");
 
+	SYS_PORT_TRACING_FUNC(k_thread, yield);
+
 	if (!z_is_idle_thread_object(_current)) {
 		k_spinlock_key_t key = k_spin_lock(&sched_spinlock);
 
@@ -1259,19 +1276,27 @@ int32_t z_impl_k_sleep(k_timeout_t timeout)
 	k_ticks_t ticks;
 
 	__ASSERT(!arch_is_in_isr(), "");
-	sys_trace_void(SYS_TRACE_ID_SLEEP);
+
+	SYS_PORT_TRACING_FUNC_ENTER(k_thread, sleep, timeout);
 
 	/* in case of K_FOREVER, we suspend */
 	if (K_TIMEOUT_EQ(timeout, K_FOREVER)) {
 		k_thread_suspend(_current);
+
+		SYS_PORT_TRACING_FUNC_EXIT(k_thread, sleep, timeout, (int32_t) K_TICKS_FOREVER);
+
 		return (int32_t) K_TICKS_FOREVER;
 	}
 
 	ticks = timeout.ticks;
 
 	ticks = z_tick_sleep(ticks);
-	sys_trace_end_call(SYS_TRACE_ID_SLEEP);
+
-	return k_ticks_to_ms_floor64(ticks);
+	int32_t ret = k_ticks_to_ms_floor64(ticks);
+
+	SYS_PORT_TRACING_FUNC_EXIT(k_thread, sleep, timeout, ret);
+
+	return ret;
 }
 
 #ifdef CONFIG_USERSPACE
@@ -1286,8 +1311,13 @@ int32_t z_impl_k_usleep(int us)
 {
 	int32_t ticks;
 
+	SYS_PORT_TRACING_FUNC_ENTER(k_thread, usleep, us);
+
 	ticks = k_us_to_ticks_ceil64(us);
 	ticks = z_tick_sleep(ticks);
+
+	SYS_PORT_TRACING_FUNC_EXIT(k_thread, usleep, us, k_ticks_to_us_floor64(ticks));
+
 	return k_ticks_to_us_floor64(ticks);
 }
 
@@ -1301,6 +1331,8 @@ static inline int32_t z_vrfy_k_usleep(int us)
 
 void z_impl_k_wakeup(k_tid_t thread)
 {
+	SYS_PORT_TRACING_OBJ_FUNC(k_thread, wakeup, thread);
+
 	if (z_is_thread_pending(thread)) {
 		return;
 	}
@@ -1462,7 +1494,8 @@ static void end_thread(struct k_thread *thread)
 		unpend_all(&thread->join_queue);
 		update_cache(1);
 
-		sys_trace_thread_abort(thread);
+		SYS_PORT_TRACING_FUNC(k_thread, sched_abort, thread);
+
 		z_thread_monitor_exit(thread);
 
 #ifdef CONFIG_USERSPACE
@@ -1525,7 +1558,11 @@ void z_thread_abort(struct k_thread *thread)
 #if !defined(CONFIG_ARCH_HAS_THREAD_ABORT)
 void z_impl_k_thread_abort(struct k_thread *thread)
 {
+	SYS_PORT_TRACING_OBJ_FUNC_ENTER(k_thread, abort, thread);
+
 	z_thread_abort(thread);
+
+	SYS_PORT_TRACING_OBJ_FUNC_EXIT(k_thread, abort, thread);
 }
 #endif
 
@@ -1534,6 +1571,8 @@ int z_impl_k_thread_join(struct k_thread *thread, k_timeout_t timeout)
 	k_spinlock_key_t key = k_spin_lock(&sched_spinlock);
 	int ret = 0;
 
+	SYS_PORT_TRACING_OBJ_FUNC_ENTER(k_thread, join, thread, timeout);
+
 	if ((thread->base.thread_state & _THREAD_DEAD) != 0U) {
 		ret = 0;
 	} else if (K_TIMEOUT_EQ(timeout, K_NO_WAIT)) {
@@ -1545,9 +1584,16 @@ int z_impl_k_thread_join(struct k_thread *thread, k_timeout_t timeout)
 		__ASSERT(!arch_is_in_isr(), "cannot join in ISR");
 		add_to_waitq_locked(_current, &thread->join_queue);
 		add_thread_timeout(_current, timeout);
-		return z_swap(&sched_spinlock, key);
+
+		SYS_PORT_TRACING_OBJ_FUNC_BLOCKING(k_thread, join, thread, timeout);
+		ret = z_swap(&sched_spinlock, key);
+		SYS_PORT_TRACING_OBJ_FUNC_EXIT(k_thread, join, thread, timeout, ret);
+
+		return ret;
 	}
 
+	SYS_PORT_TRACING_OBJ_FUNC_EXIT(k_thread, join, thread, timeout, ret);
+
 	k_spin_unlock(&sched_spinlock, key);
 	return ret;
 }

kernel/thread.c

@@ -61,9 +61,15 @@ void k_thread_foreach(k_thread_user_cb_t user_cb, void *user_data)
 	 * k_thread_abort from user_cb.
 	 */
 	key = k_spin_lock(&z_thread_monitor_lock);
+
+	SYS_PORT_TRACING_FUNC_ENTER(k_thread, foreach);
+
 	for (thread = _kernel.threads; thread; thread = thread->next_thread) {
 		user_cb(thread, user_data);
 	}
+
+	SYS_PORT_TRACING_FUNC_EXIT(k_thread, foreach);
+
 	k_spin_unlock(&z_thread_monitor_lock, key);
 #endif
 }
@@ -77,11 +83,17 @@ void k_thread_foreach_unlocked(k_thread_user_cb_t user_cb, void *user_data)
 	__ASSERT(user_cb != NULL, "user_cb can not be NULL");
 
 	key = k_spin_lock(&z_thread_monitor_lock);
+
+	SYS_PORT_TRACING_FUNC_ENTER(k_thread, foreach_unlocked);
+
 	for (thread = _kernel.threads; thread; thread = thread->next_thread) {
 		k_spin_unlock(&z_thread_monitor_lock, key);
 		user_cb(thread, user_data);
 		key = k_spin_lock(&z_thread_monitor_lock);
 	}
+
+	SYS_PORT_TRACING_FUNC_EXIT(k_thread, foreach_unlocked);
+
 	k_spin_unlock(&z_thread_monitor_lock, key);
 #endif
 }
@@ -120,7 +132,6 @@ bool z_is_thread_essential(void)
 	return (_current->base.user_options & K_ESSENTIAL) == K_ESSENTIAL;
 }
 
-
 #ifdef CONFIG_THREAD_CUSTOM_DATA
 void z_impl_k_thread_custom_data_set(void *value)
 {
@@ -186,11 +197,16 @@ int z_impl_k_thread_name_set(struct k_thread *thread, const char *value)
 
 	strncpy(thread->name, value, CONFIG_THREAD_MAX_NAME_LEN);
 	thread->name[CONFIG_THREAD_MAX_NAME_LEN - 1] = '\0';
-	sys_trace_thread_name_set(thread);
+
+	SYS_PORT_TRACING_OBJ_FUNC(k_thread, name_set, thread, 0);
+
 	return 0;
 #else
 	ARG_UNUSED(thread);
 	ARG_UNUSED(value);
+
+	SYS_PORT_TRACING_OBJ_FUNC(k_thread, name_set, thread, -ENOSYS);
+
 	return -ENOSYS;
 #endif /* CONFIG_THREAD_NAME */
 }
@@ -348,6 +364,8 @@ void z_check_stack_sentinel(void)
 #ifdef CONFIG_MULTITHREADING
 void z_impl_k_thread_start(struct k_thread *thread)
 {
+	SYS_PORT_TRACING_OBJ_FUNC(k_thread, start, thread);
+
 	z_sched_start(thread);
 }
 
@@ -587,7 +605,8 @@ char *z_setup_new_thread(struct k_thread *new_thread,
 	new_thread->base.prio_deadline = 0;
 #endif
 	new_thread->resource_pool = _current->resource_pool;
-	sys_trace_thread_create(new_thread);
+
+	SYS_PORT_TRACING_OBJ_FUNC(k_thread, create, new_thread);
 
 #ifdef CONFIG_THREAD_RUNTIME_STATS
 	memset(&new_thread->rt_stats, 0, sizeof(new_thread->rt_stats));
@@ -771,6 +790,8 @@ void z_init_thread_base(struct _thread_base *thread_base, int priority,
 FUNC_NORETURN void k_thread_user_mode_enter(k_thread_entry_t entry,
 					    void *p1, void *p2, void *p3)
 {
+	SYS_PORT_TRACING_FUNC(k_thread, user_mode_enter);
+
 	_current->base.user_options |= K_USER;
 	z_thread_essential_clear();
 #ifdef CONFIG_THREAD_MONITOR
@@ -987,7 +1008,7 @@ static inline k_ticks_t z_vrfy_k_thread_timeout_expires_ticks(
 void z_thread_mark_switched_in(void)
 {
 #ifdef CONFIG_TRACING
-	sys_trace_thread_switched_in();
+	SYS_PORT_TRACING_FUNC(k_thread, switched_in);
 #endif
 
 #ifdef CONFIG_THREAD_RUNTIME_STATS
@@ -1042,7 +1063,7 @@ void z_thread_mark_switched_out(void)
 #endif /* CONFIG_THREAD_RUNTIME_STATS */
 
 #ifdef CONFIG_TRACING
-	sys_trace_thread_switched_out();
+	SYS_PORT_TRACING_FUNC(k_thread, switched_out);
 #endif
 }
 

kernel/timeout.c

@@ -299,7 +299,9 @@ static inline int64_t z_vrfy_k_uptime_ticks(void)
 
 void z_impl_k_busy_wait(uint32_t usec_to_wait)
 {
+	SYS_PORT_TRACING_FUNC_ENTER(k_thread, busy_wait, usec_to_wait);
 	if (usec_to_wait == 0U) {
+		SYS_PORT_TRACING_FUNC_EXIT(k_thread, busy_wait, usec_to_wait);
 		return;
 	}
 
@@ -324,6 +326,7 @@ void z_impl_k_busy_wait(uint32_t usec_to_wait)
 #else
 	arch_busy_wait(usec_to_wait);
 #endif /* CONFIG_ARCH_HAS_CUSTOM_BUSY_WAIT */
+	SYS_PORT_TRACING_FUNC_EXIT(k_thread, busy_wait, usec_to_wait);
 }
 
 #ifdef CONFIG_USERSPACE