路地裏 ソース解読研究所

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

当ブログをご覧の皆様へ

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

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

岡山カーネル勉強会

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をダウンロード

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

みなさんは、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進数の区別

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

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

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

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

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

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に掲載する予定です。

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

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

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

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

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

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

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

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

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

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

先日のダンプ内の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に初期化されていましたが、実際のデッドロックの発生時など、ダンプファイルからデッドロックの原因特定に役立つことは間違いなさそうです。

ログイン時のサウンド

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

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

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

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

dump解析(1) 二の巻

さて、前回、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) 一の巻

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

ML40でのダンプ解析には、

1. vmcore(ダンプ本体)
2. vmlinux(kernel-debuginfoに入っている)
3. 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

-----