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有很多内核相关配置选项，可以通过这些选项进行细化。

配置	解释
CONFIG_KERNEL_EVENT_LOGGER	Logger总开关。
CONFIG_KERNEL_EVENT_LOGGER_CONTEXT_SWITCH	进程切换事件。
CONFIG_KERNEL_EVENT_LOGGER_INTERRUPT	中断事件。
CONFIG_KERNEL_EVENT_LOGGER_SLEEP	睡眠事件。
CONFIG_KERNEL_EVENT_LOGGER_BUFFER_SIZE	RingBuffer大小。
CONFIG_KERNEL_EVENT_LOGGER_DYNAMIC	将logging控制权交给应用自身。
CONFIG_KERNEL_EVENT_LOGGER_CUSTOM_TIMESTAMP	允许自定义时间戳函数。

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 事件读取

事件的读取可以通过如下函数进行，具体用法可以查看链接。

• sys_k_event_logger_get()
• sys_k_event_logger_get_wait()
• sys_k_event_logger_get_wait_timeout()

如下是代码示例：

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
", 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中：

• sys_k_event_logger_put()
• sys_k_event_logger_put_timed()

自定义事件接口函数内容如下：

#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!