Ceph Kernel module dynamic debug

概述

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

代码定义

Ceph的kernel module有两个,如下:

1
2
3
4
5
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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
/*
* 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

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
/* 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:

1
2
3
4
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的目录:

1
2
3
4
5
6
7
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支持:

1
2
3
4
5
6
7
8
9
10
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

1
2
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

1
2
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

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

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

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

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

1
2
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

1
2
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指定的含义介绍如下:

1
2
3
4
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说明

上述+-号含义如下:

1
2
3
\-    remove the given flags 
\+ add the given flags
= set the flags to the given flags

支持的flag有:

1
2
3
4
5
6
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配置:

如下所示:

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

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

1
2
3
4
5
6
7
8
9
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

支持原创