前回のパッチとは別でフレームバッファのドライバでのメモリーリークを修正するパッチを投げたのでデバッグのメモ
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_fbとcon2fb_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);
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 ―パフォーマンス改善、開発効率向上、省電力化のためのテクニック
- 作者: 池田宗広,大岩尚宏,島本裕志,竹部晶雄,平松雅巳,高橋浩和
- 出版社/メーカー: オライリージャパン
- 発売日: 2011/07/26
- メディア: 単行本(ソフトカバー)
- 購入: 4人 クリック: 50回
- この商品を含むブログ (4件) を見る