Ceph Kernel module dynamic debug

概述

在使用CephFS的kernel client后，发现它对比ceph-fuse客户端，不方便找到对应的log了，在dmesg或kern.log里也仅有很少的log输出，这在遇到问题的时候很不方便，需要找到打印Ceph kernel log的方法。

代码定义

Ceph的kernel module有两个，如下：

root@ceph2:~# lsmod | grep ceph
ceph                  385024  0
libceph               315392  1 ceph
fscache               368640  1 ceph
libcrc32c              16384  8 nf_conntrack,nf_nat,dm_persistent_data,btrfs,xfs,raid456,libceph,ip_vs

• ceph：CephFS kernel client模块
• libceph：Ceph kernel网络通信模块

在Ceph kernel的代码里，有两类log输出机制：

1. pr_debug 输出
   分为 info / warning / error等好多种，调用 printk 输出；

2. dout 输出
   Kernel里对应Dynamic Debug；

pr_debug

通过调用 printk 的指定log级别输出；

文件：include/linux/printk.h

/*
 * These can be used to print at the various log levels.
 * All of these will print unconditionally, although note that pr_debug()
 * and other debug macros are compiled out unless either DEBUG is defined
 * or CONFIG_DYNAMIC_DEBUG is set.
 */
#define pr_emerg(fmt, ...) \
    printk(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
#define pr_alert(fmt, ...) \
    printk(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)
#define pr_crit(fmt, ...) \
    printk(KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)
#define pr_err(fmt, ...) \
    printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
#define pr_warning(fmt, ...) \
    printk(KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)
#define pr_warn pr_warning
#define pr_notice(fmt, ...) \
    printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
#define pr_info(fmt, ...) \
    printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)

dout

ceph kernel代码里log大部分使用dout输出，它的定义如下：

文件：include/linux/ceph/ceph_debug.h

/* SPDX-License-Identifier: GPL-2.0 */
#ifndef _FS_CEPH_DEBUG_H
#define _FS_CEPH_DEBUG_H

#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt

#include <linux/string.h>

#ifdef CONFIG_CEPH_LIB_PRETTYDEBUG

/*
 * wrap pr_debug to include a filename:lineno prefix on each line.
 * this incurs some overhead (kernel size and execution time) due to
 * the extra function call at each call site.
 */

# if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)
#  define dout(fmt, ...)                        \
    pr_debug("%.*s %12.12s:%-4d : " fmt,                \
         8 - (int)sizeof(KBUILD_MODNAME), "    ",       \
         kbasename(__FILE__), __LINE__, ##__VA_ARGS__)
# else
/* faux printk call just to see any compiler warnings. */
#  define dout(fmt, ...)    do {                \
        if (0)                      \
            printk(KERN_DEBUG fmt, ##__VA_ARGS__);  \
    } while (0)
# endif

#else

/*
 * or, just wrap pr_debug
 */
# define dout(fmt, ...) pr_debug(" " fmt, ##__VA_ARGS__)

#endif

#endif

从上面可以看出，如果内核支持了 CONFIG_DYNAMIC_DEBUG，那我们就可以动态获取到这部分debug输出了；

系统Dynamic Debug支持

在机器上检查kernel是不是支持 CONFIG_DYNAMIC_DEBUG：

root@ceph2:/boot# uname -a 
Linux ceph2 4.18.5-041805-generic #201808241320 SMP Fri Aug 24 13:22:12 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux 
root@ceph2:/boot# grep CONFIG_DYNAMIC_DEBUG config-4.18.5-041805-generic 
CONFIG_DYNAMIC_DEBUG=y

如果输出如上述，则表示使用的linux kernel支持了CONFIG_DYNAMIC_DEBUG，那就可以动态获取Ceph kernel module的输出了；

获取debugfs的目录：

root@ceph2:~# mount | grep debugfs 
debugfs on /sys/kernel/debug type debugfs (rw,relatime) 

root@ceph2:~# cd /sys/kernel/debug/ 
root@ceph2:/sys/kernel/debug# cd dynamic_debug/ 
root@ceph2:/sys/kernel/debug/dynamic_debug# ls 
control

查看对应Ceph都有哪些Dynamic Debug支持：

root@ceph2:/sys/kernel/debug/dynamic_debug# cat control | grep ceph | wc -l 
975 

root@ceph2:/sys/kernel/debug/dynamic_debug# cat control | grep ceph | less 
net/ceph/ceph_common.c:787 [libceph]exit_ceph_lib =_ " exit_ceph_lib\012" 
net/ceph/ceph_common.c:739 [libceph]ceph_open_session =_ " open_session start\012” 
...
fs/ceph/cache.c:212 [ceph]ceph_fscache_file_set_cookie =_ " fscache_file_set_cookie %p %p enabling cache\012" 
fs/ceph/cache.c:204 [ceph]ceph_fscache_file_set_cookie =_ " fscache_file_set_cookie %p %p disabling cache\012" 
fs/ceph/cache.c:138 [ceph]ceph_fscache_inode_check_aux =_ " ceph inode 0x%p cached okay\012"

Dynamic Debug介绍

模式分类

Linux Kernel里的Dynamic Debug支持好几种配置模式，介绍如下：

1、func
输出指定函数的log

echo -n 'func xxx +p' > /sys/kernel/debug/dynamic_debug/control 
echo -n 'func xxx -p' > /sys/kernel/debug/dynamic_debug/control

比如：ceph_open_session，则会打印这个函数内的所有log

2、file
输出指定文件的log

echo -n 'file xxx.c +p' > /sys/kernel/debug/dynamic_debug/control 
echo -n 'file xxx.c -p' > /sys/kernel/debug/dynamic_debug/control

比如：ceph_common.c，则会打印该文件内的所有log

3、module
输出指定模块的log

echo -n 'module libceph +p' > /sys/kernel/debug/dynamic_debug/control 
echo -n 'module libceph -p' > /sys/kernel/debug/dynamic_debug/control

比如：libceph/ceph，则会打印libceph或ceph模块的所有log

当前ceph相关的就这两个模块；

4、format
输出符合指定格式的log

echo -n 'format xxx +p' > /sys/kernel/debug/dynamic_debug/control 
echo -n 'format xxx -p' > /sys/kernel/debug/dynamic_debug/control

比如：get_session，则只会打印匹配这个字符串的log

5、line
输出指定行号的log

echo -n 'file xxx line xxx +p' > /sys/kernel/debug/dynamic_debug/control 
echo -n 'file xxx line xxx -p' > /sys/kernel/debug/dynamic_debug/control

比如：100-200，则只会打印指定文件里100行-200行内的log

不同line指定的含义介绍如下：

line 1603           // exactly line 1603 
line 1600-1605      // the six lines from line 1600 to line 1605 
line -1605          // the 1605 lines from line 1 to line 1605 
line 1600-          // all lines from line 1600 to the end of the file

Flag说明

上述+-号含义如下：

\-    remove the given flags 
\+    add the given flags 
=    set the flags to the given flags

支持的flag有：

p    enables the pr_debug() callsite. 
f    Include the function name in the printed message 
l    Include line number in the printed message 
m    Include module name in the printed message 
t    Include thread ID in messages not generated from interrupt context 
_    No flags are set. (Or'd with others on input)

自动配置Dynamic Debug

如何自动配置dynamic debug？

通常有三种办法：

1、添加模块加载的配置
2、添加boot args，修改/proc/cmdline
3、传递参数给modprobe

下面介绍通过模块加载时候指定参数的办法：

在/etc/modprobe.d/目录创建 .conf 文件，然后在里面添加dyndbg配置：

如下所示：

root@ceph2:/etc/modprobe.d# cat ceph.conf 
options ceph dyndbg="format get_session +p"

之后就可以通过dmesg或者在kern.log里查看ceph kernel module的log了 ：） 测试如下：

root@ceph2:/etc/modprobe.d# rmmod ceph 
root@ceph2:/etc/modprobe.d# modprobe ceph 
root@ceph2:/etc/modprobe.d# mount -t ceph 100.64.0.21,100.64.0.22,100.64.0.26:/ /mnt/cephfs 
root@ceph2:/etc/modprobe.d# dmesg -T | tail -n 5 
[Thu Oct 25 19:54:13 2018] ceph:  mdsc get_session 0000000046b3700b 2 -> 3 
[Thu Oct 25 19:54:13 2018] ceph:  mdsc get_session 0000000096e295d5 1 -> 2 
[Thu Oct 25 19:54:13 2018] ceph:  mdsc get_session 0000000096e295d5 2 -> 3 
[Thu Oct 25 19:54:13 2018] ceph:  mdsc get_session 0000000046b3700b 1 -> 2 
[Thu Oct 25 19:54:13 2018] ceph:  mdsc get_session 0000000046b3700b 2 -> 3

参考文章

https://lwn.net/Articles/434856/
https://www.kernel.org/doc/html/v4.18/admin-guide/dynamic-debug-howto.html