SPDKTraceLog用法简介

今天我们给大家介绍SPDK Trace Log在Debug/Free build下针对特定模块的使用。

温馨提示：由于部分函数较长，建议使用电脑端或者手机横屏阅读~

一

什么是日志

日志，又称为Log，是我们开发人员的一款利器。我们通常在程序代码中插入一些特殊的输出代码，将程序当前的运行状态按需输出，以便于在无人值守的情况下记录信息，在事后对程序的处理过程进行分析。不管是在调试还是测试的阶段，日志都是我们的得力助手。

一个完善的日志系统不只是简单地在控制台输出，还具有以下几个特征：

• 使用一种方式就支持输出到多个目标，例如：控制台，文本文件，数据库等。

• 允许控制输出的级别，过滤输出的内容，而不需要大幅度修改日志程序。

• 使用简单，可以使用简单的语法来记录日志。

二

Linux内核中的日志系统函数和SPDK的封装

我们先来了解一下linux内核的三个系统函数openlog、syslog和closelog，这是一套系统日志写入接口。还有一个vsyslog，和syslog功能一样，只是参数格式不同。

2.1. openlog

openlog函数用来打开一个到系统日志记录程序的连接，打开之后就可以用syslog或vsyslog函数向系统日志里添加信息了。而closelog函数就是用来关闭此连接的。

通常来说，openlog需要在模块最开始指定，即限定了这个模块内都是一个facility的日志，SPDK里指定的是 LOG_LOCAL7。定义在/lib/event/app.c中，

1.  void spdk_log_open(logfunc *logf)  

2.  {  

3.      if (logf) {  

4.          g_log = logf;  

5.      } else {  

6.          openlog("spdk", LOG_PID, LOG_LOCAL7);  

7.      }  

8.  }  

参数说明：

LOG_PID，Include PID with each message，更多的是方便调试。

LOG_LOCAL0~LOG_LOCAL7, 为本地使用保留。

2.2. syslog

syslog 是Linux系统默认的日志守护进程。任何希望生成日志信息的程序都可以向 syslog 接口呼叫生成该信息，把日志消息发给系统程序syslogd去记录。

如果我们的程序要使用系统日志功能，只需要在程序启动时使用openlog函数来连接syslogd程序，后面随时用syslog函数写日志就行了。

SPDK代码里是这样使用的：

1. void  spdk_vlog(enum spdk_log_level level, const char *file, const int line, const char *func,  const char *format, va_list ap)  

2. {  

3.      ……

4.      if (level <= g_spdk_log_level) {  

5.          syslog(severity, "%s:%4d:%s: *%s*: %s", file, line, func, spdk_level_names[level], buf);  

6.      }  

7. }  

日志打印效果看上去就是这样的，

00:10:27.002  [2021-12-23 04:27:19.499391] nvme_rdma.c:1778:nvme_rdma_ctrlr_create_qpair: *DEBUG*: RDMA requests

同时，syslog为每个事件赋予几个不同的优先级：

• LOG_ERR，错误 信息
  

• LOG_WARNING，警告信息 

• LOG_NOTICE，不是错误情况，但是可能需要处理 

• LOG_INFO，一般的打印信息 

• LOG_DEBUG，调试信息 

SPDK也定义了类似的6个日志事件优先等级：

1.  enum spdk_log_level {  

2.  SPDK_LOG_DISABLED = -1,/** All messages will be suppressed. */

3.  SPDK_LOG_ERROR,  

4.  SPDK_LOG_WARN,  

5.  SPDK_LOG_NOTICE,  

6.  SPDK_LOG_INFO,  

7.  SPDK_LOG_DEBUG,  

8.  }; 

2.3. closelog

最后closelog函数用来关闭上面的连接。SPDK代码里的调用：

1.  void spdk_log_close(void)  

2.  {  

3.      if (!g_log) {  

4.          closelog();  

5.      }  

6.  }  

三

SPDK log相关的RPC命令

3.1 基本的log命令

SPDK通过RPC命令，提供了丰富的log访问存取接口，和log相关的命令有下列这些，

    log_set_flag (set_log_flag)

                        set log flag        # 设置日志标记

    log_clear_flag (clear_log_flag)

                        clear log flag          # 清除日志标记

    log_get_flags (get_log_flags)

                        get log flags       # 获取全部模块日志标记

    log_set_level (set_log_level)

                        set log level           # 设置日志事件优先级别

    log_get_level (get_log_level)

                        get log level           # 获取当前日志事件优先级别

    log_set_print_level (set_log_print_level)

                        set log print level # 设置日志终端打印级别

    log_get_print_level (get_log_print_level)

                        get log print level # 获取日志终端打印级别

    log_enable_timestamps   # 显示系统时间戳，例如[2021-12-23 10:18:12.642789]

                        -d, --disable  Disable timestamps, 默认值

                        -e, --enable   Enable timestamps

下面举例简单介绍一下这些命令的使用方法。

3.1.1 4个log_level命令

在SPDK里，使用RPC命令的前提是开启target server，这里以nvmf_tgt为例，

./build/bin/nvmf_tgt --json bdev_nvme.json   # bdev_nvme.json内容请见附件

                                                                            # 另开一个终端窗口

./scripts/rpc.py log_set_level "NOTICE"      # 这里最低只能设置"ERROR"

./scripts/rpc.py log_get_level               # 显示当前log等级

"NOTICE"

./scripts/rpc.py log_set_print_level "INFO"  # 设置当前log打印等级

./scripts/rpc.py log_set_print_level         # 显示当前log打印等级

"INFO"

log_set_ print_level和log_set_level略有区别。前者设置打印级别，后者设置记录级别，记录了但不一定要在终端打印出来。从下面这段简化的spdk_vlog函数代码示例可以看出来。

1. void  spdk_vlog(enum spdk_log_level level, const char *file, const int line, const char *func,  const char *format, va_list ap)  

2. {  

3.      if (level <= g_spdk_log_print_level) {  

4.          fprintf(stderr, "%s%s:%4d:%s: *%s*: %s", timestamp, file, line, func, spdk_level_names[level], buf); 

5.      }  

6.    

7.      if (level <= g_spdk_log_level) {  

8.          syslog(severity, "%s:%4d:%s: *%s*: %s", file, line, func, spdk_level_names[level], buf);  

9.      }  

10.}  

接下来，产生一个ERROR的打印。这里参数-c Nmmm理应是Nvme0，故意输错名字，target端会产生错误打印，

./scripts/rpc.py bdev_nvme_get_controller_health_info -c Nmmm

# target终端窗口

bdev_nvme_rpc.c:1537:rpc_bdev_nvme_get_controller_health_info: *ERROR*: nvme ctrlr name &＃39;Nmmm&＃39; does not exist

3.1.2 时间戳开关

记录每次被更新时，系统都会自动维护时间戳，我们可以选择显示或者关闭显示时间戳。

./scripts/rpc.py log_enable_timestamps -d    # 关闭时间戳

./scripts/rpc.py log_enable_timestamps -e    # 开启时间戳

./scripts/rpc.py bdev_nvme_get_controller_health_info -c Nmmm

[2021-12-23 10:18:12.642789] bdev_nvme_rpc.c:1537:rpc_bdev_nvme_get_controller_health_info: *ERROR*: nvme ctrlr name &＃39;Nmmm&＃39; does not exist

3.1.3 debug开关

如果要系统产生某个指定模块更加详细的log，可以打开debug开关。需要在开启target时，使用-L参数，加模块名，all表示全部模块。

./build/bin/nvmf_tgt --json bdev_nvme.json -L nvme   # 指定某个模块或all

./scripts/rpc.py log_get_print_level

"DEBUG"

请注意，这里前提是编译SPDK代码的时候要带上debug参数，如下所示：

./configure --enable-debug

3.2 针对NVMe模块的使用

上面介绍了基本的log命令用法， 接下来我们拿NVMe作为例子，针对特定模块，设置log flag。也就是说，让target服务端只打印NVMe bdev相关的log。

首先通过RPC log_set_flag命令选择特定的模块，

./scripts/rpc.py log_set_flag "nvme"

./scripts/rpc.py log_get_flags  # 查看全部模块标记

  "log": false,

  "log_rpc": false,

  "lvol": false,

  "lvol_rpc": false,

  "nbd": false,

  "notify_rpc": false,

  "nvme": true,                             # 会显示true，已经设置好

清除log flag是用log_clear_flag。

./scripts/rpc.py log_clear_flag "nvme"

下面举个完整的例子。

首先启动nvmf target服务端应用程序。

./build/bin/nvmf_tgt

然后创建名为Nvme0的bdev，然后删除。

./scripts/rpc.py bdev_nvme_attach_controller -b Nvme0 -t pcie -a 0000:5f:00.0

./scripts/rpc.py bdev_nvme_detach_controller Nvme0

我们观察，target服务端窗口都没有任何新增log显示。这时，通过RPC log_set_flag命令，设置“nvme”log标志，再重新创建和删除bdev。

./scripts/rpc.py log_set_flag "nvme" 

./scripts/rpc.py bdev_nvme_attach_controller -b Nvme0 -t pcie -a 0000:5f:00.0

./scripts/rpc.py bdev_nvme_detach_controller Nvme0

再观察target服务端窗口，则会出现刚刚加载以及卸载Nvme0的log。

[2021-12-23 11:14:56.655651] nvme_pcie_common.c: 158:nvme_pcie_qpair_construct: *INFO*: max_completions_cap = 8 num_trackers = 24

[2021-12-23 11:14:56.677745] nvme_qpair.c: 251:nvme_admin_qpair_print_command: *NOTICE*: IDENTIFY (06) qid:0 cid:23 nsid:0 cdw10:00000001 cdw11:00000000 PRP1 0x16b6a5c000 PRP2 0x0

……

[2021-12-23 11:15:16.683121] nvme_qpair.c: 456:spdk_nvme_print_completion: *NOTICE*: ABORTED - SQ DELETION (00/08) qid:0 cid:22 cdw0:0 sqhd:0000 p:0 m:0 dnr:0

3.3 针对NBD模块的使用

我们再拿NBD(Network Block Device)作为例子，设置log flag，让target服务端只打印NBD bdev相关的log。

首先通过RPC命令设置log_set_flag，

./scripts/rpc.py log_set_flag "nbd"

./scripts/rpc.py log_get_flags

  "log": false,

  "log_rpc": false,

  "lvol": false,

  "lvol_rpc": false,

  "nbd": true,                          # 会显示true，已经设置好

要测试NBD设备，需要准备一些前提条件，

modprobe nbd                  # 加载nbd模块（如果没有，需要下载）
lsmod | grep nbd              # 查看nbd模块是否加载

接下来看下对比效果。启动nvmf target服务端应用程序。

./build/bin/nvmf_tgt

创建NBD的bdev。

./scripts/rpc.py bdev_malloc_create 256 512

./scripts/rpc.py nbd_start_disk Malloc0 /dev/nbd0

./scripts/rpc.py nbd_stop_disk /dev/nbd0

我们观察，target服务端窗口都没有任何新增log显示。这时通过RPC命令，设置“nbd”log标志后，再重新创建NBD。

./scripts/rpc.py log_set_flag "nbd"

./scripts/rpc.py nbd_start_disk Malloc0 /dev/nbd0

target服务端窗口，则会出现刚才加载NBD的log。

[2021-12-30 00:15:13.433639] nbd.c:1147:spdk_nbd_start: *INFO*: Enabling kernel access to bdev Malloc0 via /dev/nbd0

四

如何给自定义的第三方Bdev添加对应的Trace

4.1 注册flag

块设备模块对于SPDK来说，相当于传统操作系统中的设备驱动程序。该模块提供了一组函数指针，这些函数指针被调用以服务块设备I / O请求。SPDK提供了许多块设备模块，包括NVMe，RAM-disk和Ceph RBD。如果用户希望自己编写以与自定义硬件或现有存储软件堆栈进行交互，具体请参考https://spdk.io/doc/bdev_module.html。要添加新模块的log开关，需要额外注册新的模块的名字，本质上记录和打印log最终也是调用第二章提到的linux日志系统函数。本文假设用户已经编写好名为bdev_abc的第三方模块，现在添加对应的log trace flag。

首先在已写好的bdev_abc.c代码里注册log flag。

1. SPDK_LOG_REGISTER_COMPONENT(bdev_abc)  

这个宏定义调用了下面的函数，也就是一个入队的操作。

1. void spdk_log_register_flag(const char *name, struct spdk_log_flag *flag)  

2. {  

3.      ......  

4.      TAILQ_INSERT_TAIL(&g_log_flags, flag, tailq);  

5. }  

当新增flag时，向已有的g_log_flags链表队列插入新结点bdev_abc，如图所示。

图4-1：g_log_flags链表队列

说明：0/1是bool类型的flag开关。

4.2 打开/关闭flag

新添加模块的log flag开关默认是关闭的，需要的时候可以打开。这将使用到第三章提到的RPC命令，例如log_set_flag/ log_clear_flag。这里的set/clear flag的一套操作，都是在log_flag.c里完成的。它们用来控制输出或者不输出和该模块相关的log打印。

./scripts/rpc.py log_set_flag "bdev_abc"

./scripts/rpc.py log_get_flags

  "log": false,

  "log_rpc": false,

  "lvol": false,

  "lvol_rpc": false,

  "nbd": false,

  "notify_rpc": false,

  "bdev_abc": true,                # 会显示true，已经设置好

怎么知道当前SPDK app都支持哪些log flag模块呢？也就是说，现有队列包含哪些结点？这个可以通过app -h命令查看。

./build/bin/nvmf_tgt -h

……

-L, --logflag     enable log flag (all, accel, accel_ioat, aio, app_config, app_rpc, bdev, bdev_ftl, bdev_malloc, bdev_null, bdev_nvme, bdev_raid, bdev_raid0, blob, blob_rw, blobfs, blobfs_bdev, blobfs_bdev_rpc, blobfs_rw, ftl_core, ftl_init…

注：显示的结果，根据SPDK编译时./configure --with的开关，会略有不同。

4.3 查看log打印

当需要打印log的时候，我们可以在代码里使用下面四种封装函数宏定义：SPDK_NOTICELOG、SPDK_WARNLOG、SPDK_ERRLOG和SPDK_DEBUGLOG。其实质是通过封装的spdk_vlog函数，来调用linux内核的syslog和fprintf函数，具体请参考第3.1.1节的spdk_vlog。

用法举例：

1.  SPDK_NOTICELOG("Unable to perform reset, already in progress.\n"); 

2.  SPDK_WARNLOG("Specified command could not be aborted.\n"); 

3.  SPDK_ERRLOG("compare failed: rc = %d\n", rc); 

以上这些函数用法跟C语言的printf()一样。只有SPDK_DEBUGLOG，需要指定模块名，以便app -L的时候可以筛选该模块的log信息。

1. SPDK_DEBUGLOG(bdev_abc, "No action for abc controller timeout.\n"); 

再通过RPC命令打开该模块的debug开关。

./build/bin/nvmf_tgt -L bdev_abc

以上步骤完成后，我们就可以在运行日志中看到自己添加的模块产生的警告、错误和调试信息。是不是很简单，小伙伴们快去动手试试吧。

附件

bdev_nvme.json

1.  {  

2.    "subsystems": [  

3.      {  

4.        "subsystem": "bdev",  

5.        "config": [  

6.          {  

7.            "method": "bdev_nvme_attach_controller",  

8.            "params": {  

9.              "name": "Nvme0",  

10.             "trtype": "PCIe",  

11.             "traddr": "0000:5f:00.0",  

12.             "prchk_reftag": false,  

13.             "prchk_guard": false  

14.           }  

15.         }  

16.       ]  

17.     }  

18.   ]  

19. }  

参考资料

1.https://spdk.io/doc/jsonrpc.html

2.https://spdk.io/doc/bdev_module.html

转载须知

DPDK与SPDK开源社区

公众号文章转载声明

推荐阅读

Intel 助力移动云百万 IOPS 云硬盘，打造极速云存储体验

深入浅出Hyperscan出版啦！

SPDK Vhost 基于最新21.10发布版本的性能报告

DPDK Release 21.11

点点“赞”和“在看”，给我充点儿电吧~