読者です 読者をやめる 読者になる 読者になる

lkmlにフレームバッファのメモリーリーク修正パッチを投げたのでそのデバッグ過程メモ

kernel linux

前回のパッチとは別でフレームバッファのドライバでのメモリーリークを修正するパッチを投げたのでデバッグのメモ

kmemleakのレポートはこのようなもの。

unreferenced object 0xffff880036ca84c0 (size 16):
  comm "swapper/0", pid 1, jiffies 4294877407 (age 4434.633s)
  hex dump (first 16 bytes):
    00 00 00 00 00 00 00 00 00 00 00 00 00 00 ff ff  ................
  backtrace:
    [<ffffffff814ed01e>] kmemleak_alloc+0x4e/0xb0
    [<ffffffff8118913c>] __kmalloc+0x1fc/0x290
    [<ffffffff81302c9e>] bit_cursor+0x24e/0x6c0
    [<ffffffff812ff2f4>] fbcon_cursor+0x154/0x1d0
    [<ffffffff813675d8>] hide_cursor+0x28/0xa0
    [<ffffffff81368acf>] update_region+0x6f/0x90
    [<ffffffff81300268>] fbcon_switch+0x518/0x550
    [<ffffffff813695b9>] redraw_screen+0x189/0x240
    [<ffffffff8136a0e0>] do_bind_con_driver+0x360/0x380
    [<ffffffff8136a6e4>] do_take_over_console+0x114/0x1c0
    [<ffffffff812fdc83>] do_fbcon_takeover+0x63/0xd0
    [<ffffffff813023e5>] fbcon_event_notify+0x605/0x720
    [<ffffffff81501dcc>] notifier_call_chain+0x4c/0x70
    [<ffffffff81087f8d>] __blocking_notifier_call_chain+0x4d/0x70
    [<ffffffff81087fc6>] blocking_notifier_call_chain+0x16/0x20
    [<ffffffff812f201b>] fb_notifier_call_chain+0x1b/0x20

まずメモリを確保したところを探す。
関数はbit_cursor()なのでここを見る。

237 static void bit_cursor(struct vc_data *vc, struct fb_info *info, int mode,
238                        int softback_lines, int fg, int bg)
239 {
240         struct fb_cursor cursor;
241         struct fbcon_ops *ops = info->fbcon_par;

この関数では2ヶ所kmalloc()してる。
1つ目はここ。

270         if (attribute) {
271                 u8 *dst;
272 
273                 dst = kmalloc(w * vc->vc_font.height, GFP_ATOMIC);
274                 if (!dst)

もう一つはこちら。

312         if (cursor.set & FB_CUR_SETSIZE ||
313             vc->vc_cursor_type != ops->p->cursor_shape ||
314             ops->cursor_state.mask == NULL ||
315             ops->cursor_reset) {
316                 char *mask = kmalloc(w*vc->vc_font.height, GFP_ATOMIC);
317                 int cur_height, size, i = 0;

とりあえずお手軽にkmalloc()で返ってきたアドレスをこんな感じでprintkで表示させると316行目のほうでアロケートしたメモリがリークしていることが分かったので、次はどのようにリークしたかをチェック。

pr_info("kmalloc: %p\n", mask)

ここでallocしたmaskって変数は構造体の変数に代入されるので構造体が不要になったタイミングで解放漏れの可能性があると。
そこで、毎度お馴染みのprintkデバッグで(このメモリーリークしたプロセスってpid1でシェルも立ち上がって無い時の話なのでprintkで良いかみたいなw)。ちなみにpr_info("")はprintk(KERN_INFO "")のシンタックスシュガーです。
そうするとこの関数はシェルでログインしてdmesgするまでの間に5回呼ばれてた。

1度目のkmalloc
[ 0.370507] kmalloc2: info ffff8801193ce800
[ 0.370508] kmalloc2: ops ffff8801166ac600
[ 0.370508] kmalloc2: mask ffff880036ca84c0
[ 0.370508] kmalloc2: free (null)

2度目のkmalloc
[ 0.371836] kmalloc2: info ffff8801193ce800
[ 0.371836] kmalloc2: ops ffff8801166ac600
[ 0.371836] kmalloc2: mask ffff880036ca84d0
[ 0.371837] kmalloc2: free ffff880036ca84c0

3度目のkmalloc
[ 0.371851] kmalloc2: info ffff8801193ce800
[ 0.371851] kmalloc2: ops ffff8801166ac600
[ 0.371851] kmalloc2: mask ffff880036ca84c0
[ 0.371852] kmalloc2: free ffff880036ca84d0

4度目のkmalloc
[ 0.983978] kmalloc2: info ffff8800d9eeb000
[ 0.983978] kmalloc2: ops ffff880036fef800
[ 0.983978] kmalloc2: mask ffff8800db2826a0
[ 0.983979] kmalloc2: free (null)

5度目のkmalloc
[ 0.993194] kmalloc2: info ffff8800d9eeb000
[ 0.993195] kmalloc2: ops ffff880036fef800
[ 0.993195] kmalloc2: mask ffff8800db2826b0
[ 0.993195] kmalloc2: free ffff8800db2826a0

これで表示しているのは
info:引数で渡ってくる変数のinfo
ops:struct fbcon_ops *ops = info->fbcon_par;
mask:char *mask = kmalloc(w*vc->vc_font.height, GFP_ATOMIC);の結果
free:freeしたアドレス。maskをkmallocすると以下のように古い値kfree()してから代入しているので、kfreeしたアドレスを表示。

323                 kfree(ops->cursor_state.mask);
324                 ops->cursor_state.mask = mask;

そうすると0xffff880036ca84c0の流れが見えてきた。
1度目のkmallocで0xffff880036ca84c0が返ってきてops->cursor_state.maskに代入される。
2度目のkmallocでは0xffff880036ca84c0が解放される。
3度目のkmallocでは再度0xffff880036ca84c0が返ってくる(これはさっきkfreeして空いているオブジェクトだから返ってきたんでしょう)
と、ここまでではkmalloc->kfree->kmallocときてます。そして、ここで注目するべきは変数infoの値。こいつは0xffff8801193ce800。
1~3回目まではinfoのアドレスは0xffff8801193ce800なんだけど4、5回目は違っている!!
とゆうことで、どこかのタイミングでinfoが変わったんじゃないかということが考えられる。まずはkmemleakのスタックトレースからinfoがどのように渡されているかを調べる。

まずは1つ手前のfbcon_cursor()を見てみるといきなり該当個所が見つかるw

1305 static void fbcon_cursor(struct vc_data *vc, int mode)
1306 {
1307         struct fb_info *info = registered_fb[con2fb_map[vc->vc_num]];
1308         struct fbcon_ops *ops = info->fbcon_par;

そしたらみんな大好きprintk()デバッグでvc->vc_numを表示させるとこの値はいつも0だった。
ということは、registered_fb[con2fb_map[0]]がどこかのタイミングで変わっている><

ここで一旦dmesgのログに戻ってみる。そうするとfbcon_cursor()を呼ばれるときに以下のようなログが出ていることに気付いた。

Console: switching to colour frame buffer device 128x48

ということで、grepで調べてみるとdo_bind_con_driver()が出てくる。

3067         pr_info("Console: switching ");
3068         if (!deflt)
3069                 printk("consoles %d-%d ", first+1, last+1);
3070         if (j >= 0) {
3071                 struct vc_data *vc = vc_cons[j].d;
3072 
3073                 printk("to %s %s %dx%d\n",
3074                        vc->vc_can_do_color ? "colour" : "mono",
3075                        desc, vc->vc_cols, vc->vc_rows);
3076 
3077                 if (k >= 0) {
3078                         vc = vc_cons[k].d;
3079                         update_screen(vc);
3080                 }
3081         } else
3082                 printk("to %s\n", desc);

余談だけど関数のコールフローとかを追うにはlxrを使ってて、こういったメッセージを探すときはgrep使ってます。lxrのフリーテキストサーチだとちょっと探し辛いのでgrepのほうが個人的には楽。ctagsも使ってるけどlxrのほうが個人的には使いやすいとか。
それはさておき、do_bind_con_driver()がどのようなタイミングで呼ばれているのかというとトレースに出ているので無問題。

  backtrace:
    [<ffffffff814ed01e>] kmemleak_alloc+0x4e/0xb0
    [<ffffffff8118913c>] __kmalloc+0x1fc/0x290
    [<ffffffff81302c9e>] bit_cursor+0x24e/0x6c0
    [<ffffffff812ff2f4>] fbcon_cursor+0x154/0x1d0
    [<ffffffff813675d8>] hide_cursor+0x28/0xa0
    [<ffffffff81368acf>] update_region+0x6f/0x90
    [<ffffffff81300268>] fbcon_switch+0x518/0x550
    [<ffffffff813695b9>] redraw_screen+0x189/0x240
    [<ffffffff8136a0e0>] do_bind_con_driver+0x360/0x380

ついでにregistered_fbcon2fb_mapの定義も見ておく。

 47 struct fb_info *registered_fb[FB_MAX] __read_mostly;
 97 static signed char con2fb_map[MAX_NR_CONSOLES];

では、次にregistered_fbに値を設定しているところを探す。そして見つかったのがdo_register_framebuffer()

1660         registered_fb[i] = fb_info;

そうしたら、registered_fbからデータを削除しているところを探すとdo_unregister_framebuffer()が見つかる。

1699         registered_fb[i] = NULL;

この1699行でNULLポインタに設定しているのでその前の段階でデータの解放処理があるはずと考えるのが自然。

ここででdo_unregister_framebuffer()が重要っぽいのが分かったけど、本当にここを通っているかを確認するために関数の冒頭にWARN_ON(1);を入れてみる。それと、NULLポインタ代入の前にprintkを入れて該当の変数(リークした変数)がどうなっているかも確認した結果がこちら。

[ 0.936971] Console: switching to colour dummy device 80x25
[ 0.936974] ------------[ cut here ]------------
[ 0.936978] WARNING: CPU: 0 PID: 138 at drivers/video/fbmem.c:1731 unlink_framebuffer+0x22/0x90()
[ 0.936979] Modules linked in: cirrus(+) ttm drm_kms_helper snd_hda_codec ppdev drm syscopyarea sysfillrect sysimgblt microcode snd_hwdep evdev snd_pcm snd_page_alloc pcspkr psmouse serio_raw snd_timer snd soundcore i2c_piix4 i2c_core parport_pc parport processor button intel_agp intel_gtt ext4 crc16 mbcache jbd2 sr_mod cdrom ata_generic pata_acpi virtio_balloon virtio_blk virtio_net ata_piix uhci_hcd libata scsi_mod usbcore usb_common virtio_pci virtio_ring virtio floppy
[ 0.936995] CPU: 0 PID: 138 Comm: systemd-udevd Not tainted 3.13.0-rc5-leakfix+ #25
[ 0.936996] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[ 0.936997] 0000000000000009 ffff8800db519a30 ffffffff814f75ff 0000000000000000
[ 0.936998] ffff8800db519a68 ffffffff81061c9d ffff8801193ae800 ffff8801193ae800
[ 0.937000] 0000000000000000 ffff8801162ad700 0000000000000001 ffff8800db519a78
[ 0.937002] Call Trace:
[ 0.937006] [<ffffffff814f75ff>] dump_stack+0x4d/0x6f
[ 0.937009] [<ffffffff81061c9d>] warn_slowpath_common+0x7d/0xa0
[ 0.937011] [<ffffffff81061d7a>] warn_slowpath_null+0x1a/0x20
[ 0.937012] [<ffffffff812f2a52>] unlink_framebuffer+0x22/0x90
[ 0.937014] [<ffffffff812f3be0>] do_unregister_framebuffer+0xa0/0x130
[ 0.937016] [<ffffffff812f3ddc>] do_remove_conflicting_framebuffers+0x16c/0x1a0
[ 0.937018] [<ffffffff812f3e42>] remove_conflicting_framebuffers+0x32/0x50
[ 0.937022] [<ffffffffa03ba820>] cirrus_pci_probe+0x90/0xd0 [cirrus]
[ 0.937024] [<ffffffff812c91d5>] local_pci_probe+0x45/0xa0
[ 0.937026] [<ffffffff812c8955>] ? pci_match_device+0xc5/0xd0
[ 0.937028] [<ffffffff812c9309>] pci_device_probe+0xd9/0x130
[ 0.937031] [<ffffffff8138f467>] driver_probe_device+0x87/0x3a0
[ 0.937032] [<ffffffff8138f853>] __driver_attach+0x93/0xa0
[ 0.937034] [<ffffffff8138f7c0>] ? __device_attach+0x40/0x40
[ 0.937036] [<ffffffff8138d473>] bus_for_each_dev+0x63/0xa0
[ 0.937037] [<ffffffff8138eebe>] driver_attach+0x1e/0x20
[ 0.937039] [<ffffffff8138eaa0>] bus_add_driver+0x180/0x250
[ 0.937041] [<ffffffffa03bf000>] ? 0xffffffffa03befff
[ 0.937043] [<ffffffff8138fed4>] driver_register+0x64/0xf0
[ 0.937045] [<ffffffffa03bf000>] ? 0xffffffffa03befff
[ 0.937046] [<ffffffff812c8abb>] __pci_register_driver+0x4b/0x50
[ 0.937051] [<ffffffffa0305f6a>] drm_pci_init+0x11a/0x130 [drm]
[ 0.937053] [<ffffffff814fc7ce>] ? mutex_unlock+0xe/0x10
[ 0.937054] [<ffffffffa03bf000>] ? 0xffffffffa03befff
[ 0.937057] [<ffffffffa03bf032>] cirrus_init+0x32/0x3b [cirrus]
[ 0.937059] [<ffffffff8100214a>] do_one_initcall+0xfa/0x1b0
[ 0.937062] [<ffffffff81087f98>] ? __blocking_notifier_call_chain+0x58/0x70
[ 0.937065] [<ffffffff810d87db>] load_module+0x1dab/0x25e0
[ 0.937067] [<ffffffff810d50a0>] ? store_uevent+0x40/0x40
[ 0.937069] [<ffffffff810d9186>] SyS_finit_module+0x86/0xb0
[ 0.937072] [<ffffffff81505a6d>] system_call_fastpath+0x1a/0x1f
[ 0.937073] ---[ end trace 553cc88824134555 ]---
[ 0.938705] kmalloc2: set null to ffff8801193ae800

たしかにdo_unregister_framebuffer()呼ばれているし変数もNULLになっているので予想が当たってた!
次にどのタイミングでNULLになったかをチェック
相変わらずのprintkデバッグによりfb_notifier_call_chain()の実行後にNULLになることが判明。

event.info = fb_info;
1699 pr_info("leakfix1: ops is %s\n", (fb_info->fbcon_par == NULL) ? "null" : "not null");
1700 ret = fb_notifier_call_chain(FB_EVENT_FB_UNBIND, &event);
1701 pr_info("leakfix2: ops is %s\n", (fb_info->fbcon_par == NULL) ? "null" : "not null");
1702 unlock_fb_info(fb_info);
1703 pr_info("leakfix3: ops is %s\n", (fb_info->fbcon_par == NULL) ? "null" : "not null");
1704 console_unlock();

とゆうことで次はfb_notifier_call_chain()を調べなければいけない。
fb_notifier_call_chain()はこのような関数。

 43 int fb_notifier_call_chain(unsigned long val, void *v)
 44 {
 45         return blocking_notifier_call_chain(&fb_notifier_list, val, v);
 46 }
 47 EXPORT_SYMBOL_GPL(fb_notifier_call_chain);

次はblocking_notifier_call_chain()

322 int blocking_notifier_call_chain(struct blocking_notifier_head *nh,
323                 unsigned long val, void *v)
324 {
325         return __blocking_notifier_call_chain(nh, val, v, -1, NULL);
326 }

__blocking_notifier_call_chain()はこう。

301 int __blocking_notifier_call_chain(struct blocking_notifier_head *nh,
302                                    unsigned long val, void *v,
303                                    int nr_to_call, int *nr_calls)
304 {
~中略~
312         if (rcu_dereference_raw(nh->head)) {
313                 down_read(&nh->rwsem);
314                 ret = notifier_call_chain(&nh->head, val, v, nr_to_call,
315                                         nr_calls);
~中略~
319 }
320 EXPORT_SYMBOL_GPL(__blocking_notifier_call_chain);

次はnotifier_call_chain()

 74 static int __kprobes notifier_call_chain(struct notifier_block **nl,
 75                                         unsigned long val, void *v,
 76                                         int nr_to_call, int *nr_calls)
 77 {
 78         int ret = NOTIFY_DONE;
 79         struct notifier_block *nb, *next_nb;
 80 
~中略~
 93                 ret = nb->notifier_call(nb, val, v);
 94 
~中略~
104 }

この関数の「ret = nb->notifier_call(nb, val, v);」部分。notifier_call()が何者なのか?
まずはnotifier_block構造体の定義を見る。

 53 struct notifier_block {
 54         notifier_fn_t notifier_call;
 55         struct notifier_block __rcu *next;
 56         int priority;
 57 };
 58 

そうしたらこのフレームバッファのコードでこの構造体の変数を作っている箇所を探す。
lxrでnotifier_blockをクリックすればReferenced (in 741 files total) in:って出るのでそこからdrivers/video辺りのファイルを探すって感じで。
そして見つかったのがこれ。

3333 static struct notifier_block fbcon_event_notifier = {
3334         .notifier_call  = fbcon_event_notify,
3335 };
3336 

この構造体はfb_console_init()で登録してた。

3576 static int __init fb_console_init(void)
3577 {
3578         int i;
3579 
3580         console_lock();
3581         fb_register_client(&fbcon_event_notifier);
3582         fbcon_device = device_create(fb_class, NULL, MKDEV(0, 0), NULL,

これでnb->notifier_call()で呼ばれる関数はfbcon_event_notify()というのが分かってたのでそれを見る。
fbcon_event_notify()は見ての通りでswitch文で分岐処理が入っていて、
do_unregister_framebuffer()ではFB_EVENT_FB_UNBINDを渡しているのでそこを見るとfbcon_fb_unbind()を見る必要があると分かる。

3262         case FB_EVENT_FB_UNBIND:
3263                 idx = info->node;
3264                 ret = fbcon_fb_unbind(idx);
3265                 break;

fbcon_unbind()は単純でdo_unbind_con_driver()を呼ぶだけ。

2991 static int fbcon_unbind(void)
2992 {
2993         int ret;
2994 
2995         ret = do_unbind_con_driver(&fb_con, first_fb_vc, last_fb_vc,
2996                                 fbcon_is_default);
2997 
2998         if (!ret)
2999                 fbcon_has_console_bind = 0;
3000 
3001         return ret;
3002 }

do_unbind_con_driver()はというと長いのでコピペしないけど、最後のdo_bind_con_driver()を見る必要があった。

3180         /* ignore return value, binding should not fail */
3181         do_bind_con_driver(defcsw, first, last, deflt);

しかし、do_unbind_con_driver()からdo_bind_con_driver()呼び出すってunbindしたいのかbindしたいのかどっちだよってツッコミたくなるw
それはさておきdo_bind_con_driver()を見る。
この関数を見て行ってこれは!と思ったのがこれ。

3053                 vc->vc_sw->con_deinit(vc);

これは見ての通り関数ポインタなので探すの面倒なんだけどlxr様の力によりstruct consw fb_conが見つかる。

3305 static const struct consw fb_con = {
3306         .owner                  = THIS_MODULE,
3307         .con_startup            = fbcon_startup,
3308         .con_init               = fbcon_init,
3309         .con_deinit             = fbcon_deinit,
3310         .con_clear              = fbcon_clear,
3311         .con_putc               = fbcon_putc,
3312         .con_putcs              = fbcon_putcs,
3313         .con_cursor             = fbcon_cursor,
3314         .con_scroll             = fbcon_scroll,
3315         .con_bmove              = fbcon_bmove,
3316         .con_switch             = fbcon_switch,
3317         .con_blank              = fbcon_blank,
3318         .con_font_set           = fbcon_set_font,
3319         .con_font_get           = fbcon_get_font,
3320         .con_font_default       = fbcon_set_def_font,
3321         .con_font_copy          = fbcon_copy_font,
3322         .con_set_palette        = fbcon_set_palette,
3323         .con_scrolldelta        = fbcon_scrolldelta,
3324         .con_set_origin         = fbcon_set_origin,
3325         .con_invert_region      = fbcon_invert_region,
3326         .con_screen_pos         = fbcon_screen_pos,
3327         .con_getxy              = fbcon_getxy,
3328         .con_resize             = fbcon_resize,
3329         .con_debug_enter        = fbcon_debug_enter,
3330         .con_debug_leave        = fbcon_debug_leave,
3331 };

fbcon_deinit()を見ろということですね!で、早速見てみるとfbcon_deinit()はたいしたことはやってなくて関数最後のfbcon_exit()が重要な感じに見える。

con_is_bound()でbindされているか調べているけど、今はunbindの処理から呼ばれているのでfbcon_exit()が呼ばれる。

1205 
1206         if (!con_is_bound(&fb_con))
1207                 fbcon_exit();
1208 

そしてfbcon_exit()を見てみると、ついに構造体のメンバを解放しているところを発見!

3554                 if (mapped) {
3555                         if (info->fbops->fb_release)
3556                                 info->fbops->fb_release(info, 0);
3557                         module_put(info->fbops->owner);
3558 
3559                         if (info->fbcon_par) {
3560                                 struct fbcon_ops *ops = info->fbcon_par;
3561 
3562                                 fbcon_del_cursor_timer(info);
3563                                 kfree(ops->cursor_src);
3564                                 kfree(info->fbcon_par);
3565                                 info->fbcon_par = NULL;
3566                         }
3567 

このinfo->fbcon_parがNULLじゃなかった場合にkfree()しているけど、maskが入ってないじゃんか!!!ってことでここでkfree()を入れたカーネルを作って再起動したところkmemleakからのメモリーリークレポートがなくなった。キタ━(゜∀゜)━!
ということで、ここまで調べた結果をまとめて作ったパッチがこれ。数時間の調査結果が1行にまとめられてますw

diff --git a/drivers/video/console/fbcon.c b/drivers/video/console/fbcon.c
index cd8a802..4f02375 100644
--- a/drivers/video/console/fbcon.c
+++ b/drivers/video/console/fbcon.c
@@ -3561,6 +3561,7 @@ static void fbcon_exit(void)
 
 				fbcon_del_cursor_timer(info);
 				kfree(ops->cursor_src);
+				kfree(ops->cursor_state.mask);
 				kfree(info->fbcon_par);
 				info->fbcon_par = NULL;
 			}

Linuxカーネル Hacks ―パフォーマンス改善、開発効率向上、省電力化のためのテクニック

Linuxカーネル Hacks ―パフォーマンス改善、開発効率向上、省電力化のためのテクニック