From 841194baf511f0c03f48c8ca8e10f0a4818d041a Mon Sep 17 00:00:00 2001 From: Riven Zheng Date: Thu, 21 Mar 2024 21:22:55 +0800 Subject: [PATCH] Add time analysis trace to monitor rtos kernal use. --- build_version.h | 6 +-- include/kernal/at_rtos.h | 2 +- include/kernal/kernal.h | 6 ++- include/kernal/kstruct.h | 22 +++++++++ include/kernal/timer.h | 3 +- include/kernal/trace.h | 4 +- kernal/event.c | 4 ++ kernal/kernal.c | 101 +++++++++++++++++++++++++++++++++++++-- kernal/kthread.c | 8 ++-- kernal/mutex.c | 4 ++ kernal/queue.c | 4 ++ kernal/semaphore.c | 4 ++ kernal/thread.c | 13 ++++- kernal/timer.c | 44 +++++++++++++++-- kernal/trace.c | 8 ++-- package.json | 6 +-- 16 files changed, 212 insertions(+), 27 deletions(-) diff --git a/build_version.h b/build_version.h index d76486d..a106df6 100644 --- a/build_version.h +++ b/build_version.h @@ -12,11 +12,11 @@ extern "C" { #endif -#define ATOS_BUILD_TIME "2024-03-20,11:42" -#define ATOS_COMMIT_HEAD_ID "2473e49870fbf1d073cb4dc23a50e156472c63d3" +#define ATOS_BUILD_TIME "2024-03-21,21:21" +#define ATOS_COMMIT_HEAD_ID "e791fcee4eeb5ec0ef97ad0f98b4258cf4791f16" #define ATOS_VERSION_MAJOR_NUMBER (1u) #define ATOS_VERSION_MINOR_NUMBER (2u) -#define ATOS_VERSION_PATCH_NUMBER (9u) +#define ATOS_VERSION_PATCH_NUMBER (10u) #define ATOS_VERSION_MAJOR_NUMBER_MASK (0x03FFu) #define ATOS_VERSION_MAJOR_NUMBER_POS (22u) diff --git a/include/kernal/at_rtos.h b/include/kernal/at_rtos.h index ad1b7ec..3f54ce6 100644 --- a/include/kernal/at_rtos.h +++ b/include/kernal/at_rtos.h @@ -276,7 +276,7 @@ static inline u32p_t timer_isBusy(os_timer_id_t id) */ static inline u32_t timer_system_total_ms(void) { - return (u32_t)_impl_timer_total_system_get(); + return (u32_t)_impl_timer_total_system_ms_get(); } /** diff --git a/include/kernal/kernal.h b/include/kernal/kernal.h index 9be8ac6..6c8ffd7 100644 --- a/include/kernal/kernal.h +++ b/include/kernal/kernal.h @@ -75,10 +75,12 @@ b_t _impl_kernal_isInThreadMode(void); u32_t _impl_kernal_thread_schedule_request(void); void _impl_kernal_message_notification(void); void _impl_kernal_scheduler_inPendSV_c(u32_t **ppCurPsp, u32_t **ppNextPSP); +u32_t _impl_kernal_schedule_time_get(void); +u32_t impl_kernal_thread_use_percent_take(os_id_t id); void _impl_kernal_privilege_call_inSVC_c(u32_t *svc_args); u32_t _impl_kernal_privilege_invoke(const void *pCallFun, arguments_t *pArgs); -void _impl_kernal_atos_schedule_thread(void); -void _impl_kernal_atos_idle_thread(void); +void _impl_kernal_thread_schedule(void); +void _impl_kernal_thread_idle(void); void _impl_kernal_semaphore_list_transfer_toLock(linker_head_t *pCurHead); thread_context_t *_impl_kernal_thread_runContextGet(void); diff --git a/include/kernal/kstruct.h b/include/kernal/kstruct.h index 8dd8ac6..7a8b20e 100644 --- a/include/kernal/kstruct.h +++ b/include/kernal/kstruct.h @@ -11,6 +11,7 @@ #include "typedef.h" #include "linker.h" #include "unique.h" +#include "configuration.h" #ifdef __cplusplus extern "C" { @@ -153,8 +154,27 @@ typedef struct { pThread_callbackFunc_t pEntryCallFun; } thread_entry_t; +typedef struct { + u32_t pend_ms; + + u32_t run_ms; + + u32_t exit_ms; + + u32_t active_ms; + + u32_t cycle_ms; + + u16_t percent; +} analyze_t; + typedef struct { os_id_t hold; + +#if defined KTRACE + analyze_t analyze; +#endif + union { thread_exit_t exit; @@ -243,6 +263,8 @@ typedef struct { /* The kernal already start to do schedule */ b_t run; + + u32_t pendsv_ms; } kernal_context_t; typedef struct { diff --git a/include/kernal/timer.h b/include/kernal/timer.h index 8a817a6..c2c49b7 100644 --- a/include/kernal/timer.h +++ b/include/kernal/timer.h @@ -25,7 +25,8 @@ b_t _impl_timer_status_isBusy(os_id_t id); os_id_t _impl_timer_init(pTimer_callbackFunc_t pCallFun, b_t isCycle, u32_t timeout_ms, const char_t *pName); u32p_t _impl_timer_start(os_id_t id, b_t isCycle, u32_t timeout_ms); u32p_t _impl_timer_stop(os_id_t id); -u32_t _impl_timer_total_system_get(void); +u32_t _impl_timer_total_system_us_get(void); +u32_t _impl_timer_total_system_ms_get(void); void _impl_timer_reamining_elapsed_handler(void); void _impl_timer_elapsed_handler(u32_t elapsed_us); diff --git a/include/kernal/trace.h b/include/kernal/trace.h index aa7ce59..3c0e301 100644 --- a/include/kernal/trace.h +++ b/include/kernal/trace.h @@ -28,7 +28,9 @@ extern "C" { typedef struct { u32_t priority; u32_t current_psp; - u32_t usage; + u32_t ram; + u32_t cpu; + u32_t delay; } thread_snapshot_t; typedef struct { diff --git a/kernal/event.c b/kernal/event.c index 63b6338..e6e89df 100644 --- a/kernal/event.c +++ b/kernal/event.c @@ -404,6 +404,7 @@ static void _event_schedule(os_id_t id) */ b_t _impl_trace_event_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) { +#if defined KTRACE event_context_t *pCurEvent = NULL; u32_t offset = 0u; os_id_t id = OS_INVALID_ID; @@ -440,6 +441,9 @@ b_t _impl_trace_event_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) EXIT_CRITICAL_SECTION(); return TRUE; +#else + return FALSE; +#endif } #ifdef __cplusplus diff --git a/kernal/kernal.c b/kernal/kernal.c index 8adc123..8c7b501 100644 --- a/kernal/kernal.c +++ b/kernal/kernal.c @@ -53,6 +53,7 @@ static kernal_context_t g_kernal_resource = { .current = 0u, .list = LIST_NULL, .run = FALSE, + .pendsv_ms = 0u, .member = { .pListContainer = (list_t *)&g_kernal_member_list[0], @@ -84,6 +85,60 @@ static b_t _kernal_isInPrivilegeMode(void) return _impl_port_isInInterruptContent(); } +/** + * @brief Update pendsv executed time. + */ +static void _kernal_pendsv_time_update(void) +{ + g_kernal_resource.pendsv_ms = _impl_timer_total_system_ms_get(); +} + +/** + * @brief Get pendsv executed time. + * + * @return The value of pendsv executed time. + */ +static u32_t _kernal_pendsv_time_get(void) +{ + return g_kernal_resource.pendsv_ms; +} + +/** + * @brief Kernal schedule exit time analyze. + */ +static void _kernal_schedule_exit_time_analyze(os_id_t id) +{ + /* Nothing to do */ +} + +/** + * @brief Kernal schedule entry time analyze. + */ +static void _kernal_schedule_entry_time_analyze(os_id_t id) +{ +#if defined KTRACE + thread_context_t *pEntryThread = (thread_context_t *)_impl_kernal_member_unified_id_toContainerAddress(id); + pEntryThread->schedule.analyze.pend_ms = _kernal_pendsv_time_get(); +#endif +} + +/** + * @brief Kernal schedule run time analyze. + */ +static void _kernal_schedule_run_time_analyze(os_id_t from, os_id_t to) +{ +#if defined KTRACE + thread_context_t *pFromThread = (thread_context_t *)_impl_kernal_member_unified_id_toContainerAddress(from); + thread_context_t *pToThread = (thread_context_t *)_impl_kernal_member_unified_id_toContainerAddress(to); + u32_t sv_ms = _kernal_pendsv_time_get(); + + pFromThread->schedule.analyze.active_ms += (u32_t)(sv_ms - pFromThread->schedule.analyze.run_ms); + + pFromThread->schedule.analyze.exit_ms = sv_ms; + pToThread->schedule.analyze.run_ms = sv_ms; +#endif +} + /** * @brief Get the thread PSP stack address. * @@ -91,7 +146,7 @@ static b_t _kernal_isInPrivilegeMode(void) * * @return The PSP stacke address. */ -u32_t *_kernal_thread_PSP_Get(os_id_t id) +static u32_t *_kernal_thread_PSP_Get(os_id_t id) { thread_context_t *pCurThread = (thread_context_t *)_impl_kernal_member_unified_id_toContainerAddress(id); @@ -176,6 +231,7 @@ static void _kernal_thread_entry_schedule(void) pCurThread->schedule.hold = OS_INVALID_ID; } + _kernal_schedule_entry_time_analyze(pCurThread->head.id); _impl_kernal_thread_list_transfer_toPend((linker_head_t *)&pCurThread->head); } } @@ -207,6 +263,7 @@ static b_t _kernal_thread_exit_schedule(void) } } + _kernal_schedule_exit_time_analyze(pCurThread->head.id); _kernal_thread_list_transfer_toTargetBlocking((linker_head_t *)&pCurThread->head, (list_t *)pExit->pToList); } @@ -273,6 +330,37 @@ static u32_t _kernal_member_id_toUnifiedIdRange(u8_t member_id) return (u32_t)(_kernal_member_id_toUnifiedIdEnd(member_id) - _impl_kernal_member_id_toUnifiedIdStart(member_id)); } +/** + * @brief Get pendsv executed time. + * + * @return The value of pendsv executed time. + */ +u32_t _impl_kernal_schedule_time_get(void) +{ + return _kernal_pendsv_time_get(); +} + +/** + * @brief Kernal thread use percent value take. + * + * @return The value of thread use percent. + */ +u32_t impl_kernal_thread_use_percent_take(os_id_t id) +{ +#if defined KTRACE + thread_context_t *pCurThread = (thread_context_t *)_impl_kernal_member_unified_id_toContainerAddress(id); + + pCurThread->schedule.analyze.percent = + (pCurThread->schedule.analyze.active_ms * 1000u) / (_kernal_pendsv_time_get() - pCurThread->schedule.analyze.cycle_ms); + pCurThread->schedule.analyze.active_ms = 0u; + pCurThread->schedule.analyze.cycle_ms = _kernal_pendsv_time_get(); + + return pCurThread->schedule.analyze.percent; +#else + return 0u; +#endif +} + /** * @brief kernal schedule in PendSV interrupt content. * @@ -281,10 +369,11 @@ static u32_t _kernal_member_id_toUnifiedIdRange(u8_t member_id) */ void _impl_kernal_scheduler_inPendSV_c(u32_t **ppCurPsp, u32_t **ppNextPSP) { + _kernal_pendsv_time_update(); + if (_kernal_thread_exit_schedule()) { _impl_kernal_timer_schedule_request(); } - _kernal_thread_entry_schedule(); os_id_t next = _kernal_thread_nextIdGet(); @@ -292,6 +381,7 @@ void _impl_kernal_scheduler_inPendSV_c(u32_t **ppCurPsp, u32_t **ppNextPSP) *ppCurPsp = (u32_t *)_kernal_thread_PSP_Get(g_kernal_resource.current); *ppNextPSP = (u32_t *)_kernal_thread_PSP_Get(next); + _kernal_schedule_run_time_analyze(g_kernal_resource.current, next); g_kernal_resource.current = next; } @@ -765,7 +855,7 @@ static u32_t _kernal_message_arrived(void) /** * @brief The kernal thread only serve for RTOS with highest priority. */ -void _impl_kernal_atos_schedule_thread(void) +void _impl_kernal_thread_schedule(void) { while (1) { u32p_t postcode = _kernal_message_arrived(); @@ -775,13 +865,16 @@ void _impl_kernal_atos_schedule_thread(void) } } +u32_t g_idle_cnt = 0; + /** * @brief The idle thread entry function. */ -void _impl_kernal_atos_idle_thread(void) +void _impl_kernal_thread_idle(void) { while (1) { /* TODO: Power Management */ + g_idle_cnt++; } } diff --git a/kernal/kthread.c b/kernal/kthread.c index 36cea3e..2deeb41 100644 --- a/kernal/kthread.c +++ b/kernal/kthread.c @@ -143,10 +143,10 @@ void _impl_kernal_thread_init(void) { .level = OS_PRIORITY_KERNAL_THREAD_SCHEDULE_LEVEL, }, - .pEntryFunc = _impl_kernal_atos_schedule_thread, + .pEntryFunc = _impl_kernal_thread_schedule, .pStackAddr = (u32_t *)&_kernal_schedule[0], .stackSize = KERNAL_SCHEDULE_THREAD_STACK_SIZE, - .PSPStartAddr = (u32_t)_impl_kernal_stack_frame_init(_impl_kernal_atos_schedule_thread, (u32_t *)&_kernal_schedule[0], + .PSPStartAddr = (u32_t)_impl_kernal_stack_frame_init(_impl_kernal_thread_schedule, (u32_t *)&_kernal_schedule[0], KERNAL_SCHEDULE_THREAD_STACK_SIZE), }, @@ -163,10 +163,10 @@ void _impl_kernal_thread_init(void) { .level = OS_PRIORITY_KERNAL_THREAD_IDLE_LEVEL, }, - .pEntryFunc = _impl_kernal_atos_idle_thread, + .pEntryFunc = _impl_kernal_thread_idle, .pStackAddr = (u32_t *)&_kernal_idle[0], .stackSize = KERNAL_IDLE_THREAD_STACK_SIZE, - .PSPStartAddr = (u32_t)_impl_kernal_stack_frame_init(_impl_kernal_atos_idle_thread, (u32_t *)&_kernal_idle[0], + .PSPStartAddr = (u32_t)_impl_kernal_stack_frame_init(_impl_kernal_thread_idle, (u32_t *)&_kernal_idle[0], KERNAL_IDLE_THREAD_STACK_SIZE), }, }; diff --git a/kernal/mutex.c b/kernal/mutex.c index 5e93ef7..eb96739 100644 --- a/kernal/mutex.c +++ b/kernal/mutex.c @@ -361,6 +361,7 @@ static u32_t _mutex_unlock_privilege_routine(arguments_t *pArgs) */ b_t _impl_trace_mutex_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) { +#if defined KTRACE mutex_context_t *pCurMutex = NULL; u32_t offset = 0u; os_id_t id = OS_INVALID_ID; @@ -399,6 +400,9 @@ b_t _impl_trace_mutex_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) EXIT_CRITICAL_SECTION(); return TRUE; +#else + return FALSE; +#endif } #ifdef __cplusplus diff --git a/kernal/queue.c b/kernal/queue.c index e075357..d65bfaa 100644 --- a/kernal/queue.c +++ b/kernal/queue.c @@ -628,6 +628,7 @@ static void _queue_schedule(os_id_t id) */ b_t _impl_trace_queue_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) { +#if defined KTRACE queue_context_t *pCurQueue = NULL; u32_t offset = 0u; os_id_t id = OS_INVALID_ID; @@ -664,6 +665,9 @@ b_t _impl_trace_queue_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) EXIT_CRITICAL_SECTION(); return TRUE; +#else + return FALSE; +#endif } #ifdef __cplusplus diff --git a/kernal/semaphore.c b/kernal/semaphore.c index b3a73eb..69983b9 100644 --- a/kernal/semaphore.c +++ b/kernal/semaphore.c @@ -528,6 +528,7 @@ static void _semaphore_schedule(os_id_t id) */ b_t _impl_trace_semaphore_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) { +#if defined KTRACE semaphore_context_t *pCurSemaphore = NULL; u32_t offset = 0u; os_id_t id = OS_INVALID_ID; @@ -568,6 +569,9 @@ b_t _impl_trace_semaphore_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) EXIT_CRITICAL_SECTION(); return TRUE; +#else + return FALSE; +#endif } #ifdef __cplusplus diff --git a/kernal/thread.c b/kernal/thread.c index f47889c..d5e4869 100644 --- a/kernal/thread.c +++ b/kernal/thread.c @@ -592,9 +592,11 @@ static u32p_t _thread_sleep_privilege_routine(arguments_t *pArgs) */ b_t _impl_trace_thread_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) { +#if defined KTRACE thread_context_t *pCurThread = NULL; u32_t offset = 0u; os_id_t id = OS_INVALID_ID; + u32_t sv_ms = 0u; ENTER_CRITICAL_SECTION(); @@ -608,16 +610,21 @@ b_t _impl_trace_thread_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) return FALSE; } + sv_ms = _impl_kernal_schedule_time_get(); if (pCurThread->head.linker.pList == _thread_list_waitingHeadGet()) { pMsgs->pState = "wait"; + pMsgs->thread.delay = sv_ms - pCurThread->schedule.analyze.exit_ms; } else if (pCurThread->head.linker.pList == _thread_list_pendingHeadGet()) { if (id == _thread_id_runtime_get()) { pMsgs->pState = "run"; + pMsgs->thread.delay = sv_ms - pCurThread->schedule.analyze.run_ms; } else { pMsgs->pState = "pend"; + pMsgs->thread.delay = sv_ms - pCurThread->schedule.analyze.pend_ms; } } else if (pCurThread->head.linker.pList) { pMsgs->pState = "wait"; + pMsgs->thread.delay = sv_ms - pCurThread->schedule.analyze.exit_ms; } else { pMsgs->pState = "unused"; @@ -639,10 +646,14 @@ b_t _impl_trace_thread_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) unused++; } unused *= sizeof(u32_t); - pMsgs->thread.usage = ((pCurThread->stackSize - unused) * 100u) / pCurThread->stackSize; + pMsgs->thread.ram = ((pCurThread->stackSize - unused) * 100u) / pCurThread->stackSize; + pMsgs->thread.cpu = impl_kernal_thread_use_percent_take(pCurThread->head.id); EXIT_CRITICAL_SECTION(); return TRUE; +#else + return FALSE; +#endif } #ifdef __cplusplus diff --git a/kernal/timer.c b/kernal/timer.c index f2b6427..903b68e 100644 --- a/kernal/timer.c +++ b/kernal/timer.c @@ -42,7 +42,8 @@ _timer_resource_t g_timer_resource = {0u}; static u32_t _timer_init_privilege_routine(arguments_t *pArgs); static u32_t _timer_start_privilege_routine(arguments_t *pArgs); static u32_t _timer_stop_privilege_routine(arguments_t *pArgs); -static u32_t _timer_total_system_get_privilege_routine(arguments_t *pArgs); +static u32_t _timer_total_system_ms_get_privilege_routine(arguments_t *pArgs); +static u32_t _timer_total_system_us_get_privilege_routine(arguments_t *pArgs); static u32_t _kernal_timer_schedule_request_privilege_routine(arguments_t *pArgs); /** @@ -471,9 +472,19 @@ b_t _impl_timer_status_isBusy(os_id_t id) * * @return The value of the total system time (ms). */ -u32_t _impl_timer_total_system_get(void) +u32_t _impl_timer_total_system_ms_get(void) { - return _impl_kernal_privilege_invoke((const void *)_timer_total_system_get_privilege_routine, NULL); + return _impl_kernal_privilege_invoke((const void *)_timer_total_system_ms_get_privilege_routine, NULL); +} + +/** + * @brief Get the kernal RTOS system time (us). + * + * @return The value of the total system time (us). + */ +u32_t _impl_timer_total_system_us_get(void) +{ + return _impl_kernal_privilege_invoke((const void *)_timer_total_system_us_get_privilege_routine, NULL); } /** @@ -605,7 +616,7 @@ static u32_t _timer_stop_privilege_routine(arguments_t *pArgs) * * @return The result of privilege routine. */ -static u32_t _timer_total_system_get_privilege_routine(arguments_t *pArgs) +static u32_t _timer_total_system_ms_get_privilege_routine(arguments_t *pArgs) { ENTER_CRITICAL_SECTION(); @@ -621,6 +632,27 @@ static u32_t _timer_total_system_get_privilege_routine(arguments_t *pArgs) return ms; } +/** + * @brief It's sub-routine running at privilege mode. + * + * @param pArgs The function argument packages. + * + * @return The result of privilege routine. + */ +static u32_t _timer_total_system_us_get_privilege_routine(arguments_t *pArgs) +{ + ENTER_CRITICAL_SECTION(); + + UNUSED_MSG(pArgs); + + u32_t us = (u32_t)((!g_timer_resource.remaining_us) ? (_impl_clock_time_elapsed_get()) : (0u)); + + us += g_timer_resource.system_us; + + EXIT_CRITICAL_SECTION(); + return us; +} + /** * @brief It's sub-routine running at privilege mode. * @@ -748,6 +780,7 @@ void _impl_timer_elapsed_handler(u32_t elapsed_us) */ b_t _impl_trace_timer_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) { +#if defined KTRACE timer_context_t *pCurTimer = NULL; u32_t offset = 0u; os_id_t id = OS_INVALID_ID; @@ -791,6 +824,9 @@ b_t _impl_trace_timer_snapshot(u32_t instance, kernal_snapshot_t *pMsgs) EXIT_CRITICAL_SECTION(); return TRUE; +#else + return FALSE; +#endif } #ifdef __cplusplus diff --git a/kernal/trace.c b/kernal/trace.c index 95864df..eac09d5 100644 --- a/kernal/trace.c +++ b/kernal/trace.c @@ -64,11 +64,13 @@ void _impl_trace_kernal_snapshot_print(void) _impl_trace_firmware_snapshot_print(); _impl_trace_postcode_snapshot_print(); - KTRACE(">> %-6s %-15s %-5s %-7s %-3s %-10s %-6s\n", "Thread", "Name", "ID", "STATE", "PRI", "PSP_ADDR", "USE(%)"); + KTRACE(">> %-6s %-15s %-5s %-7s %-3s %-10s %-7s %-9s %-10s\n", "Thread", "Name", "ID", "STATE", "PRI", "PSP_ADDR", "RAM(1%)", + "CPU(0.1%)", "W/P/R(ms)"); for (u32_t i = 0u; i < THREAD_INSTANCE_SUPPORTED_NUMBER; i++) { if (_impl_trace_thread_snapshot(i, &snapshot_data)) { - KTRACE(" %-6d %-15s %-5d %-7s %-3d 0x%-8x %-3d\n", (i + 1u), snapshot_data.pName, snapshot_data.id, snapshot_data.pState, - snapshot_data.thread.priority, snapshot_data.thread.current_psp, snapshot_data.thread.usage); + KTRACE(" %-6d %-15s %-5d %-7s %-3d 0x%-8x %-7d %-9d %-10d\n", (i + 1u), snapshot_data.pName, snapshot_data.id, + snapshot_data.pState, snapshot_data.thread.priority, snapshot_data.thread.current_psp, snapshot_data.thread.ram, + snapshot_data.thread.cpu, snapshot_data.thread.delay); } else { unused[0]++; } diff --git a/package.json b/package.json index 466d532..80e01a9 100644 --- a/package.json +++ b/package.json @@ -1,7 +1,7 @@ { "name": "At-RTOS", "homepage": "https://github.com/At-EC/At-RTOS", - "version": "1.2.9", - "timestamp": "2024-03-20,11:42", - "commit_id": "9448ad094554b116852766d85667479349978042" + "version": "1.2.10", + "timestamp": "2024-03-21,21:21", + "commit_id": "2473e49870fbf1d073cb4dc23a50e156472c63d3" }