Zephyr的Logging
1 前言
刚接触Zephyr，两眼一抹黑，光是阅读代码对系统没什么概念。还需要通过一些日志了解系统的运行机制，以及各种内核行为。
这就需要借助系统的Logging，大体分为两部分System Logging和Kernel Event Logger。
下面就分别介绍System Logging和Kernel Event Logger。
2 Kernel Event Logger
Logger记录内核特定性为，比如Interrupts、Context Switching、Sleep等。这些Log有助于优化应用，无论是进行debug还是性能调优。
2.1 Kernel Event Logger Configuration
Logger有很多内核相关配置选项，可以通过这些选项进行细化。
| 配置 | 解释 |
| Logger总开关。 | |
| 进程切换事件。 | |
| 中断事件。 | |
| 睡眠事件。 | |
| RingBuffer大小。 | |
| 将logging控制权交给应用自身。 | |
| 允许自定义时间戳函数。 |
2.2 Event定义
目前内核已经支持如下四中预定义Event，分别是进程切换、中断、睡眠、和线程。
这些事件被记录在内核的Ring Buffer中，应用可以读取然后分析内核行为。这些记录在Ring Buffer满之后，会被覆盖，因此必须及时读取。
默认情况下，内核打开所有事件记录。但是应用自身可以根据需要开关特定类型事件，或者选择特定时间段开关。
#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
2.2.1 时间戳
默认情况下，时间戳从Hardware clock取，这是一个32为的时钟计数，很容易溢出，需要将溢出计数进行记录。
同时，Logger的时间戳还可以通过sys_k_event_logger_set_timer()进行自定义。
2.2.2 事件读取
事件的读取可以通过如下函数进行，具体用法可以查看链接。
如下是代码示例：
u16_t event_id; u8_t dropped_count; u32_t data[3]; u8_t data_size; while(1) { /* retrieve an event */ data_size = SIZE32_OF(data); res = sys_k_event_logger_get_wait(&event_id, &dropped_count, data, &data_size); if (dropped_count > 0) { /* ... Process the dropped events count ... */ } if (res > 0) { /* process the event */ switch (event_id) { case KERNEL_EVENT_LOGGER_CONTEXT_SWITCH_EVENT_ID: /* ... Process the context switch event ... */ break; case KERNEL_EVENT_LOGGER_INTERRUPT_EVENT_ID: /* ... Process the interrupt event ... */ break; case KERNEL_EVENT_LOGGER_SLEEP_EVENT_ID: /* ... Process the sleep event ... */ break; default: printf("unrecognized event id %d\n", event_id); } } else if (res == -EMSGSIZE) { /* ... Data array is too small to hold the event! ... */ } }
2.2.3 增加自定义事件
首先需要在kernel_event_logger.h定义一个Event ID，ID总会不超过32.
自定义事件通过如下API写入到Logger中：
自定义事件接口函数内容如下：
#define MY_CUSTOM_EVENT_ID 8 /* record custom event only if recording is currently wanted */ if (sys_k_must_log_event(MY_CUSTOM_EVENT_ID)) { u32_t data[2]; data[0] = custom_data_1; data[1] = custom_data_2; sys_k_event_logger_put(MY_CUSTOM_EVENT_ID, data, ARRAY_SIZE(data)); }
应用调用此事件示例如下：
#define MY_CUSTOM_TIME_ONLY_EVENT_ID 9 if (sys_k_must_log_event(MY_CUSTOM_TIME_ONLY_EVENT_ID)) { sys_k_event_logger_put_timed(MY_CUSTOM_TIME_ONLY_EVENT_ID); }
2.3 系统预定义事件
KERNEL_EVENT_LOGGER_CONTEXT_SWITCH_EVENT_ID
在__pendsv(swap.S)中进行线程上下文切换，然后在这里记录事件。
SECTION_FUNC(TEXT, __pendsv) #ifdef CONFIG_KERNEL_EVENT_LOGGER_CONTEXT_SWITCH /* Register the context switch */ push {lr} bl _sys_k_event_logger_context_switch ... void _sys_k_event_logger_context_switch(void) { extern struct _kernel _kernel; u32_t data[2]; ... data[0] = _sys_k_get_time();----------------------------记录当前Hardware Cycles data[1] = (u32_t)_kernel.current;-----------------------记录切换出去的线程ID ... _sys_event_logger_put_non_preemptible(&sys_k_event_logger, KERNEL_EVENT_LOGGER_CONTEXT_SWITCH_EVENT_ID, data, ARRAY_SIZE(data)); }
KERNEL_EVENT_LOGGER_INTERRUPT_EVENT_ID
中断事件记录入口在中断处理函数中：
_timer_int_handler(cortex_x_systick.c)-->
_isr_wrapper(isr_wrapper.S)-->
_arch_isr_direct_header(irq_manage.c)-->
_sys_k_event_logger_interrupt
void _sys_k_event_logger_interrupt(void) { u32_t data[2]; if (!sys_k_must_log_event(KERNEL_EVENT_LOGGER_INTERRUPT_EVENT_ID)) { return; } /* if the kernel event logger has not been initialized, we do nothing */ if (sys_k_event_logger.ring_buf.buf == NULL) { return; } data[0] = _sys_k_get_time();-----------------记录Hardware cycles data[1] = _sys_current_irq_key_get();--------中断号 sys_k_event_logger_put(KERNEL_EVENT_LOGGER_INTERRUPT_EVENT_ID, data, ARRAY_SIZE(data)); }
KERNEL_EVENT_LOGGER_SLEEP_EVENT_ID
由于睡眠需要记录睡眠和唤醒点，以及导致唤醒的中断，所以参数有三个。
k_cpu_idle(cpu_idle.S)--> _sys_k_event_logger_enter_sleep void _sys_k_event_logger_enter_sleep(void) { if (!sys_k_must_log_event(KERNEL_EVENT_LOGGER_SLEEP_EVENT_ID)) { return; } _sys_k_event_logger_sleep_start_time = k_cycle_get_32();---------------------记录睡眠开始时间 } _isr_wrapper(isr_wrapper.S)--> _arch_isr_direct_header(irq_manage.c)--> _sys_k_event_logger_exit_sleep void _sys_k_event_logger_exit_sleep(void) { u32_t data[3]; if (!sys_k_must_log_event(KERNEL_EVENT_LOGGER_SLEEP_EVENT_ID)) { return; } if (_sys_k_event_logger_sleep_start_time != 0) { data[0] = _sys_k_get_time();-------------------------------------------------------------唤醒时间 data[1] = (k_cycle_get_32() - _sys_k_event_logger_sleep_start_time)----------------------记录睡眠持续时间 / sys_clock_hw_cycles_per_tick; /* register the cause of exiting sleep mode */ data[2] = _sys_current_irq_key_get();----------------------------------------------------唤醒中断号 ... _sys_k_event_logger_sleep_start_time = 0; sys_k_event_logger_put(KERNEL_EVENT_LOGGER_SLEEP_EVENT_ID, data, ARRAY_SIZE(data)); } }
KERNEL_EVENT_LOGGER_THREAD_EVENT_ID
_sys_k_event_logger_thread_ready--> _sys_k_event_logger_thread_pend--> _sys_k_event_logger_thread_exit--> log_thread_event static void log_thread_event(enum sys_k_event_logger_thread_event event, struct k_thread *thread) { u32_t data[3]; if (!sys_k_must_log_event(KERNEL_EVENT_LOGGER_THREAD_EVENT_ID)) { return; } data[0] = _sys_k_get_time(); data[1] = (u32_t)(thread ? thread : _kernel.current); data[2] = (u32_t)event;-----------------------------------记录当前线程的状态 sys_k_event_logger_put(KERNEL_EVENT_LOGGER_THREAD_EVENT_ID, data, ARRAY_SIZE(data)); }
enum sys_k_event_logger_thread_event {
KERNEL_LOG_THREAD_EVENT_READYQ,
KERNEL_LOG_THREAD_EVENT_PEND,
KERNEL_LOG_THREAD_EVENT_EXIT,
};
3 System Logging
另外应用还可以通过终端输出Log，系统System Logging定义了四中不同等级的SYS_LOG_X：SYS_LOG_ERR、SYS_LOG_WRN、SYS_LOG_INF、SYS_LOG_DBG。
#define SYS_LOG_LEVEL_OFF 0 #define SYS_LOG_LEVEL_ERROR 1 #define SYS_LOG_LEVEL_WARNING 2 #define SYS_LOG_LEVEL_INFO 3 #define SYS_LOG_LEVEL_DEBUG 4
关于Log等级有两种：全局性和模块内部。如果模组内部定义了Log等级，设置可以设置自己的Log等级。通过定义SYS_LOG_LEVEL且包含头文件sys_log.h。
3.1 System Logging配置
CONFIG_SYS_LOG: Global switch, turns on/off all system logging.System Logging开关
CONFIG_SYS_LOG_DEFAULT_LEVEL: Default level, sets the logging level used by modules that are not setting their own logging level.
CONFIG_SYS_LOG_SHOW_TAGS: Globally sets whether level tags will be shown on log or not.
CONFIG_SYS_LOG_SHOW_COLOR: Globally sets whether ANSI colors will be used by the system log.
CONFIG_SYS_LOG_OVERRIDE_LEVEL: It overrides module logging level when it is not set or set lower than the override value.在模组等级没有设置或者低于此等级时，使用此等级。
3.2 System Logging使用
使用方法如下，当然系统CONFIG_SYS_LOG_OVERRIDE_LEVEL或者模组内部等级定义不低于WARN。
SYS_LOG_WRN("hi!"); [general] [WRN] main: Hi!
