Zephyr log系统原理

Creative Commons
本作品采用知识共享署名
发表于 | 分类于 | | 阅读次数：

本文说明zephyr log系统的架构和原理。以及Frontend和Core的代码实现。

架构

,
下图说明了zephyr log系统的架构:
logsys

运行原理

可以看到log系统由frontend,core,backend组成,显示一个message的典型流程工作:

  1. frontend检查log msg的level是否大于等于build-in level
  2. frontend检查log msg的level是否大于等于slot-0的level
  3. frontend使用log_message分配一个message，将log msg装入message
  4. frontend将message放入到log_list内
  5. core的thread从log_list中读取message
  6. core将message送到各个backend
  7. core检查backend是否active
  8. core检查message的level是否大于等于其所属frontend对应的backend level（slot-n）
  9. backend使用log_output格式化message
  10. backend将格式化后的message送到驱动进行显示
  11. core使用log_message释放已显示的message

Level

zephyr log系统共有4种level: err>wrn>info>dbg，在编译时指定frontend的build-in level，在运行时可以动态的设置runtime level。 runtime level不能小于build-in level。 每个frontend使用一个32bit filter记录自己的runtime level，一个filter可以分为10个3bit的slot，其中slot0记录该filter中最大的level，剩下的9个slot对应不同的backend的level(可见zephyr最多支援9个backend)

文件构成

log系统的文件放在include/logging/和subsys/logging/中主要如下
log.h/log_core.h 提供Frontend功能，用于注册Frontend，Frontend显示，并执行Frontend的level过滤
log_core.c 提供core功能，创建一个thread，接收从Frontend送来的message，并根据backend的filter进行过滤，然后依次送到各个backend去显示
log_backend_xxx.c 是各个backend的实现代码例如log_backend_uart.c/log_backend_rtt.c等，backend提供到各个驱动的输出功能。backend使用log_output格式信息后再写向driver。
log_msg.c 用于分配和释放meassage
log_list.c 用于在Frontend和Core之间传递log_msg分配的message
log_output.c 用于格式化和控制message输出，被backend调用，并使用backend注册的回调输出到物理通道
log_cmds.c 提供shell命令，用于设置filter和控制log系统

实现

基础宏说明

分析log的代码有一些基础宏，这里说明其作用已方便分析，具体原理请看代码分析
#define _LOG_EVAL(_eval_level, _iftrue, _iffalse)
如果_eval_level为1~4,使用_iftrue，否则使用_iffalse
#define _LOG_LEVEL_RESOLVE(…)
第二个参数为送入level参数
如果送入参数有level，使用送入参数level
如果没有送入level，且LOG_LEVEL为1~4，使用LOG_LEVEL
如果没有送入level，且LOG_LEVEL不为1~4，使用CONFIG_LOG_DEFAULT_LEVEL
#define _LOG_MODULE_DATA_CREATE(_name, _level)
定义并初始化log_source_const_data & log_source_dynamic_data变量
#define LOG_CURRENT_MODULE_ID()
获取当前module log id, 计算__log_current_const_data在log_const_sections的位置

#define LOG_CURRENT_DYNAMIC_DATA_ADDR()
获取当前module的dynmic data,也就是__log_current_dynamic_data

注册module

1
2
3
4
CONFIG_ETHERNET_LOG_LEVEL 3
#define LOG_MODULE_NAME eth_enc28j60
#define LOG_LEVEL CONFIG_ETHERNET_LOG_LEVEL
LOG_MODULE_REGISTER(LOG_MODULE_NAME, LOG_LEVEL)

以上宏展开后为

1
2
3
4
5
6
7
8
9
10
11
12
13
14
const struct log_source_const_data log_const_eth_enc28j60	     \
    __attribute__ ((section(".log_const_eth_enc28j60"))) \
	__attribute__((used)) = {					     \
		.name = "eth_enc28j60",				     \
		.level = 3						     \
	};		\
	struct log_source_dynamic_data log_dynamic_eth_enc28j60	\
	__attribute__ ((section(".log_dynamic_eth_enc28j60")))					\
	__attribute__((used));	\
	extern const struct log_source_const_data log_const_eth_enc28j60;	      \
	extern struct log_source_dynamic_data log_dynamic_eth_enc28j60;	      \
	static const struct log_source_const_data *__log_current_const_data __attribute__((unused)) = &log_const_eth_enc28j60;  \
	static struct log_source_dynamic_data *__log_current_dynamic_data __attribute__((unused)) = &log_dynamic_eth_enc28j60;\
	static const u32_t __log_level __attribute__((unused)) = 3;

可以看到注册module时会定义module的data struct及注册文件引用该module data struct的：
定义了一个全局的struct log_source_const_data，存放当前module name和build-in level
定义了一个全局的struct log_source_dynamic_data,里面存放32bit filter，后面再展开介绍
定义了一个static的指针log_current_const_data指向struct log_source_const_data
定义了一个static的指针log_current_dynamic_data指向struct log_source_dynamic_data
定义了一个static u32_t __log_level 存储当前file的log level

log module声明

当在a文件中使用LOG_MODULE_REGISTER注册了一个log module，可以在b文件中使用LOG_MODULE_DECLARE声明后使用

1
2
3
4
CONFIG_ETHERNET_LOG_LEVEL 2
#define LOG_MODULE_NAME eth_enc28j60
#define LOG_LEVEL CONFIG_ETHERNET_LOG_LEVEL
LOG_MODULE_DECLARE(LOG_MODULE_NAME, LOG_LEVEL)

以上宏展开为

1
2
3
4
5
extern const struct log_source_const_data log_const_eth_enc28j60;	      \
extern struct log_source_dynamic_data log_dynamic_eth_enc28j60;	      \
static const struct log_source_const_data *__log_current_const_data __attribute__((unused)) = &log_const_eth_enc28j60;  \
static struct log_source_dynamic_data *__log_current_dynamic_data __attribute__((unused)) = &log_dynamic_eth_enc28j60;\
static const u32_t __log_level __attribute__((unused)) = 2;

可以看到声明log module其实就是在自己所在的文件另外定义2个指针指向moudle data struct，并定义自己文件的__log_level。
值得说明的是，log注册文件使用的level就是build-in level，而其它文件通过声明的方式引用log module时可以通过LOG_LEVEL_SET定义自己的level

1
2
#define LOG_LEVEL_SET(level) \
	static const u32_t __log_level __attribute__((unused)) = level

log显示

LOG通过下面4个宏将信息送到core进行显示

1
2
3
4
5
6
7
8
9
10
#define LOG_LEVEL_NONE 0
#define LOG_LEVEL_ERR  1
#define LOG_LEVEL_WRN  2
#define LOG_LEVEL_INF  3
#define LOG_LEVEL_DBG  4

#define LOG_ERR(...)    _LOG(LOG_LEVEL_ERR, __VA_ARGS__)
#define LOG_WRN(...)   _LOG(LOG_LEVEL_WRN, __VA_ARGS__)
#define LOG_INF(...)   _LOG(LOG_LEVEL_INF, __VA_ARGS__)
#define LOG_DBG(...)    _LOG(LOG_LEVEL_DBG, __VA_ARGS__

可以看到最后都是通过宏_LOG进行显示的，只是送入的level不一样，因此这里只用分析_LOG

1
2
3
4
5
#define _LOG(_level, ...)			       \
	__LOG(_level,				       \    //要显示log的level
	      (u16_t)LOG_CURRENT_MODULE_ID(),	       \    // 当前log module的id，见前面的说明
	      LOG_CURRENT_DYNAMIC_DATA_ADDR(),	       \   //__log_current_dynamic_data 见前面说明
	      __VA_ARGS__)

继续展开

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
#define __LOG(_level, _id, _filter, ...)				    \
	do {								    \
		if (_LOG_CONST_LEVEL_CHECK(_level) &&			    \       //const 过滤比较的是每个file的__log_level
		    (_level <= LOG_RUNTIME_FILTER(_filter))) {		    \   //比较动态的filter
			struct log_msg_ids src_level = {		    \
				.level = _level,			    \
				.domain_id = CONFIG_LOG_DOMAIN_ID,	    \
				.source_id = _id			    \
			};						    \
									    \
			if ((1 << _level) & LOG_FUNCTION_PREFIX_MASK) {	    \   //将log信息送到core显示
				__LOG_INTERNAL(src_level,		    \
						_LOG_STR(__VA_ARGS__));	    \
			} else {					    \
				__LOG_INTERNAL(src_level, __VA_ARGS__);	    \
			}						    \
		}	    \
	} while (false)

log frontend过滤

_LOG_CONST_LEVEL_CHECK最后就是和每个file的__log_level进行比较。
LOG_RUNTIME_FILTER要复杂一点，runtime filter可以在运行时通过shell cmd进行改变，这里只和runtime filter的slot-0比较

1
2
3
#define LOG_FILTER_AGR_SLOT_IDX 0
#define LOG_RUNTIME_FILTER(_filter) \
	LOG_FILTER_SLOT_GET(&(_filter)->filters, LOG_FILTER_AGGR_SLOT_IDX)

runtime filter是定义在struct log_source_dynamic_data的一个32bit数

1
2
3
4
struct log_source_dynamic_data {
	u32_t filters;
#endif
};

run time filter被分为10个3bit slot，如下图：
slot
其中slot1~slot9对应9个backend，slot0中保存了slot1~slot9中最低的level（数字最大），当LOG_RUNTIME_FILTER过滤时发现msg的level比slot0都低（数字大）则表示没有一个backend会显示这个msg，就在这里被过滤而不送到core去

msg送显

通过__LOG_INTERNAL将struct log_msg_ids（包含module id和msg level）及msg信息送到core：

1
__LOG_INTERNAL->_LOG_INTERNAL_X->择根据变参的参数数量选择log_0，log_1，log_2，log_3，log_n进行显示

在上面几个log_x函数中会分别调用log_msg_create_x alloc并用arg初始化出struct log_msg，在用msg_finalize将log_msg_ids和时间戳打包入log_msg后加入log_list_t，等待log_process取走送到forntend显示，已log_0为例

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
void log_0(const char *str, struct log_msg_ids src_level)
{
	struct log_msg *msg = log_msg_create_0(str);    //分配&初始化log_msg

	if (msg == NULL) {
		return;
	}
	msg_finalize(msg, src_level);   //加入显示
}

log_msg_create_0->_log_msg_std_alloc->log_msg_chunk_alloc


static inline void msg_finalize(struct log_msg *msg,
				struct log_msg_ids src_level)
{
	unsigned int key;

	msg->hdr.ids = src_level;
	msg->hdr.timestamp = timestamp_func();  //加时间戳

	atomic_inc(&buffered_cnt);

	key = irq_lock();

	log_list_add_tail(&list, msg);  //加入到log msg list

	irq_unlock(key);
}

log msg显示

log core中的thread log_process_thread_func 从log msg list中取出log msg进行显示

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
static void log_process_thread_func(void *dummy1, void *dummy2, void *dummy3)
{
	__ASSERT_NO_MSG(log_backend_count_get() > 0);

	log_init();
	thread_set(k_current_get());

	while (true) {
		if (log_process(false) == false) {  //显示处理
			k_sleep(CONFIG_LOG_PROCESS_THREAD_SLEEP_MS);
		}
	}
}

bool log_process(bool bypass)
{
	struct log_msg *msg;

	if (!backend_attached && !bypass) {
		return false;
	}
	unsigned int key = irq_lock();

	msg = log_list_head_get(&list); //读取log msg list
	irq_unlock(key);

	if (msg != NULL) {
		atomic_dec(&buffered_cnt);
		msg_process(msg, bypass);   //显示处理
	}

	if (!bypass && dropped_cnt) {
		dropped_notify();
	}

	return (log_list_head_peek(&list) != NULL); 
}

static void msg_process(struct log_msg *msg, bool bypass)
{
	struct log_backend const *backend;

	if (!bypass) {
		for (int i = 0; i < log_backend_count_get(); i++) {
			backend = log_backend_get(i);   //便利所有backend

			if (log_backend_is_active(backend) &&   //判读backend是否被halt
			    msg_filter_check(backend, msg)) {   //判断当前backend 的level（其它slot）
				log_backend_put(backend, msg);      //送到backend显示
			}
		}
	}

	log_msg_put(msg);   //显示玩后，释放log msg
}

backend显示

backend的显示是通过注册的backend API来进行显示，backend会在后面的文章进行介绍

1
2
3
4
5
6
7
static inline void log_backend_put(const struct log_backend *const backend,
				   struct log_msg *msg)
{
	__ASSERT_NO_MSG(backend);
	__ASSERT_NO_MSG(msg);
	backend->api->put(backend, msg);
}

参考

https://lgl88911.gitee.io/2019/02/17/Zephyr-log%E7%B3%BB%E7%BB%9F/
https://docs.zephyrproject.org/latest/reference/logging/index.html