Ceph Kernel module dynamic debug

Ceph · 發表 2018-11-10 00:17:48

摘要：在使用CephFS的kernel client後，發現它對比ceph-fuse客戶端，不方便找到對應的log了，在dmesg或kern.log裡也僅有很少的log輸出，這在遇到問題的時候很不方便，需要找到列印Ceph kernel log的方法。程式碼定義 Ceph的kernel...

在使用CephFS的kernel client後，發現它對比ceph-fuse客戶端，不方便找到對應的log了，在dmesg或kern.log裡也僅有很少的log輸出，這在遇到問題的時候很不方便，需要找到列印Ceph kernel log的方法。

程式碼定義

Ceph的kernel module有兩個，如下：

root@ceph2:~# lsmod | grep ceph
ceph3850240
libceph3153921 ceph
fscache3686401 ceph
libcrc32c163848 nf_conntrack,nf_nat,dm_persistent_data,btrfs,xfs,raid456,libceph,ip_vs

ceph：CephFS kernel client模組
libceph：Ceph kernel網路通訊模組

在Ceph kernel的程式碼裡，有兩類log輸出機制：

pr_debug 輸出

分為 info / warning / error等好多種，呼叫 printk 輸出；
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 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

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有：

penables the pr_debug() callsite. 
fInclude the function name in the printed message 
lInclude line number in the printed message 
mInclude module name in the printed message 
tInclude 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

參考文章

ofollow,noindex">https://lwn.net/Articles/434856/

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