川の流れのように‥(Eiji Ota's Weblog)

leakにも強いSol10のmdb:あぁぁなんて便利なのぉの巻

皆さん、こんにちは。 週末は如何でしたか？ すっかり間が空いてしまい、ちょっとご無沙汰って感じです。(^-^).oO (Gobusata Desu!) 障害調査やらI/Oメモリやらで、カラカラと走り回っていたんですけれど、それに加え、 娘の通う日本語補習校のボランティアにはまってしまいました。はは。。。^.^; ボランティアで、 Webアプリを作っているんですけど、普段の開発とは畑違いの世界。でも、Webアプリに 興味があったので（流行ものに弱い）、ちょっと深入りしてしまったらはまってしまいました。^0^ MySQL ＋ PHP ＋ Javascriptなんで、完全にインタープリターの世界。 すぐ結果がみれる‥デバックもサクサク快感シリーズ。 あぁぁこのサクサク感がいいぃって浸ってしまい、ついつい夜更かしを繰り返し、ついには 家でも会社でも、昼でも夜でもプログラムを作っている有様。。。妙に若い頃を思い出してしまいました。 たまには違うプログラミングも楽しいって分かったこの頃です。(^_^) ちょっと脱線してしまいましたけど、今日も助っ人mdb君のお話です。 やっぱりプログラミングではデバックもサクサク快感を味わいたいモノ。 Solaris君にはmdbがついているさっていうことで、普通なら頭を抱えてしまいがちな、 メモリリークをmdbでささぁ、さくさくっていうところをご紹介です。 メモリリークというトラブルは、何にもないと＊＊とてつもなく、そして限りなく＊＊大変。 (はぁぁ‥考えただけでも、重くなってしまうぐらい‥) トラブルの状況も、マシンがだんだんと重くなって‥まるで足に１つ１つ重石を繋がれている ように、徐々に先に進まなくなってきて‥そして、もうズリズリと最後は這っているかのような‥ こういうトラブルに見舞われたら、あぁあなたのマシンにもメモリリーク居るかも？ メモリリークは原因を探るのは難しいくせに、ワークアランドは簡単明快。そうです、マシンを リブートしちゃうんです。そうすると、それまで溜めに溜めた重石を全部捨て去るように、 いきなりサクサクに戻りますよね。でも、また数日して徐々に重くなっていく感じが復活。(--;) 仕方無しに、定期的にリブートするようにするかぁぁっていう体験はありませんか？ そうです、それがメモリリークくんなんです。困ったものですねぇ。 さて、この困り者のメモリリークくん、調査しようとなると、まずはパニックではないので、 メッセージも何もありません。遅くなったら強制的にクラッシュダンプを取るのが第一歩です。 でも、そこからが地道な作業の始まり‥カーネル内のメモリの使用状況をみて、どの子が重りを つけられ、アップアップしているか探し、やたら巨大化して肥満状態になった子をみつけたら、 その子がどこでやたらメモリを食べているかを探す‥っていうのが、今まででした‥。^^; でも何も情報がないのでは、砂漠に埋もれた指輪を探すようなもの。壮大な砂漠を目前に途方に くれてしまいますね。(T-T) でもSolarisの場合は、嬉しい機能が幾つかあって、壮大な砂漠を抜ける道を教えてくれるので 本当に助かるなぁ。"-"　 メモリリークで当たりをつけるには、メモリにロギング機能がないと話になりません - この子が 重そうだって分かっても、何も情報がないのでは、結局は巨大なジャングルのようなソースコードを 走り回るようなもの。たっぷり汗をかくわりには、結局迷子になりかねませんよね。^.^ Solarisは、カーネルメモリのアロケートにslab allocator (object-caching kernel memory allocator) を使用しています。Jeff Bonwickさんが作成したものですが、大変 有名なもので、数々のOSに影響を与えているカーネルメモリ・アロケーターです。最近ではLinux/BSDも 似たような実装を行っています。興味がある人は、次のUsenixの論文に目を通されてもよいし、巷で 売られているカーネル本にも簡単な解説があったりします。(でも、ちょっと難しいので‥心してね^-^） Jeff Bonwickさんの(最初の)論文。 The Slab Allocator: An Object-Caching Kernel Memory Allocator (1994) カーネル本には、例えば、Uresh VahaliaさんのUnix Internals: The New Frontiers. (Prentice Hall, 1996)が有名かも知れません。 まぁ、slab allocatorの実装の詳細はそちらに譲るとして、slab allocatorには、 object-cachingによる性能改善以外に強力なログ機能があって、このログ機能が、メモリ破壊や メモリリークに一役かっているんですよぉ。このログ機構のお陰で、メモリ破壊の調査がやたら楽。 涙ポロポロものなんですけど、mdbのマニュアルとかを見て貰うと、何となく分かって貰えるかも？ さて、メモリリークくんには、そのものズバリの"findleaks"というコマンドがmdbには用意されていて、 こいつを使ってやれば、あっという間のリークくん(←なんじゃらほい？)になるんですよ。 では、ちょっと見てやりましょうね。(前置きながかった？かしら‥） さぁ、トラブルが発生、あなたはクラッシュダンプを取りました。トラブッた人の話では、 どうやらメモリリークの様子。 でも大丈夫。findleaksで一発！ さぁいきますよぉ。

> ::findleaks
CACHE             LEAKED           BUFCTL CALLER
000003000006f688       1 00000300088fada8 cpr_isset+0x14
000003000006f688       1 0000030008d72da8 cpr_write_header+0x64
000003000006f688       1 0000030008143570 devi_attach+0xcc
000003000006f688       1 000003013875e280 devi_attach+0xcc
000003000006f688       1 000003004461d938 devi_attach+0xcc
000003000006f688       1 000003000a819738 devi_attach+0xcc
000003000006f688       1 00000300210add68 devi_attach+0xcc
000003000006f688       1 00000300022b67c8 devi_attach+0xcc
000003000006f688       1 00000300095cbdf0 devi_attach+0xcc
000003000006f688       1 000003000994c038 devi_attach+0xcc
0000030001453688       1 0000030008f0d4f8 dv_mknod+0x28
000003000006f688       1 000003000acd6e88 dv_mknod+0x44
0000030000073408       1 0000030009217c08 dv_shadow_node+0x4c8
000003000006f688       1 0000030050a3b4d0 frrequest+0xafc
000003000006f688       1 000003000964a268 ibt_query_qp+0x108
0000030000077188       1 00000300009fb6b0 kobj_export_ksyms+0x11c
000003000007a008       1 00000300009f6868 kobj_export_ksyms+0x11c
0000030000077b88       1 00000300009eb5a8 kobj_export_ksyms+0x11c
000003000006f688       1 0000030000cc5b88 kobj_zalloc+8
000003000006f688       3 00000300087d6938 kobj_zalloc+8
000003000006f908       1 00000300091f1180 nv_mem_zalloc+0x10
000003000006f908       1 0000030008084338 nv_mem_zalloc+0x10
0000030000072008       1 0000030001f61cc0 nv_priv_alloc+0x10
0000030000072008       1 0000030001f5f630 nv_priv_alloc+0x10
000003000006f688       1 00000300087d4d58 pcmcia_get_io_regs+0x26c
000003000006f688       1 0000030008d73a20 rmc_comm_send_pend_req+0xa4
000003000006f688       3 0000030003176208 sppptun_open+0x2e0
000003000108cc88       1 000003000920c9d0 vn_alloc+0xc
=-----------------------------------------------------------------=
           Total      32 buffers, 8936 bytes

どうですか？　誰が何回リークしたのか、一発でしょう？ じゃ、その関数のどこでメモリがアロケートされたものか、見るにはどうすればいいでしょう？ それには、BUFCTLで表示されているアドレスを、これまたズバリ"bufctl"コマンドに指定して やります。例えば‥、

> 00000300088fada8::bufctl -v
            ADDR          BUFADDR        TIMESTAMP           THREAD
                            CACHE          LASTLOG         CONTENTS
     300088fada8      300093c2d68     4f6d0aee3671      2a100cf1cc0
                      3000006f688      3000049b980      300007ae9a0
                 kmem_cache_alloc+0x90
                 kmem_zalloc+0x28
                 cpr_isset+0x14
                 i_cpr_save_cpu_info+4
                 i_cpr_mp_setup+0x2c
                 devi_attach+0xcc
                 attach_node+0xdc
                 i_ndi_config_node+0x148
                 i_ddi_attachchild+0x64
                 devi_attach_node+0x5c
                 devi_attach_children+0x90
                 config_immediate_children+0xa8
                 devi_config_common+0xa4
                 mt_config_thread+0x68

これで、メモリが解放されなかったのは、cpr_isset+0x14番地で獲得されたものだって分かりますね。 やたら簡単過ぎますっ。(-vを忘れないでね！） findleaksはSol10で強化されているのですが、例えば-dフラグをつけてやると、bufctlを使用する 必要がありませんよ。手が抜けて、嬉しい限り！

> ::findleaks -d
findleaks: using cached results (-f will force a full run)
CACHE             LEAKED           BUFCTL CALLER
000003000006f688       1 00000300088fada8 cpr_isset+0x14
000003000006f688       1 0000030008d72da8 cpr_write_header+0x64
000003000006f688       1 0000030008143570 devi_attach+0xcc
000003000006f688       1 000003013875e280 devi_attach+0xcc
000003000006f688       1 000003004461d938 devi_attach+0xcc
000003000006f688       1 000003000a819738 devi_attach+0xcc
000003000006f688       1 00000300210add68 devi_attach+0xcc
000003000006f688       1 00000300022b67c8 devi_attach+0xcc
000003000006f688       1 00000300095cbdf0 devi_attach+0xcc
000003000006f688       1 000003000994c038 devi_attach+0xcc
0000030001453688       1 0000030008f0d4f8 dv_mknod+0x28
000003000006f688       1 000003000acd6e88 dv_mknod+0x44
0000030000073408       1 0000030009217c08 dv_shadow_node+0x4c8
000003000006f688       1 0000030050a3b4d0 frrequest+0xafc
000003000006f688       1 000003000964a268 ibt_query_qp+0x108
0000030000077188       1 00000300009fb6b0 kobj_export_ksyms+0x11c
000003000007a008       1 00000300009f6868 kobj_export_ksyms+0x11c
0000030000077b88       1 00000300009eb5a8 kobj_export_ksyms+0x11c
000003000006f688       1 0000030000cc5b88 kobj_zalloc+8
000003000006f688       3 00000300087d6938 kobj_zalloc+8
000003000006f908       1 00000300091f1180 nv_mem_zalloc+0x10
000003000006f908       1 0000030008084338 nv_mem_zalloc+0x10
0000030000072008       1 0000030001f61cc0 nv_priv_alloc+0x10
0000030000072008       1 0000030001f5f630 nv_priv_alloc+0x10
000003000006f688       1 00000300087d4d58 pcmcia_get_io_regs+0x26c
000003000006f688       1 0000030008d73a20 rmc_comm_send_pend_req+0xa4
000003000006f688       3 0000030003176208 sppptun_open+0x2e0
000003000108cc88       1 000003000920c9d0 vn_alloc+0xc
=-----------------------------------------------------------------=
           Total      32 buffers, 8936 bytes

kmem_alloc_16 leak: 1 buffer, 16 bytes
            ADDR          BUFADDR        TIMESTAMP           THREAD
                            CACHE          LASTLOG         CONTENTS
     300088fada8      300093c2d68     4f6d0aee3671      2a100cf1cc0
                      3000006f688      3000049b980      300007ae9a0
                 kmem_cache_alloc+0x90
                 kmem_zalloc+0x28
                 cpr_isset+0x14
                 i_cpr_save_cpu_info+4
                 i_cpr_mp_setup+0x2c
                 devi_attach+0xcc
                 attach_node+0xdc
                 i_ndi_config_node+0x148
                 i_ddi_attachchild+0x64
                 devi_attach_node+0x5c
                 devi_attach_children+0x90
                 config_immediate_children+0xa8
                 devi_config_common+0xa4
                 mt_config_thread+0x68

（たくさん表示が続くのでカット...^-^;）

でもちょっと困ることが‥。先もお話しましたけれど、これらの情報はslab allocatorのロギング機能 で取得されたものを表示しているんです。でも、ロギングはデバックカーネルで有効。。。。 それじゃ、困りますねぇー。デバックカーネルじゃないと、findleaksは強化されたものの、 それじゃぁ限定的な情報しか表示してくれませんよねぇ。例えば、

> ::findleaks
CACHE             LEAKED           BUFFER CALLER
0000030000072308       2 000006000091f0a0 ?
0000030000073508       2 00000300003ac300 ?
0000030000076908       1 00000300000e5b40 ?
0000030000077508       1 00000300000ecac0 ?
0000030000077808       1 00000300000e7000 ?
=-----------------------------------------------------------------=
           Total       7 buffers, 8096 bytes

うーん、これじゃ、誰なのか分からない‥。(==;) ロギングは性能に影響を与えるので、通常はoffなんですよねぇ。それにデバックカーネルは製品には 使われませんし。=.=; そういう場合には、lightweighなデバックフラグを使うのも手かも知れませんよ。 /etc/systemファイルに、次の行を加えてリブートしてやるんです。 set kmem_flags = 0x00000100 すると、次のようにデバックカーネルでなくても、どの子がリークしてしまったか分かるようになりますよ。

> ::findleaks
CACHE             LEAKED           BUFFER CALLER
0000030000726c08       1 0000060000a25e40 cpu_init_private+0x54
0000030000073508       2 0000060000874580 init_cpu_info+0xcc
0000030000072308       2 00000600009f5a10 init_cpu_info+0x100
0000030000077508       1 00000300001460c0 kobj_export_ksyms+0x11c
=-----------------------------------------------------------------=
           Total       6 buffers, 2888 bytes

このフラグ、富士通がPrimePowerをサポートするのに必要として、導入された軽量なデバックフラグです。 メモリリークだけでなく、メモリ破壊にも大変有効なので、気にならない方は、Onにしておくのを お奨めしちゃいます。 (富士通のPrimePowerではデフォルトでOnになっている‥はず ^_^) メモリリークとかメモリ破壊は、本当に大変な障害なんですけど、こういうツールで今は 相当に楽になっていますよね！　嬉しいなって思う機能の一つかな。^-^ それでは。

Posted at 05:53午後 6 13, 2005 by eota in opensolaris  |  Comments[0]