Subsys: Logger¶
1 功能概述¶
Zephyr 提供了一个 Log 子系统(Logging Subsystem),本例程演示:
Zephyr Log 机制的基本功能
输出 Log 的两种通信接口:UART Log 与 Segger RTT Log
2 环境要求¶
Board: pan108xxa1_evb / pan108xxa3_evb / pan108xxb1_evb / pan108xxb5_evb
UART: 将 P00 与 TX0 引脚接在一起,P01 与 RX0 引脚接在一起,在 PC 上打开终端工具(如 SecureCRT),波特率设置为 921600
3 编译和烧录¶
例程位置:zephyr\samples_panchip\subsys\logging\logger
使用 ZAL 工具可以对其进行编译、烧录、打开 VS Code 调试等操作。关于 ZAL 工具的详细介绍请参考:Zephyr APP Launcher 工具介绍。
4 演示说明¶
4.1 通过 UART 输出 Log¶
在 ZAL 工具的 Config 下拉菜单中选择名为
prj.conf
的配置文件,然后编译并下载程序程序下载后,可以从 UART 串口上看到如下的 Log 打印信息:
4.2 通过 Segger RTT 输出 Log¶
在 ZAL 工具的 Config 下拉菜单中选择名为
prj_rtt.conf
的配置文件,然后编译并下载程序程序下载后,可以发现已经无法从 UART 串口上看到 Log 打印信息,此时不要断开 JLink 与 SoC 的 SWD 连接
在编译工具链 Toolchain 目录下的 JLink-V644b 子目录中,双击
JLinkRTTViewer.exe
,在弹出的配置界面中按照下图所示的方法配置:配置完成后,进入 RTT Log 主界面,即可看到 Log 输出:
注1:若没有 Log 输出,可以尝试按 EVB 的 Reset 按键,然后在 RTT Viewer 界面的 File 菜单中选择 Connect,唤起配置界面后重新配置 JLink 连接参数。
注2:Segger 提供了更多的查看 RTT Log 的方式,包括 RTT Client、RTT Logger、Telnet 等,例如使用支持 Telnet 的工具监听 localhost:19021 端口,也可接收到 RTT Log:
4.3 本例程完整的 Log 记录¶
*** Booting Zephyr OS build zephyr-v2.7.0 ***
---=< RUNNING LOGGER DEMO FROM KERNEL THREAD >=---
Module logging showcase.
[00:00:00.104,533] <inf> sample_module: log in test_module 11
[00:00:00.104,547] <inf> sample_module: Inline function.
Disabling logging in the sample_module module
Function called again but with logging disabled.
Instance level logging showcase.
[00:00:00.104,910] <inf> sample_instance.inst1: Inline call.
[00:00:00.104,931] <inf> sample_instance.inst1: counter_value: 0
[00:00:00.104,950] <wrn> sample_instance.inst1: Example of hexdump:
01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 |........ ........
11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 |........ .......
21 22 |!"
[00:00:00.104,961] <inf> sample_instance.inst2: Inline call.
[00:00:00.104,974] <inf> sample_instance.inst2: counter_value: 0
[00:00:00.104,989] <wrn> sample_instance.inst2: Example of hexdump:
01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 |........ ........
11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 |........ .......
21 22 |!"
Changing filter to warning on sample_instance.inst1 instance.
[00:00:00.105,230] <wrn> sample_instance.inst1: Example of hexdump:
01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 |........ ........
11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 |........ .......
21 22 |!"
[00:00:00.105,244] <inf> sample_instance.inst2: Inline call.
[00:00:00.105,260] <inf> sample_instance.inst2: counter_value: 1
[00:00:00.105,275] <wrn> sample_instance.inst2: Example of hexdump:
01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 |........ ........
11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 |........ .......
21 22 |!"
Disabling logging on both instances.
Function call on both instances with logging disabled.
String logging showcase.
[00:00:01.139,477] <inf> main: Logging transient string:transient_string
Severity levels showcase.
[00:00:01.139,548] <err> main: Error message example.
[00:00:01.139,553] <wrn> main: Warning message example.
[00:00:01.139,560] <inf> main: Info message example.
Logging performance showcase.
[00:00:03.149,443] <inf> main: performance test - log message 0
[00:00:04.154,368] <inf> main: performance test - log message 0
[00:00:05.159,268] <inf> main: performance test - log message 0
[00:00:06.164,168] <inf> main: performance test - log message 0
[00:00:07.169,068] <inf> main: performance test - log message 0
[00:00:08.173,968] <inf> main: performance test - log message 0
[00:00:09.178,868] <inf> main: performance test - log message 0
[00:00:10.183,768] <inf> main: performance test - log message 0
[00:00:11.188,668] <inf> main: performance test - log message 0
[00:00:12.193,568] <inf> main: performance test - log message 0
[00:00:13.198,468] <inf> main: performance test - log message 0
[00:00:14.203,368] <inf> main: performance test - log message 0
[00:00:15.208,268] <inf> main: performance test - log message 0
[00:00:15.208,331] <inf> main: performance test - log message 1
[00:00:15.208,339] <inf> main: performance test - log message 2
[00:00:15.208,346] <inf> main: performance test - log message 3
[00:00:15.208,353] <inf> main: performance test - log message 4
[00:00:15.208,360] <inf> main: performance test - log message 5
[00:00:15.208,367] <inf> main: performance test - log message 6
[00:00:15.208,373] <inf> main: performance test - log message 7
[00:00:16.216,076] <inf> main: performance test - log message 0
[00:00:16.216,151] <inf> main: performance test - log message 1
[00:00:16.216,160] <inf> main: performance test - log message 2
[00:00:16.216,167] <inf> main: performance test - log message 3
[00:00:16.216,174] <inf> main: performance test - log message 4
[00:00:16.216,180] <inf> main: performance test - log message 5
[00:00:16.216,187] <inf> main: performance test - log message 6
[00:00:16.216,194] <inf> main: performance test - log message 7
[00:00:16.216,201] <inf> main: performance test - log message 8
[00:00:16.216,208] <inf> main: performance test - log message 9
[00:00:16.216,214] <inf> main: performance test - log message 10
[00:00:16.216,221] <inf> main: performance test - log message 11
[00:00:16.216,228] <inf> main: performance test - log message 12
[00:00:16.216,235] <inf> main: performance test - log message 13
[00:00:16.216,241] <inf> main: performance test - log message 14
[00:00:16.216,248] <inf> main: performance test - log message 15
[00:00:16.216,255] <inf> main: performance test - log message 16
[00:00:16.216,262] <inf> main: performance test - log message 17
[00:00:16.216,269] <inf> main: performance test - log message 18
[00:00:16.216,275] <inf> main: performance test - log message 19
[00:00:16.216,282] <inf> main: performance test - log message 20
[00:00:16.216,289] <inf> main: performance test - log message 21
[00:00:16.216,296] <inf> main: performance test - log message 22
[00:00:16.216,303] <inf> main: performance test - log message 23
[00:00:16.216,309] <inf> main: performance test - log message 24
[00:00:17.240,417] <inf> main: performance test - log message 0
[00:00:17.240,492] <inf> main: performance test - log message 1
[00:00:17.240,501] <inf> main: performance test - log message 2
[00:00:17.240,508] <inf> main: performance test - log message 3
[00:00:17.240,514] <inf> main: performance test - log message 4
[00:00:17.240,521] <inf> main: performance test - log message 5
[00:00:17.240,528] <inf> main: performance test - log message 6
[00:00:17.240,535] <inf> main: performance test - log message 7
[00:00:17.240,542] <inf> main: performance test - log message 8
[00:00:17.240,548] <inf> main: performance test - log message 9
[00:00:17.240,555] <inf> main: performance test - log message 10
[00:00:17.240,562] <inf> main: performance test - log message 11
[00:00:17.240,569] <inf> main: performance test - log message 12
[00:00:17.240,576] <inf> main: performance test - log message 13
[00:00:17.240,582] <inf> main: performance test - log message 14
[00:00:17.240,589] <inf> main: performance test - log message 15
[00:00:17.240,596] <inf> main: performance test - log message 16
[00:00:17.240,603] <inf> main: performance test - log message 17
[00:00:17.240,609] <inf> main: performance test - log message 18
[00:00:17.240,616] <inf> main: performance test - log message 19
[00:00:17.240,623] <inf> main: performance test - log message 20
[00:00:17.240,630] <inf> main: performance test - log message 21
[00:00:17.240,637] <inf> main: performance test - log message 22
[00:00:17.240,643] <inf> main: performance test - log message 23
[00:00:17.240,650] <inf> main: performance test - log message 24
[00:00:17.240,657] <inf> main: performance test - log message 25
[00:00:17.240,664] <inf> main: performance test - log message 26
[00:00:17.240,670] <inf> main: performance test - log message 27
[00:00:17.240,677] <inf> main: performance test - log message 28
[00:00:17.240,684] <inf> main: performance test - log message 29
[00:00:17.240,691] <inf> main: performance test - log message 30
[00:00:17.240,698] <inf> main: performance test - log message 31
[00:00:17.240,704] <inf> main: performance test - log message 32
[00:00:17.240,711] <inf> main: performance test - log message 33
[00:00:17.240,718] <inf> main: performance test - log message 34
[00:00:17.240,725] <inf> main: performance test - log message 35
[00:00:17.240,731] <inf> main: performance test - log message 36
[00:00:17.240,738] <inf> main: performance test - log message 37
[00:00:17.240,745] <inf> main: performance test - log message 38
[00:00:17.240,752] <inf> main: performance test - log message 39
[00:00:17.240,759] <inf> main: performance test - log message 40
[00:00:17.240,765] <inf> main: performance test - log message 41
[00:00:17.240,772] <inf> main: performance test - log message 42
[00:00:17.240,779] <inf> main: performance test - log message 43
[00:00:17.240,786] <inf> main: performance test - log message 44
[00:00:17.240,793] <inf> main: performance test - log message 45
[00:00:17.240,799] <inf> main: performance test - log message 46
[00:00:17.240,806] <inf> main: performance test - log message 47
[00:00:17.240,813] <inf> main: performance test - log message 48
[00:00:17.240,820] <inf> main: performance test - log message 49
[00:00:17.240,826] <inf> main: performance test - log message 50
[00:00:17.240,833] <inf> main: performance test - log message 51
[00:00:17.240,840] <inf> main: performance test - log message 52
[00:00:17.240,847] <inf> main: performance test - log message 53
[00:00:17.240,854] <inf> main: performance test - log message 54
[00:00:17.240,860] <inf> main: performance test - log message 55
[00:00:17.240,867] <inf> main: performance test - log message 56
[00:00:17.240,874] <inf> main: performance test - log message 57
[00:00:17.240,881] <inf> main: performance test - log message 58
[00:00:17.240,887] <inf> main: performance test - log message 59
[00:00:17.240,894] <inf> main: performance test - log message 60
[00:00:17.240,901] <inf> main: performance test - log message 61
[00:00:17.240,908] <inf> main: performance test - log message 62
Estimated logging capabilities: 123046 messages/second
Logs from external logging system showcase.
[00:00:19.306,926] <err> ext_log_system: critical level log
[00:00:19.306,962] <err> ext_log_system: error level log, 1 arguments: 1
[00:00:19.306,999] <wrn> ext_log_system: warning level log, 2 arguments: 1 2
[00:00:19.307,049] <inf> ext_log_system: notice level log, 3 arguments: 100, string, 0x00000255
[00:00:19.307,096] <inf> ext_log_system: info level log, 4 arguments : 1 2 3 4
5 开发说明¶
使能 Zephyr Logging 机制,需要打开
CONFIG_LOG=y
总开关,且:SDK 默认使用的 Log Backend 即为 UART,因此开启 Log 总开关后无需特别配置即可将 Log 输出至 UART
若想将 Log Backend 切换为 Segger RTT,需要额外配置如下的 Config:
CONFIG_LOG_BACKEND_UART=n CONFIG_LOG_BACKEND_RTT=y CONFIG_USE_SEGGER_RTT=y
使能
CONFIG_LOG=y
,默认配置为 Buffered Log,即在执行打印 Log 接口的时候,Log 不会立刻输出,而是缓存在 Log Buffer 中,待系统空闲的时候 (即调度到 Idle 线程之前),在专门的 Log 线程中将数据统一打印出来。这样的好处是系统的实时性能够得到保证,但代价是额外的 Flash 和 RAM 资源。有时候,我们希望使用 Log 功能,但 RAM 资源又比较紧缺,这时候我们仍然可以使能 Log 功能,但是可以不开启缓存功能,而是在执行打印 Log 接口的时候 立刻将当前 Log 打印出来,方法是配置如下 Config:
CONFIG_LOG=y CONFIG_LOG_MODE_IMMEDIATE=y
如果资源仍然紧缺,还可配置如下的 Config,进一步简化 Log 功能:
CONFIG_LOG_MODE_MINIMAL=y
logging 相关的主要接口定义及介绍请参考:
zephyr\include\logging\log.h
zephyr\include\logging\log_ctrl.h
6 RAM/Flash资源使用情况¶
Memory region Used Size Region Size %age Used
FLASH: 26716 B 384 KB 6.79%
SRAM: 10944 B 64 KB 16.70%