From f17144349b985744d64e00ff48df362c895b9eae Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torbj=C3=B6rn=20Leksell?= Date: Fri, 26 Mar 2021 10:59:08 +0100 Subject: [PATCH] Tracing: Thread tracing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add thread tracing hooks, default hooks, and documentation. Signed-off-by: Torbjörn Leksell --- include/tracing/tracing.h | 323 +++++++++++++++++++++++++++++--------- kernel/include/ksched.h | 6 +- kernel/sched.c | 62 +++++++- kernel/thread.c | 31 +++- kernel/timeout.c | 3 + 5 files changed, 334 insertions(+), 91 deletions(-) diff --git a/include/tracing/tracing.h b/include/tracing/tracing.h index 44ffbeb8e20..c280d2e48e8 100644 --- a/include/tracing/tracing.h +++ b/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 diff --git a/kernel/include/ksched.h b/kernel/include/ksched.h index 066ab061da5..772eaf5f726 100644 --- a/kernel/include/ksched.h +++ b/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) diff --git a/kernel/sched.c b/kernel/sched.c index 5e515162cc2..b6aecd8a602 100644 --- a/kernel/sched.c +++ b/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; } diff --git a/kernel/thread.c b/kernel/thread.c index 0cb1063f8cd..b692d6c76d9 100644 --- a/kernel/thread.c +++ b/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 } diff --git a/kernel/timeout.c b/kernel/timeout.c index f3ad84808e8..877c2ae7187 100644 --- a/kernel/timeout.c +++ b/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