路地裏ソース解読研究所

「路地裏ソース解読研究所」ブログ閉鎖について

MIRACLE LINUX — 2006-09-26T16:30:41+09:00

当ブログをご覧の皆様へ

武田保真が株式会社ミラクル・リナックスを退職したことに伴い、
当ブログを閉鎖・休止させていただくことになりましたことを、
お知らせさせていただきます。

ブログ開設以来たくさんの方にご支援を頂き、誠にありがとうございました。

岡山カーネル勉強会

yasuma — 2006-08-07T09:00:00+09:00

8/5(土)に無事、岡山カーネル勉強会を行うことができました。

その中で、私はcrashコマンドの使い方を中心に、一部ハンズオンのような形で
実際にみなさんで一緒にcrashを使ってみながら、カーネル内部を覗いていくということが簡単にできるんだということを体感していただきました。

私のセッションの流れとしては、
- VMwareでcrashをすぐに使えるMIRACLEV4.0環境をDVD-Rで配布。みなさんのノートPCで起動。
- 当日の資料にはdiskdumpやnetdumpに関する資料が無かったので、少し口頭で説明しました。
- なぜダンプが必要か?
- カーネルPANICが発生した瞬間のログやメッセージは、syslogでは記録されない。
- カーネルダンプを取得することで、問題の原因が何であるか追及することができる。

- crashの使い方
1. 稼働中カーネルのメモリ内容を簡単に見るためにcrashを使う方法
2. sysrq+cによる強制PANICを実施。カーネルダンプファイルを作成
3. 作成したダンプファイルを見ながらcrashの使い方を勉強

こういった流れで説明をしていきました。
カーネルの事を知らない方が対象でしたので、うまく伝えきることができない部分もありましたが、「crashを使ってカーネルの勉強することができる」というのは新しい発見でした。

当日の資料を載せておきますので、ぜひ参考にしてみてください。
kernel_study_20060805.pdfをダウンロード

ファイルシステムに関する情報源

yasuma — 2006-07-28T16:24:00+09:00

みなさんは、WikiPediaを使ったことはありますか。

今回、たまたまGoogle検索の結果でWikiPediaのページがひっかかったのですが、
英語版は内容が充実していますね。

参考までに、Linuxの3つのファイルシステムに関するページを見てください。

Ext3 : http://en.wikipedia.org/wiki/Ext3
XFS : http://en.wikipedia.org/wiki/XFS
ReiserFS : http://en.wikipedia.org/wiki/ReiserFS

弊社でもよくファイルシステムの制限値などに関して問い合わせを受けることがあるのですが、一般的な内容に関しては上記のページの内容で十分すぎるほどに記載されています。
日本語で記載されていないので、少し障壁が高いかもしれませんが情報源としては、非常に価値のあるものだと思います。
ぜひ、みなさんも活用してみてはいかがでしょうか。

2進数と10進数の区別

yasuma — 2006-07-27T16:14:25+09:00

最近、Linuxに関連するドキュメントなどで、KiBとかGiBといった単位を目にする機会が増えてきました。
詳細については、このあたりのドキュメントが詳しいのですが、ギガやテラといった桁になると、2進数での計算結果と、10進数での計算結果の差が大きくなるので明確に使い分けなければ、大きな誤解を招くことになるために、2進数用の単位としてKiBやGiBを使うことが一般的になりつつあるようです。

HDDは100ギガバイトですが、メモリは1ギビバイトというべきみたいです。
みなさんも「キロ、メガ、ギガ、テラ、ペタ」を覚えたら、「キビ、メビ、ギビ、テビ、ペビ」を覚えて使いこなしてみてはいかがでしょうか。

何も知らない人が聞くと、どれも呪文のようですね。

岡山カーネル勉強会(詳細)

yasuma — 2006-07-26T10:49:22+09:00

先日お知らせした岡山カーネル勉強会ですが、内容もほぼ固まりつつありますので、改めてご紹介しておきます。

8/5(土) 13:00-18:00に岡山理科大学にて実施します。
詳細確認、申し込みはこちらのwikiにてお願いします。
岡山カーネル勉強会

さて私の担当の時間ですが、MIRACLE LINUX V4.0を使って、「crashを使ってカーネル内部を覗いて見よう」という内容で実施しようと思い準備中です。

そこで、当日の実演用にVMware Player用のMIRACLE LINUX V4.0環境を用意しています。
MIRACLE LINUX V4.0の最小構成インストールに、kernel-debuginfoや、crashコマンドの最新版など、カーネル内部を覗いて見るのに必要なものを含めています。
X Windowなどを除くことで2GB程度のイメージに抑えることができましたので、DVD-Rで参加者のみなさんにも実行環境としてお渡しする予定です。
当日、ノートPCを持ってこられる方は、ぜひVMware Playerをインストールしておいてください。もちろんVMware Workstationとかがインストールされているならば、そちらでも構いません。

USB接続のDVD-ROMドライブを持参する予定ですので、DVD-ROMドライブが付いていない方でも、PCにコピーしてもらって使ってもらおうと思っています。

あとはリモートログインするために、Windows環境の方はputtyなどのssh端末を用意しておくと便利だと思います。

当日の私の発表資料については、後日、本BLOGに掲載する予定です。

それではみなさんの参加をお待ちしています。

ダンプを解析する技術と伝える技術

yasuma — 2006-07-25T09:00:00+09:00

ひらさんの「困難は手法を見つける手がかり」に書かれている「記憶力の限界」というのは、私自身、ダンプ解析の際には、そのたびごとにソースを眺めながらダンプを追っていることからも、自分の記憶力に限界があることは明白だ。

ひらさんはソースコードを解析する手法として「ひらメソッド」と呼ぶ、記録による新しい解析手法を提案している。

一方の私がブログに最近書いているのは、ダンプ解析やカーネル内部を覗く手法ということで、まだ私の中で方法論として確立されていない方法ではあるが、自分がやったことを単に書くという形で披露している。
ただ、弊社吉岡のエントリ「プロセスプログラミングの実践方法」にも書かれているとおり、作業の記録をとることがその第一歩であるというのは共通の認識だ。

ひらさんのサイトにある言葉で「記録力」を高める第一歩が、私にとってはブログにダンプ解析の経緯を記録することであったりする。
技術や知識が記録になった時点で、その記録を通じて他人とそれらを共有することが可能になると思う。そしてその記録は自分の記憶力の限界も越えることができる。

私のブログも、読者との技術・知識の共有の素となることを願って書いている。

そして、その内容をいかにうまく伝えるか、それを私は「技術をことばにする」と呼んでいる。いかに上手に「ことば」にできるかで、相手に伝わる技術、伝わらない技術が出てきてしまう。

この「ことば」の洗練方法を学んでいると思う今日このごろです。

kernel-2.6.17でのspinlockのオーナー情報

yasuma — 2006-07-24T09:00:00+09:00

先日のダンプ内のSPINLOCKのコメント欄で話題になっていたspinlockのオーナーの特定についてですが、少し調べてみました。

Fedora Core 5のUpdateカーネルとして提供されている2.6.17-1.2157_FC5と、

http://people.redhat.com/anderson/ で提供されているcrash-4.0-2.33の組み合わせでカーネルの内部を覗いて見ました。

kernel-debuginfoは、
ftp://ftp.kddlabs.co.jp/pub/Linux/distributions/fedora/core/updates/5/i386/debug/kernel-debuginfo-2.6.17-1.2157_FC5.i686.rpm

あたりからダウンロードしてきます。約800MB程度ありますので、ご注意を。

まず最初にkernel-2.6.17-1.2157_FC5.i686.rpmをインストールし、そのカーネルで起動します。

続いて、kernel-debuginfo-2.6.17-1.2157_FC5.i686.rpmと、crash-4.0-2.33.i386.rpmをインストールしてから下記の操作を行います。

-------------
# uname -r
2.6.17-1.2157_FC5
# crash /boot/System.map-2.6.17-1.2157_FC5
crash> ps
--------------
で適当なプロセス(syslogdなどが良いでしょう)を選択して、filesコマンドでファイル一覧を表示させます。

----------------------

crash> files 1473

PID: 1473 TASK: c1321550 CPU: 0 COMMAND: "syslogd"

ROOT: / CWD: /
FD FILE    DENTRY INODE TYPE PATH
0 c132e500 d08fe6e0 d1c985b4 SOCK socket:/[3800]
1 d1af3d80 d0a1f930 d0a47b58 REG /var/log/messages
2 c12c7900 d0a1f9c4 d0a478b4 REG /var/log/secure
3 d1c965c0 d08fe2d4 d0a47610 REG /var/log/maillog
4 d1dc78c0 d08fe240 d0a4736c REG /var/log/cron
5 d1dc7a40 d08feef8 d0a470c8 REG /var/log/spooler
6 c13c10c0 d0a1fc14 d0a62dfc REG /var/log/boot.log
-----------------
次にinode情報を表示させてみます。
-----------------
crash> struct inode d0a62dfc
....
i_lock = {
   raw_lock = {
         slock = 1
   },
   magic = 3735899821,
   owner_cpu = 4294967295,
   owner = 0xffffffff
},
....
-------
というように、spinlockをつかんでいるownerのエントリを確認することができるようになっていました。
今回は、稼動中のカーネルの情報を見ましたので、実際にspinlockを取得している瞬間ではないためownerのエントリが0xffffffffに初期化されていましたが、実際のデッドロックの発生時など、ダンプファイルからデッドロックの原因特定に役立つことは間違いなさそうです。

ログイン時のサウンド

yasuma — 2006-07-20T09:00:00+09:00

みなさんはMIRACLE LINUX V4.0のログイン時のサウンドって聞いたことがありますか?

実を言うと、私は、今日、初めて聞きました。
なにしろ社内にあるのはサーバーばかりで、サウンドカードもスピーカーも付いていないマシンばかりなのです。
風の噂でログインサウンドが鳴るというのは知っていたのですが、実際のサウンドは初めてでした。偶然、ヘッドフォンをつないでいて気づきました。

このサウンドを作ったのは我が社ではなく、多分RedFlag社だと思いますが、なかなかいけています。3社でAsianuxを共同開発しているのでお互いの得意分野を活かすという部分の一端ですね。

ちなみに簡単に聞く方法としては、Windows上のVMwareにML40をインストールして、VMwareのサウンドも有効にしておくことです。startxするとサウンドが聞こえてきます。
ぜひお試しあれ。

dump解析(1) 二の巻

yasuma — 2006-07-19T09:00:00+09:00

さて、前回、buffer_headを特定したものの、なぜこのbuffer_headがロックされたままとなっているのか分かりません。
さらに調べを進めていきたいと思います。

__wait_on_buffer()でなぜ待ちつづけるかというと、__wait_on_buffer()内のsync_buffer()でバッファのロックが解除されないからです。
では、sync_buffer()を調べてみましょう。
-----
fs/buffer.c
static void sync_buffer(struct buffer_head *bh)
{
struct block_device *bd;

      smp_mb();
      bd = bh->b_bdev;
      if (bd)
            blk_run_address_space(bd->bd_inode->i_mapping);
}
-----

ここで、b_bdevは、前回、0xf7f10a80が入っていましたので、blk_run_address_space()が実行されるはずです。そこで、bd->bd_inode->i_mappingを調べてみます。
----
crash> struct block_device 0xf7f10a80
struct block_device {
bd_dev = 9437185,
bd_inode = 0xf7f10af4,
bd_openers = 1,
-----
さらにbd_inodeを調べます。
------
crash> struct inode 0xf7f10af4
struct inode {
i_hash = {
next = 0x0,
pprev = 0xf54527f4
},
...略 ...
i_op = 0xc046cae0,
i_fop = 0xc046cb40,
i_sb = 0xf7f47200,
i_flock = 0x0,
i_mapping = 0xf7f10ba4,
i_data = {
host = 0xf7f10af4,
page_tree = {
   height = 4,
   gfp_mask = 544,
   rnode = 0xf620be38
},
--------

i_mapping=0xf7f10ba4が入っていますので、さらに進んで
-----
static inline void blk_run_address_space(struct address_space *mapping)
{
      if (mapping)
            blk_run_backing_dev(mapping->backing_dev_info, NULL);
}
------
ということになります。mapping->backing_dev_infoを調べてみます。
-----
crash> struct address_space 0xf7f10ba4
host = 0xf7f10af4,
...
backing_dev_info = 0xf74acec8,
...
-----
このbacking_dev_infoを使うのは、blk_run_backing_dev()です。
-----
static inline void blk_run_backing_dev(struct backing_dev_info *bdi,
                                    struct page *page)
{
      if (bdi && bdi->unplug_io_fn)
            bdi->unplug_io_fn(bdi, page);
}
----
どこまでも地道な作業が進みます...。
----
crash> struct backing_dev_info 0xf74acec8
struct backing_dev_info {
ra_pages = 32,
state = 0,
memory_backed = 0,
congested_fn = 0,
congested_data = 0x0,
unplug_io_fn = 0xc022446f <blk_backing_dev_unplug>,
unplug_io_data = 0xf74acd80
}
-----

ようやくデバイスのリクエストキューの部分まで来ました。ちなみにここで、*pageはNULLです。
------
static void blk_backing_dev_unplug(struct backing_dev_info *bdi,

                                 struct page *page)
{
      request_queue_t *q = bdi->unplug_io_data;

      /*
      * devices don't necessarily have an ->unplug_fn defined
      */
      if (q->unplug_fn)
            q->unplug_fn(q);
}
------

上記関数内の

-----
request_queue_t *q = bdi->unplug_io_data;

-----

これがI/Oリクエストキューであることが判明しました。

----
unplug_io_data = 0xf74acd80

-----

それならば、リクエストキューの中身を確認します。

-----
crash> struct request_queue_t 0xf74acd80
struct request_queue_t No struct type named request_queue_t.
----
エ、エラーでした。
気を取り直して、
-----
$ cd include/linux
$ grep request_queue_t *
blkdev.h:typedef struct request_queue request_queue_t;
-----
ということで、request_queue型が正しいようなので、改めて、
-----
crash> struct request_queue 0xf74acd80
struct request_queue {
queue_head = {
next = 0x0,
prev = 0x0
},
lasstruct request_queue {
queue_head = {
next = 0x0,
prev = 0x0
},
last_merge = 0x0,
elevator = {
t_merge = 0x0,
elevator = {
... 略 ...
request_fn = 0,
back_merge_fn = 0,
front_merge_fn = 0,
merge_requests_fn = 0,
make_request_fn = 0xf883992e,
prep_rq_fn = 0,
unplug_fn = 0xf88396ef,
merge_bvec_fn = 0,
activity_fn = 0,
issue_flush_fn = 0xc026e939 <md_flush_all>,
unplug_timer = {
entry = {
   next = 0x0,
   prev = 0x0
},
expires = 0,
lock = {
   lock = 1,
   magic = 3735899821
},
magic = 1267182958,
function = 0xc0224488 <blk_unplug_timeout>,
data = 4148874624,
base = 0x0
},
unplug_thresh = 4,
unplug_delay = 3,
unplug_work = {
pending = 0,
entry = {
   next = 0xf74ace90,
   prev = 0xf74ace90
},
func = 0xc022447f <blk_unplug_work>,
...以下略。
-------
となっています。
-----
unplug_fn = 0xf88396ef
-----
が設定されているので、
------
      if (q->unplug_fn)
            q->unplug_fn(q);
------
は実行されているはずです。
------
crash> sym 0xf88396ef
f88396ef (t) raid1_unplug
------

これでようやくsync_buffer()したときに、今対象としているbuffer_headに対しては、raid1_unplug()という処理が行われるんだなぁ〜というところまでたどり着きました。

------
static void raid1_unplug(request_queue_t *q)
{
unplug_slaves(q->queuedata);
}
----
q->queuedataが必要みたいなので、再度request_queueの中身に戻って、
----
queuedata = 0xf7f2e400,
----
を得ます。

unplug_slaves()は、各RAIDレベルごとに用意されている関数なので、raid1.cのunplug_slaves()を確認します。

-----

static void unplug_slaves(mddev_t *mddev)
{
      conf_t *conf = mddev_to_conf(mddev);
      int i;
      unsigned long flags;

      spin_lock_irqsave(&conf->device_lock, flags);
      for (i=0; i<mddev->raid_disks; i++) {
            mdk_rdev_t *rdev = conf->mirrors[i].rdev;
            if (rdev && atomic_read(&rdev->nr_pending)) {
                     request_queue_t *r_queue = bdev_get_queue(rdev->bdev);

                     atomic_inc(&rdev->nr_pending);
                     spin_unlock_irqrestore(&conf->device_lock, flags);

                     if (r_queue->unplug_fn)
                              r_queue->unplug_fn(r_queue);

                     spin_lock_irqsave(&conf->device_lock, flags);
                     rdev_dec_pending(rdev, mddev);
            }
      }
      spin_unlock_irqrestore(&conf->device_lock, flags);
}
-------

まず、*confを導くために、mddev_to_conf()を確認してみます。

------
typedef struct r1_private_data_s conf_t;

#define mddev_to_conf(mddev) ((conf_t *) mddev->private)
------

ということなので、

------
crash> struct conf_t 0xf7f2e400
struct: cannot handle "conf_t": try "gdb whatis" or "gdb ptype"

------

そういえば、さきほどconf_tはtypedefされていたので...

-----
crash> struct r1_private_data_s 0xf7f2e400
struct: cannot handle "r1_private_data_s": try "gdb whatis" or "gdb ptype"
------
まだだめです。そういえば、raid1.koをロードしていないので、structが判別できないんですね。

-----
crash> mod
MODULE NAME          SIZE OBJECT FILE
f8825e80 sd_mod       20480 (not loaded) [CONFIG_KALLSYMS]
f883cb00 raid1       19584 (not loaded) [CONFIG_KALLSYMS]
.....

-----

そこで、raid1.koをロードします。

-----

crash> mod -s raid1 raid1.ko
MODULE NAME SIZE OBJECT FILE
f883cb00 raid1 19584 raid1.ko
-----

再度、confを調べます。
-----
crash> struct r1_private_data_s 0xf7f2e400
struct: cannot handle "r1_private_data_s": try "gdb whatis" or "gdb ptype"
-----

やっぱりだめです。

注: これは実はkernel-debuginfoに含まれるraid1.ko.debugをロードすれば問題なくstructコマンドで解析できることに後で気づきました。

とにかく、うまくいかなかったので、

----
crash> rd 0xf7f2e400 100
f7f2e400: f7e5d800 f883ca80 00900001 00000001 ................
f7f2e410: f7e5d880 f7e5d880 00000000 00000000 ................

-----

*mddev = f7e5d800 ということがメモリダンプから分かります。

include/linux/raid/md_k.hから

-----
typedef struct mddev_s mddev_t;
-----

となっているので、

-----
crash> struct mddev_s f7e5d800

struct mddev_s {
private = 0xf7f2e400,
pers = 0xf74a2f80,
unit = 2,
md_minor = 1,

-----

*conf = 0xf7f2e400 ということが分かります。

さらに次のルーチンで、raidのディスクごとの処理をしているので、raid_disksの

数値を探します。

-----
for (i=0; i<mddev->raid_disks; i++) {
-----

すると、
-----
layout = -135931836,
raid_disks = -135931836,
max_disks = 1,
-----

と、異常な数値になっています。

その結果、raid_disksの数値が負のため、各ディスクに対するI/O発行処理のループが実行されず、バッファのステータスが変わらなかったために、ストールが発生したと思われます。

最後は非常にあっさりしたものでしたが、そこまでにたどり着くまでは非常に地道にデータとソースを確認する作業が続くのでした。

dump解析(1) 一の巻

yasuma — 2006-07-18T09:00:00+09:00

本エントリはダンプ解析について知ってもらうために多少編集している部分がありますが、ご了承ください。

ML40でのダンプ解析には、

vmcore(ダンプ本体)
vmlinux(kernel-debuginfoに入っている)
System.map(kernelパッケージに入っている)

が必要です。

ダンプの解析開始は、通常こんな感じで始まります。

-----
# cd /var/crash/10.1.0.111-xxxx/
# crash /boot/System.map-2.6.9-34.21AXsmp /usr/lib/debug/lib/modules/2.6.9-34.21AXsmp/modules/vmlinux vmcore
----

まず何をするかというと、どこでpanicしたのか確認するために、btです。
----
crash> bt
PID: 0    TASK: c0322a80 CPU: 0 COMMAND: "swapper"
#0 [c0393f10] start_disk_dump at f8e0eced
#1 [c0393f2c] die_nmi at c0106bbb
#2 [c0393f44] unknown_nmi_panic_callback at c0117a97
#3 [c0393f9c] do_nmi at c0106cec
#4 [c0393fa4] nmi at c02d536c
EAX: 00000000 EBX: c0393000 ECX: 00000000 EDX: 00000000 EBP: 004ba007
DS: 007b    ESI: 00000000 ES: 007b    EDI: c03cf120
CS: 0060    EIP: c01040e8 ERR: 00000000 EFLAGS: 00000246
#5 [c0393fe0] mwait_idle at c01040e8
#6 [c0393fec] start_kernel at c039478f
#7 [c0393ffc] is386 at c010020c
-----
これを見ると、swaperプロセスなので、idleプロセス中でpanicが発生していることが分かります。

しかも、#4 [c0393fa4] nmi at c02d536c これは、NMIによる割り込みが発生したのがpanicの要因であることも見て取れます。
普通、こういう場合は、マシンのNMIボタンを押すなどして、能動的に取得したdumpファイルであることがほとんどです。こういったパターンでは、マシンがストールして、何も操作を受け付けなくなり、最後の手段としてNMIによるダンプ取得を行うのが普通です。

次にどんなプロセスが動いていたのか調べてみます。
-----
crash> ps

PID PPID CPU TASK ST %MEM    VSZ RSS COMM
>    0    0 0 c0322a80 RU 0.0    0    0 [swapper]
>    0    1 1 f7e110b0 RU 0.0    0    0 [swapper]
>    0    1 2 f7e10b30 RU 0.0    0    0 [swapper]
>    0    1 3 f7e105b0 RU 0.0    0    0 [swapper]
   1    0 0 f7e11630 IN 0.1 3280 632 init
   2    1 0 f7e10030 IN 0.0    0    0 [migration/0]
   3    1 0 f7e256b0 RU 0.0    0    0 [ksoftirqd/0]
   4    1 1 f7e25130 IN 0.0    0    0 [migration/1]
   5    1 1 f7e24bb0 IN 0.0    0    0 [ksoftirqd/1]
   6    1 2 f7e24630 IN 0.0    0    0 [migration/2]
   7    1 2 f7e240b0 IN 0.0    0    0 [ksoftirqd/2]
   8    1 3 f7e99730 IN 0.0    0    0 [migration/3]
   9    1 3 f7e991b0 IN 0.0    0    0 [ksoftirqd/3]
   10    1 0 f7e98c30 IN 0.0    0    0 [events/0]
   11    1 1 f7e986b0 IN 0.0    0    0 [events/1]
... 以下略 ...

------

各プロセスごとに、どのような状況にあるか確認するためには、btにPIDを付けます。

------
crash> bt 11
PID: 11 TASK: f7e986b0 CPU: 1 COMMAND: "events/1"
#0 [f7feef08] schedule at c02d2699
#1 [f7feef6c] worker_thread at c013109f
#2 [f7feefd0] kthread at c01346eb
#3 [f7feeff0] kernel_thread_helper at c01041f3
------

今回、ストールが発生しているということで、ステータスが「 UN」になっているプロセスについて調べた結果、PID 287(kjournald)のプロセスのタスクが__wait_on_buffer()で、バッファがロックされたままで、ロックが
解放されるのを待っている状態でした。

__wait_on_buffer()は、
-----
void __wait_on_buffer(struct buffer_head * bh)
-----
と宣言されているので、buffer_headへのポインタを引数として1つだけ持ちます。

そのため、どこのバッファを待っているのか確認するために、btに-fオプションを付けてみました。

------
crash > bt -f 287
PID: 287 TASK: f760aeb0 CPU: 2 COMMAND: "kjournald"
#0 [f7551d30] schedule at c02d26a5
[RA: c02d2e36 SP: f7551d30 FP: f7551d94 SIZE: 104]
f7551d30: f7551d90 00000046 0000001b 00000000
f7551d40: f7e10b30 f74fc630 00000019 c2025de0
f7551d50: f74fc630 00000000 c202e740 c2025de0
f7551d60: 00000002 0000031e 1fa4329b 00000180
f7551d70: f7e10b30 f760aeb0 f760b01c 00000018
f7551d80: 00000008 c2025de0 c0469b80 f39e765c
f7551d90: f7551d9c c02d2e36
#1 [f7551d94] io_schedule at c02d2e31
[RA: c015c6d4 SP: f7551d98 FP: f7551da0 SIZE: 12]
f7551d98: f54819d4 f4307e00 c015c6d4
#2 [f7551da0] __wait_on_buffer at c015c6cf
[RA: f8e96ac2 SP: f7551da4 FP: f7551dec SIZE: 76]
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
f7551db4: f7551dd4 f7551dd4 c015f391 00006e30
f7551dc4: f54819d4 00000000 f760aeb0 c015c57c
f7551dd4: c0469b88 c0469b88 00000013 f7551de8
f7551de4: f54819d4 00000013 f8e96ac2
#3 [f7551dec] journal_commit_transaction at f8e96abd
[RA: f8e98e8d SP: f7551df0 FP: f7551f68 SIZE: 380]
f7551df0: 00000001 00000000 00000f54 f679e0ac
f7551e00: 00000000 00000000 00000000 f7f2b200
f7551e10: f39e765c 00000dc6 00000000 f760aeb0
f7551e20: c0120a59 f7551e44 f7551e44 f74f21a0
f7551e30: f7e38dc0 00000001 00000000 f760aeb0
f7551e40: c0120a59 f7551e44 f7551e44 00000007
f7551e50: ffffffe3 00003029 f677c5c4 f3d98ba8
f7551e60: f3d987cc f3d98b40 f3d98ee8 f3d985c4
f7551e70: f3d98b0c f3d98d14 f3d98320 f3d98590
f7551e80: f3871180 f3871694 f5f1c938 f5e00b40
f7551e90: f5e00250 f5e00c44 f3c99f84 f54815c4
f7551ea0: f54819d4 f3d98660 f3d98660 f3d98660
f7551eb0: f3d98660 f3d98660 f3d98660 f3d98660
f7551ec0: f3d98660 f3d98660 f3d98660 f3d98660
------

__wait_on_bufferのbh(buffer_head)をきちんと特定するため、もう少し調べると、

-----
void __wait_on_buffer(struct buffer_head * bh)
{
wait_queue_head_t *wqh = bh_waitq_head(bh);
DEFINE_BH_WAIT(wait, bh);

      do {
            prepare_to_wait(wqh, &wait.wait, TASK_UNINTERRUPTIBLE);
            if (buffer_locked(bh)) {
                     sync_buffer(bh);
                     io_schedule();
            }
      } while (buffer_locked(bh));
      finish_wait(wqh, &wait.wait);
}
----------------
というコードになっています。
さらに DEFINE_BH_WAIT(wait, bh);はマクロなので、内容をみると、
------
#define __DEFINE_BH_WAIT(name, b, f)                                  \
      struct bh_wait_queue name = {                                  \
            .bh    = b,                                           \
            .wait = {                                           \
                              .task = current,                   \
                              .flags = f,                         \
                              .func = bh_wake_function,          \
                              .task_list =                         \
                                    LIST_HEAD_INIT(name.wait.task_list),\
                     },                                           \
      }
#define DEFINE_BH_WAIT(name, bh)       __DEFINE_BH_WAIT(name, bh, 0)
-----
このようになっています。

もういちど__wait_on_buffer()のスタックに注目します。

------
#2 [f7551da0] __wait_on_buffer at c015c6cf
[RA: f8e96ac2 SP: f7551da4 FP: f7551dec SIZE: 76]
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
f7551db4: f7551dd4 f7551dd4 c015f391 00006e30
f7551dc4: f54819d4 00000000 f760aeb0 c015c57c
f7551dd4: c0469b88 c0469b88 00000013 f7551de8
f7551de4: f54819d4 00000013 f8e96ac2
-----
この部分の
-----
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
-----
に注目すると、00000000のエントリ、つまり 0がスタックに入れられている箇所があります。

0をスタックに入れている箇所を探すために、disコマンドで__wait_on_buffer()を逆アセンブルします。

-----
crash> dis __wait_on_buffer
0xc015c668 <__wait_on_buffer>: push %esi
0xc015c669 <__wait_on_buffer+1>:       push %ebx
0xc015c66a <__wait_on_buffer+2>:       sub $0x40,%esp
0xc015c66d <__wait_on_buffer+5>:       mov %eax,%ebx
0xc015c66f <__wait_on_buffer+7>:       call 0xc015c53b <bh_waitq_head>
0xc015c674 <__wait_on_buffer+12>:    mov %ebx,(%esp)
0xc015c677 <__wait_on_buffer+15>:    mov %eax,%esi
0xc015c679 <__wait_on_buffer+17>:    mov $0xfffff000,%eax
0xc015c67e <__wait_on_buffer+22>:    movl $0x0,0x4(%esp)
0xc015c686 <__wait_on_buffer+30>:    and %esp,%eax
-----

すると0xc015c67eの命令でスタックに0を入れています。

これは、さきほどの
-----
#define DEFINE_BH_WAIT(name, bh) __DEFINE_BH_WAIT(name, bh, 0)
-----
の0のことだと気づきます。(ここは経験と勘です。)

すると、そのマクロの中に、
-----
.task = current, \
-----
という行があることが分かります。currentというと、このプロセスのtask_structのポインタを表しますので、psの結果、
------
287 1 2 f760aeb0 UN 0.0 0 0 [kjournald]
------
より、currentがf760aeb0であることが分かります。
再度、さきほどのスタックのデータを見るとまさに同じ値が格納されています。
-----
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
-----
さらに、
-----
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
-----
の値を確認するために、次のコマンドを実行します。
-----
crash> sym c015c57c
c015c57c (t) bh_wake_function
----

これはまさに先ほどのマクロ中の
-----
.func = bh_wake_function, \
-----
です。ということは、必然的に、その前にある

-----
.bh = b,

------
が
------
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
-----

であることが分かります。

そこで、このbuffer_head構造体のデータをstructコマンドで確認してみます。
-------
crash> struct buffer_head 0xf54819d4
struct buffer_head {
b_state = 24605,
b_this_page = 0x0,
b_page = 0xc16c71e0,
b_count = {
counter = 2
},
b_size = 4096,
b_blocknr = 3526,
b_data = 0xf638f000 "<A4>\201",
b_bdev = 0xf7f10a80,
b_end_io = 0xf8e96184,
b_private = 0xf39e765c,
b_assoc_buffers = {
next = 0xf5481a00,
prev = 0xf5481a00
}
}
-----

b_end_io = 0xf8e96184 が設定されています。b_end_ioは、IO完了時に呼び出す後処理の関数アドレスなので、調べてみます。

-----

crash > sym 0xf8e96184
f8e96184 (t) journal_end_buffer_io_sync
-----

普通に、ジャーナルの完了処理のようです。
では、このページのロックが解放されない理由を探さなければなりません。

このバッファのページは、b_bdev = 0xf7f10a80 ですので、これが指すブロックデバイスを特定します。

b_bdevは、buffer_head構造体の中で、次のように宣言されています。

------

struct block_device *b_bdev;
------

そこで、ブロックデバイスの情報を確認します。
-------

crash > struct block_device 0xf8e96184
struct block_device {
bd_dev = 9437185,
bd_inode = 0xf7f10af4,
bd_openers = 1,
bd_sem = {
count = {
   counter = 1
},
sleepers = 0,
wait = {
   lock = {
      lock = 1,
      magic = 3735899821
   },
   task_list = {
      next = 0xf7f10a9c,
      prev = 0xf7f10a9c
   }
}
},
bd_mount_sem = {
count = {
   counter = 1
},
sleepers = 0,
wait = {
   lock = {
      lock = 1,
      magic = 3735899821
   },
   task_list = {
      next = 0xf7f10ab4,
      prev = 0xf7f10ab4
   }
}
},
bd_inodes = {
next = 0xf754fc10,
prev = 0xf754fc10
},
bd_holder = 0xf885ac60,
bd_holders = 2,
bd_contains = 0xf7f10a80,
bd_block_size = 4096,
bd_part = 0x0,
bd_part_count = 0,
bd_invalidated = 0,
bd_disk = 0xf7e2a180,
bd_list = {
next = 0xf740db64,
prev = 0xf740d964
},
bd_inode_backing_dev_info = 0x0,
bd_private = 0
}

--------

どのデバイスであるかは、block_device構造体の先頭に

-----

struct block_device {
dev_t bd_dev;
-----

のように宣言されているので確認してみます。

-----

bd_dev = 9437185,

-----

ブロックデバイス dev_tは、include/linux/kdev_t.hで、以下のように、メジャーマイナーが設定されています。
-----
#define MINORBITS 20
#define MINORMASK ((1U << MINORBITS) - 1)

#define MAJOR(dev) ((unsigned int) ((dev) >> MINORBITS))
#define MINOR(dev) ((unsigned int) ((dev) & MINORMASK))
#define MKDEV(ma,mi) (((ma) << MINORBITS) | (mi))
-----

9437185を計算に入れると、Major 9、Minor 1という結果になりました。

これが確認に使ったプログラム。
-------
#include <stdio.h>
#define MINORBITS    20
#define MINORMASK    ((1U << MINORBITS) - 1)
#define MAJOR(dev)    ((unsigned int) ((dev) >> MINORBITS))
#define MINOR(dev)    ((unsigned int) ((dev) & MINORMASK))
#define MKDEV(ma,mi) (((ma) << MINORBITS) | (mi))

int main(int argc, char **argv)
{
printf("MAJOR:%d\n", MAJOR(9437185));
printf("MINOR:%d\n", MINOR(9437185));
printf("%d\n", MKDEV(9,1));
}
---------

これは、/dev/の下でmajor 9、minor 1のデバイスを探すと、/dev/md1を表していました。

-----
$ ls -l /dev/md1
brw-r----- 1 root disk 9, 1 7月 16 02:34 /dev/md1

-----

路地裏 ソース解読研究所

「路地裏ソース解読研究所」ブログ閉鎖について

岡山カーネル勉強会

ファイルシステムに関する情報源

2進数と10進数の区別

岡山カーネル勉強会(詳細)

ダンプを解析する技術と伝える技術

kernel-2.6.17でのspinlockのオーナー情報

ログイン時のサウンド

dump解析(1) 二の巻

dump解析(1) 一の巻

路地裏ソース解読研究所