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

mdbでサクサクとカーネルをデバック - mdb (modular debugger)

こんにちは。

先日、AMD64のマシンでのハング障害について調べなくてはならなかったのですが、mdbの強力な機能のお陰であまり時間もかからず、助かりました。(^-^)V oO (Yokatta---)

そこで今日はmdbの話をちょっとさせて下さいね。

ハング障害っていうのは、案外と困りもの。だって、パニックだったら、"ここで値が壊れていたのでパニック"っていうのは、大抵は分かるでしょ？　（まぁ、どうして値が壊れたの？っていう辺りが実は難しかったりするんですけど、それはちょっとおいて‥）でも、ハングの場合は、どこで（そして、なんで）ハングしてるのぉ？というところから出発しなければいけないんですものね。手間暇がかかるわけです。(~.~;)

でも、mdbには強力な機能があって、どこでハングしているかが簡単に分かります。今日はその方法について、説明しますね。（こういうのは、経験から来るモノですので、貴重な情報ですよぉ。）

ハングした場合は、幾つかケースがあるのですけど、今回はひたすらCPUが走り続ける、端から見ていても暑そうな、そんなケースについて説明しましょう。

(*) タスクがループしているひたすら汗をかいている場合 --- CPUが同じ箇所を永遠に実行し続けてしまう場合です。終了するはずもないので、ハングに見えてしまいますよね。

調査は大抵強制ダンプを採取して行うのですが、この場合はダンプを採取した時に各々のCPUが何を実行していたかをチェックすれば分かります。mdbでは、cpuinfoというコマンドがあって、ダンプが採取された時に各々のCPUで実行されているThreadについて情報を出力してくれます。

まず、ダンプをmdbで見るには、ダンプの番号、０から始まる数字を指定してあげるだけで、unixとvmcoreの双方のデータを読み込みます。例えば、ダンプがunix.0, vmcore.0だとしますよね。そしたら、０という数字を引数で指定してあげるだけです。

% mdb 0 ------- これで、unix.0, vmcore.0を読み込む。

そうすると、色々なメッセージがでてきますが、取りあえずは無視です。(^-^)

mdb: warning: dump is from SunOS 5.10 s10_74l1; dcmds and macros may
not match kernel implementation

Loading modules: [ unix krtld genunix dtrace specfs ufs sd isp sgsbbc
ip sctp wrsm random fcp fctl nca nfs sppp ptm logindmux md wrsmd cpc
fcip ]

そして、この不等号(>)のところでコマンドを打ちましょう。この不等号(>)はコマンドプロンプトなんですね。
コマンドは、コロンを２つつけて書くことになっています。例えば、::dcmdsみたいに。

今回の場合は、cpuinfoを実行することですから、::cpuinfoと打てばいいんですね。で、この時のポイントは、-vオプションをつけてやることです。そうすると、各CPUでの「その時の」threadの状況を出力してくれます。

::cpuinfo -v
 ID ADDR         FLG NRUN BSPL PRI RNRN KRNRN SWITCH THREAD      PROC
  1 00001835ac8  1b    1    0 109   no    no t-0    2a10007fcc0 sched
                  |    |    |

       RUNNING  --+    |    +--   PIL THREAD
         READY         |          10 2a10007fcc0
        EXISTS         |           - 2a10001fcc0 (idle)
        ENABLE         |
                       +--    PRI THREAD      PROC
                              60 2a10165fcc0 sched

 ID ADDR        FLG NRUN BSPL PRI RNRN KRNRN SWITCH THREAD      PROC
  3 30000f22000  1d    1    0  -1   no    no t-7    2a100255cc0 (idle)
                  |    |
       RUNNING  --+    +--    PRI THREAD      PROC
      QUIESCED                60 2a100137cc0 sched
        EXISTS   
        ENABLE   

今回の場合は、次のような状態でした。

 ID ADDR        FLG NRUN BSPL PRI RNRN KRNRN SWITCH THREAD      PROC
  0 fffffffffbc22960  1f    3    0 109   no    no t-5898
fffffe80000b3c80 sched
                  |    |    |
       RUNNING  --+    |    +--   PIL THREAD
         READY         |          10 fffffe80000b3c80  clock interrupt
      QUIESCED         |           4 fffffe80000b9c80 software interrupt
        EXISTS         |           - fffffe8000005c80 (idle)
        ENABLE         |
                       +--    PRI THREAD      PROC
                              99 fffffe80000e9c80 sched
                              60 fffffe80008b2c80 sched
                              60 fffffe800017fc80 sched

実はループしていたのは、割り込みレベル4で入っていた、ソフトウェア割り込みだったんですが、threadのスタックは、findstackコマンドで簡単に見れますので、すぐに原因までたどり着くことができました。

スタックを調べるには、見てみたいthreadアドレスに::findstackを指定してやるだけです。今回の場合は、怪しいthreadはfffffe80000b9c80ですから、これに::findstackを指定してやります。

fffffe80000b9c80::findstack
stack pointer for thread fffffe80000b9c80: fffffe80000b9860
[ fffffe80000b9860 _resume_from_idle+0xde() ]
  fffffe80000b9980 wait_till_seen+0x67()
  fffffe80000b99e0 remove_av+0xab()
  fffffe80000b9a10 rem_avintr+0x52()
  fffffe80000b9a40 pci_disable_intr+0x6e()
  fffffe80000b9b00 pci_intr_ops+0x467()
  fffffe80000b9b40 i_ddi_intr_ops+0xb1()
  fffffe80000b9b80 i_ddi_intr_ops+0xb1()
  fffffe80000b9b90 i_ddi_handle_intr_ops+9()
  fffffe80000b9bc0 ddi_intr_disable+0x52()
  fffffe80000b9bf0 bge_reset+0xc7()
  fffffe80000b9c10 bge_restart+0x1c()
  fffffe80000b9c40 bge_chip_factotum+0xd8()

今回はループしていても、クロック割り込み（レベル10の割り込みthread）が入ってきていましたので、スタックに残っている最後の関数は_resume_from_idle()でしたが、ハングはその前のwait_till_seen()で起きていました。（この関数が、ソフトウェア割り込みで呼び出されることを考慮しておらず、そのために発生したということがこの後すぐに分かりました。）

以前は、mdbのようなデバッカーがなく、adbといったBSD Unixの時代からあるデバッカーを使用していたために、原因判明まで結構な時間がかかったものです。今はmdbがあるから、相当楽になったと思います。^-^

mdbでどのようなコマンドが使えるかは、::dcmdsを実行すると分かります。たくさん出てくるのでびっくりするかも知れませんね。出力された関数のもそっと詳細な情報を知りたいときは、::helpコマンドを使います。

例えば、findstackについてもっと知りたいっていう場合は、::help findstackって叩いてあげます。

::help findstack

NAME
  findstack - find kernel thread stack

SYNOPSIS
  addr ::findstack [-v]

ATTRIBUTES

  Target: kvm
  Module: genunix
  Interface Stability: Unstable

Solaris Operating Systemのいいところは、こういう強力なデバッカーが標準でついてくるところですね。
もちろん、OpenSolaris上でもほとんどすべてのソースが付いてきますので、DTraceやmdbの恩恵を得ることができます。こういう点が、LinuxやNetBSD, FreeBSDに比べて良いところかも知れませんね。開発時のデバックがOpenSolaris上では相当楽になるんじゃないかなって今から期待したいです。(^-^)

それでは良い週末を！

Posted at 03:08午後 5 20, 2005 by eota in opensolaris  |  Comments[0]