メモリダンプから.NETのメモリ状態を探りたい

こんにちは、@mayukiです。

以前、このブログにてダンプ解析入門 - Visual Studioでの可視化によるC#トラブルシューティングというスタックオーバーフローのような問題を調査する方法について触れましたが、今回はダンプを元にメモリ周りの状態を見ていく方法について調べたので少しまとめてみました。

長い時間実行するようなアプリケーション(アプリケーションサーバーなど)ではメモリの使用状況やメモリリークなどを調査したいというケースがたまにやってきます。そんなときにはプロセスのメモリダンプを取得して解析することで問題の原因がわかりそう…そんなシチュエーションで役立つかもしれません。

お品書き

前提

まずダンプを取得する対象のbitness(64bit/32bit)と解析するマシンのbitnessは合わせておきましょう。合致していない場合であっても頑張れば解析できるとは思うのですが今回はそこに関して詳しくは触れません。

特にAny CPUでビルドしていてもPrefer 32-bitが有効な状態でビルドされている場合、64bitマシン上では32bitで起動するので要注意です。

またダンプファイルの取得の仕方に関しては先のエントリーを参照してください。

追記: 今回の開発環境はVisual Studio 2017 (15.4.1) + .NET Framework 4.7 + Windows 10 Version 1709の組み合わせです。バージョンによっては若干手順が異なる、利用できない場合があります。

メモ: 64bit コンピューターで動作している32bit プロセスのダンプをとる

詳しくは触れませんが、もし間違ってPrefer 32-bitが有効なまま起動したといった状況で64bit (x64) コンピューターで動作する32bit (x86)プロセスで動いているもののダンプをとって調べることになった際には次の点に注意してください。

• 32bitプロセスのダンプを取得するときは32bitのタスクマネージャーなどを利用する
  • WinDbg (x86)で開いて、SOSも読み込んだのに SOS does not support the current target architecture. と出るときはこれを疑います
  • タスクマネージャーでみて、対象のプロセスが古いWindowsであればプロセス名に * 32と表示されているか、Windows 10やServer 2016などであれば Platform が 32 bit となっているかどうかを見て、タスクマネージャー自体のbitnessとあっているかどうかを確認します
  • Sysinternalsのprocdump を使うことで気にせずいい感じにとれるそうです
  • 参考: https://blogs.msdn.microsoft.com/tess/2010/09/29/capturing-memory-dumps-for-32-bit-processes-on-an-x64-machine/
• WinDbgでダンプを開くときはWinDbgのbitnessを解析対象プロセスのbitnessに合わせる
  • つまり32bitプロセスをデバッグするにはWinDbg(x86)が必要だということです

ダンプのみどころ

ダンプをとったはいいものの一体何を見ればいいのかを考える必要があります。メモリ周りと言っても単純にメモリの使用状態を見たいのか、メモリリークを調べたいのかで少し違いますが次のようなものをよく見る感じでしょうか。

• メモリ使用量全般(リーク時も含む)を調べる
  • ヒープの使用状況/オブジェクトの数
    • 何が大きく占めているのか、異常に増え続けていそうなものがあるのか?
    • 各ジェネレーションごとのサイズなど
• メモリリークを調べる
  • オブジェクトのルート
    • GCで回収できないのは誰がつかんでいるせいなのか?
  • ファイナライザーの状態
    • ファイナライザースレッドがブロックされていないか
      • ファイナライザースレッドがブロックされているとFinalize待ちが溜まる

もっとも、メモリダンプをとってメモリ周りを調べるようなシチュエーションでは大抵はリークを疑っているケースがほとんどかと思います。

どのツールで解析すれば?

さて、ダンプファイルを無事取得でき、見たいところも何となくわかったとしてどうやって調べていけばよいのか…。前回はVisual Studioを利用しましたが今回はそれに2つ加えて、3つの解析ツールをご紹介します。

• Visual Studio: どこのご家庭にもあるIDE (※ただし Enterprise に限る)
• DebugDiag: お手軽レポーター
• WinDbg: ハードコアデバッガー

これら3つともMicrosoftの提供しているツールで、下に進むにつれ詳細な情報が取れるとふんわりと考えてもらえればよいかと思います。今回WinDbgに関してはコマンドがいろいろあるのでその部分が若干多めな解説です。

サードパーティーのツールなどもありますが今回は標準的なツールのみです(最近はdotMemoryもダンプをインポートできるらしいとか)。

Visual Studioを試してみる

さてまずVisual Studioです。メモリダンプをとった後とりあえず開いてみるならVisual Studioではないでしょうか?開発環境であれば特に追加のインストールも不要ですしお手軽ですね。(※ただし Enterprise に限る)

ここでは以下の単にオブジェクトを作るだけのプログラムでダンプをとってみたものを解析してみます。

namespace ConsoleApp18
{
    class Program
    {
        private static List<A> _values = new List<A>();

        static void Main(string[] args)
        {
            for (var i = 0; i < 100000; i++)
            {
                _values.Add(new A() { ValueB = new B() });
            }
            Console.ReadLine(); // ← ここで止まっているときにダンプをとる
        }
    }

    class A
    {
        public B ValueB { get; set; }
    }
    class B
    {
        public int Value { get; set; }
    }
}

というわけで上記プログラムからとったメモリダンプをVisual Studioでひらくと次のような画面が表示されます。

この画面の右側のActionsの"Debug Managed Memory"を選択するとメモリ状態を表示するモードとなります。

これでオブジェクトがどのぐらいあり、どのぐらいのメモリを使っているのかという情報を一覧表示できます。お手軽ですね

一覧の下には "Paths to Root" と "Referenced Types" という二つのビューがあります。

"Paths to Root" は選択したオブジェクトからルートとなるオブジェクトへのツリー、つまり参照元を表示します(最終的にはGC対象となるルート)。上の図の例では Program._values(static変数) → List<A> → A → B という順でたどれるよということになります。この場合 values しかRootがないので values がなくなればGCが回収可能となりますし、逆を言えばここが残っているということは解放できないということでもあります。

"Referenced Types" は選択したオブジェクトが参照しているオブジェクトへのツリー、つまり参照先を表示します(選択したオブジェクトが依存しているオブジェクト)。上記の図ではList<A>はA[]を持ち、A[]はAを、AはBを参照しているということがわかります。

なお、一覧のObject Typeのカラムでアイコンが表示されるのでクリックすることで個々のオブジェクトを探っていくこともできます。

と、Visual Studioで見れば何となくあれが多いんだなとか、これで開放されてなさそうだなといった情報をつかめる場合が多いでしょう。これだけではわからない、Visual Studioでは開けないなど、もう少し突っ込んだ状態を調べたくなったら他のツールを検討します。

メモ: 以前はVisual StudioにSOS拡張をロードできたのですがここ最近はそのようなことができなくなっています

DebugDiagを試してみる

次はDebugDiagを使ってみましょう。DebugDiagはMicrosoftが提供しているダンプ自動解析ツールです。ダンプファイルを突っ込むとまあまあいい感じにレポートを出してくれるという便利ツールです(それだけではないのですが)。無料です。

インストールして DebugDiag 2 Analysis を起動すると以下のような画面が表示されます。

ここで今回はメモリ関連の解析を行いたいので DotNetMemoryAnalysis にチェックを入れ、Add Data Files でダンプファイルを選択し、Start Analysisで解析を開始します。解析が完了するとレポートがInternet Explorer(!)で開かれます。

レポートには以下のようなものが記録されます。

• ヒープのサイズ等の情報
• メモリを多く使っているオブジェクトの一覧
• ファイナライゼーションキューにあるオブジェクトの一覧
• 怪しそうな項目の警告

あくまでレポートなのでVisual Studioに比べて逆に細かいところは見れないのですが、まとめを出してくれるので大まかに状態の把握をするのには便利ですし、ファイナライゼーションキューの情報なども出せるのはなかなかわるくないのです。

ただこのレポート、MHTML形式なうえに微妙に壊れることがあるのが若干難ありですが読めるのであればあまり気にしないことにしましょう。読めないようなものが出てきた場合には…お疲れさまでした…。また巨大なダンプファイルの解析にはとても時間がかかるので辛抱も必要です(とはいえWinDbgでもかかります)。

おまけ: ハングやクラッシュを調べる

ちなみに解析ルールとしてCrashHangAnalysisというクラッシュやハングを解析するルールもあります。

折角なのでダンプ解析入門 - Visual Studioでの可視化によるC#トラブルシューティングと同じようにスタックオーバーフローを確認してみましょう。

namespace ConsoleApp18
{
    class Program
    {
        static void Main(string[] args)
        {
            HogeHoge(1);
        }
        static void HogeHoge(int s)
        {
            HogeHoge2(s);
        }
        static void HogeHoge2(int s)
        {
            HogeHoge(s);
        }
    }
}

前回のエントリーのコードをx64で実行したところRyuJITは賢いおかげだからなのかStack overflowにならなかったため少し変更しています。これをビルドして実行すると無事死亡です。

その際作られたダンプファイルをDebugDiagに食べさせて、CrashHangAnalysisをかけてみましょう。するとレポートに力強くErrorの文字とProgram.Hogehoge(Int32)でstack overflowという結果が表示されます。

レポートにはスレッドのスタックトレースなども出てくるので一発でダメなのがわかりますね。

このあたり、[それVisual Studioでできるよ]と言われるとそうですねという感じなのですが、GUIでポチポチやって明らかにダメなものを発見できるお手軽解析ツールとして入れて置いておいても良いかなと思います。

まあしかしレポートなどが古めかしいの直したいのでオープンソースにしてほしいぞい…。

WinDbgを試してみる

最後はハードコアなデバッガーWinDbgで解析する方法です。いろいろと面倒な代わりに詳細な情報を得られるのが特徴です。そもそも.NET用のデバッガーではないというあたりから難易度の高さを誇り、最低限の操作だけ覚えていく感じです。これも無料です。

最近Preview版として見た目がよくなったバージョンがリリースされたのですが、本質は変わっていないのでぬるま湯マネージコードマンには相変わらずハードコアです。

インストール

WinDbgのインストールですが、なんとPreview版ではMicrosoftストアからワンポチでインストールできます。おてがるですごい。

ダンプファイルを開いてまずはSOS

WinDbgを起動したらFileメニューから"Open dump file"で.dmpファイルを選択してダンプファイルを開きます。

ダンプファイルを開くと次のような画面になります。中央の "Command" タブの下部にある 0:000> とその横の入力エリアがコマンド入力欄となっていて、WinDbgであれこれ操作するのはここにコマンドを打ち込んで操作を実行していくことになります。

ダンプファイルを開いてもそのままではマネージコードのデバッグはできないのでSOS拡張をロードするところから始まります。SOS拡張をロードするには以下のコマンドを実行してください。

!loadby sos clr

この際、LoadLibraryでライブラリが見つからない的なエラーになる場合がありますが、それはbitnessがあっていない、つまり64bitマシンで32bitのダンプを解析しようとしてる場合に出てきます。 読み込むDLLを変えれば対応できるはずですが前提にも書いた通りターゲットアプリケーションを64bitにするほうが手っ取り早いのでそうしましょう。64bitコンピューターで動作する32bitプロセスのダンプを読み込みたいしたいときの注意は最初に書いた通りです。

雑基礎知識

実際のWinDbgを使うと.NET CLRの中身が透けて見えるといっても過言ではない代わりに、それ相応の用語が出てくるので何となく押さえておくとはかどります。

• ヒープ: なんかオブジェクトがあるところ。スタックじゃないやつ
• EEClass: 要するに型。コールドな情報
• MT/MethodTable: 要するに型。ホットな情報
  • 何らかコマンド実行してMTという項目に数字が出てきたらそれはMethodTableのアドレス
  • オブジェクトにはMTへの参照が書かれている
  • MethodTableはEEClassを参照している(MTからEEClassへの参照はセット)
    • 例えばEEClassはジェネリクスのオープン型、MethodTableはクローズ型みたいな
• mdToken: メタデータのトークン(ハンドル)。これを元にクラスのリファレンスが解決される
  • 普通は用事ない
• EEほにゃらら: Execution Engine
• ファイナライゼーションキュー: Finalizer(つまりC#のデストラクタ)を持っていてファイナライザーを呼び出す前のオブジェクトのキュー
• F-reachable キュー: Finalizerの呼び出しを待っているオブジェクトのキュー(一度死んだやつ)

…とはいえ MT(MethodTable) だけ覚えていれば大体なんとかなります(とは。

WinDbgでの解析のやっていきかた

では実際にWinDbgを利用してメモリの状態を調べてみましょう。

メモリリークの原因を突き止める場合、一体何が多く残っているのか、何が理由で残っているのかといったことを探るのが定石です。その調査として出来そうな手順は以下のような感じでしょうか。

1. オブジェクトの統計情報を出力する
2. 怪しそうな型を見つける
   • 例えば数が想定外に多いとか、GCに回収されていることを期待しているにもかかわらず残っているとか…
3. 型から生きているオブジェクトの一覧を出力する
4. オブジェクトからGCのルートとなるオブジェクトを探す
5. 残っているのが正しいかどうかはアプリ次第…
   • 正しければまたやり直し or 別なオブジェクトを疑う
   • 正しくなければ参照を切るなどを考える

実際のところこれだけの情報であればVisual Studioで見るのと大差なくめんどくさいだけといった感じなのですが、コマンドに慣れる意味でも駆使して見てまわってみましょう。ここではVisual Studioでの解析で利用したダンプを利用します。

オブジェクトの統計情報を出力する & 怪しそうな型を見つける

まずは「オブジェクトの統計情報を出力する」です。 !DumpHeap -stat コマンドを使うと、ヒープにあるオブジェクトを型別で数とサイズを調べた結果を少ないほうから並べて出力してくれます。

0:000> !DumpHeap -stat
Statistics:
              MT    Count    TotalSize Class Name
(...✂...snip...✂...)
00007ffc9b5f7070        6        35304 System.Object[]
000001e5823ac0d0       31       132956      Free
00007ffc3e0f6310        5      1966200 ConsoleApp18.A[]
00007ffc3e0f64c8   100000      2400000 ConsoleApp18.B
00007ffc3e0f5af8   100000      2400000 ConsoleApp18.A
Total 200321 objects

一覧を見て怪しそうな型を見つけます。この例だとなんだかCountがやたら多い型 A と B があって怪しそうなのがわかります。

型から生きているオブジェクトの一覧を出力する

次に生きている(参照の残っている)オブジェクトを見繕うために A という型のオブジェクトの一覧を出力します。

!DumpHeap -live -mt <MT addr> というコマンドを利用することで指定した型の生きているオブジェクトの一覧を出力できます。<MT addr> には先ほどの DumpHeap 結果のMT列の値を指定します。先の例では 00007ffc3e0f5af8 となります。

0:000> !DumpHeap -live -mt 00007ffc3e0f5af8
         Address               MT     Size
000001e583e12eb0 00007ffc3e0f5af8       24     
000001e583e12f18 00007ffc3e0f5af8       24     
(...✂...snip...✂...) 
000001e5842c6d68 00007ffc3e0f5af8       24     
000001e5842c6d98 00007ffc3e0f5af8       24     

Statistics:
              MT    Count    TotalSize Class Name
00007ffc3e0f5af8   100000      2400000 ConsoleApp18.A
Total 100000 objects

これで型 Aのオブジェクトのアドレス一覧を得ることができました。

オブジェクトからGCのルートとなるオブジェクトを探す

個々のオブジェクトを見つけることができたら次はそのオブジェクトがどこから参照されているのかを調べます。

オブジェクトのアドレスからルートへの参照を調べるには !GCRoot コマンドを利用します。このコマンドに先ほどの一覧のAddressを渡せばそのオブジェクトの参照元を調べて出力してくれます。

0:000> !GCRoot 000001e583e12eb0
HandleTable:
    000001e5823817d8 (pinned handle)
    -> 000001e593e15a08 System.Object[]
    -> 000001e583e12e70 System.Collections.Generic.List`1[[ConsoleApp18.A, ConsoleApp18]]
    -> 000001e593ef9aa8 ConsoleApp18.A[]
    -> 000001e583e12eb0 ConsoleApp18.A

Found 1 unique roots (run '!GCRoot -all' to see all roots).

この結果では 000001e583e12eb0(A)からのルートへの参照は A[]→List<A>→object[]→pinned handleとなっています。

Visual Studioの表示と比べると object[]→pinned handle という部分が見えていて、これはエントリポイントがなんやかんやで普段見えない何かなのであろうということが想像できます(ちょっと例が悪かったですね)。

もしメソッドの途中のローカル変数などに保持されている場合には以下のような出力になります。

Thread 2e4c4:
    000000d7b20fec20 00007ffc3e2004b7 ConsoleApp18.Program.Main(System.String[]) [c:\Projects\ConsoleApp18\ConsoleApp18\Program.cs @ 21]
        rsi: 
            ->  00000255e4dc2e70 ConsoleApp18.A

WinDbgコマンドいろいろ

WinDbgというかSOS拡張のコマンドはたくさんあるのでメモリ周りでよく使いそうなものをいくつかまとめておきます。

メモ: トラブルシューティング

• 初回コマンドを実行時に c0000005 Exception in C:\Windows\Microsoft.NET\Framework64\v4.0.30319\sos.dumpheap debugger extension. PC: 00007ffaeab47c11 VA: 0000000000000000 R/W: 0 Parameter: ffffd586`ff42f824 というようなエラーが表示される
  • 初回はエラーが出るものの、再度実行すると何もなかったかのように動くようになります。もしかしたら何か組み合わせがあっていないとかかもしれません(ちゃんと調べていない…)

ヒープのオブジェクト統計情報を取得する: !DumpHeap -stat

ヒープの使用状況、つまり型ごとのオブジェクトの数とその総サイズを取得します。

0:000> !DumpHeap -stat
Statistics:
              MT    Count    TotalSize Class Name
00007ffb11b4bfb8        1           24 System.Collections.Generic.ObjectEqualityComparer`1[[System.Type, mscorlib]]
00007ffb11b4b468        1           24 System.Collections.Generic.GenericEqualityComparer`1[[System.String, mscorlib]]
00007ffb11b49428        1           24 System.Int32
00007ffab4266518        1           24 ConsoleApp15.B
(略)
00007ffb11b469f8      182         7744 System.String
00007ffab4265c50        2        16048 ConsoleApp15.G[]
00007ffab4265bc0     2381       228576 ConsoleApp15.G
00007ffb11b47070        7       355288 System.Object[]
000001c1c47fdf60     2180       498596      Free
00007ffab4265fa0    23814      2286144 ConsoleApp15.F
00007ffab4266120   238141     22861536 ConsoleApp15.E
00007ffab42663a0  2381419    419129744 ConsoleApp15.D
00007ffb11b4bd38     4003   2228320842 System.Byte[]
Total 2652268 objects

ヒープの状況を取得する: !HeapStat or !EEHeap -gc

!HeapStatでは現在のヒープ領域とその中の世代別の使用量、空き容量を取得できます。

0:000> !HeapStat
Heap             Gen0         Gen1         Gen2          LOH
Heap0        26680120     12978040     29711672    253804240
Heap1        24312736     11994384     36392760    262158024
Heap2        30028920     16513736     31330472    269498448
Heap3        28022536     16091536     28290896    269818560
Heap4        24296528     18617496     28643072    250623072
Heap5        27216048     12314440     32227312    262158024
Heap6        25352648     12314264     33517448    260060760
Heap7        24502504     12050624     32706112    269498448
Total       210412040    112874520    252819744   2097619576

Free space:                                                 Percentage
Heap0            3496           72         2792         7896SOH:  0% LOH:  0%
Heap1            2064           72         5824         8024SOH:  0% LOH:  0%
Heap2            2344           72       398856         8248SOH:  0% LOH:  0%
Heap3            2296           72        10952         8312SOH:  0% LOH:  0%
Heap4             504           72         1016         7672SOH:  0% LOH:  0%
Heap5             560           72         2128         8024SOH:  0% LOH:  0%
Heap6             344           72          576         7960SOH:  0% LOH:  0%
Heap7             712           48         3368         8248SOH:  0% LOH:  0%
Total           12320          552       425512        64384

FreeにあるPercentageカラムがくっついていて読みにくいですが SOH が Small Object Heap、LOHが Large Object Heap の使用割合です。

!EEHeap -gc コマンドでは各ヒープのサイズとアドレス、ジェネレーション別のアドレスを確認できます。

0:000> !EEHeap -gc
Number of GC Heaps: 8
------------------------------
Heap 0 (000001c1c4854600)
generation 0 starts at 0x000001c1c8c474b0
generation 1 starts at 0x000001c1c7fe6d38
generation 2 starts at 0x000001c1c6391000
ephemeral segment allocation context: none
         segment             begin         allocated              size
000001c1c6390000  000001c1c6391000  000001c1ca5b8fe8  0x4227fe8(69369832)
Large object heap starts at 0x000001c5c6391000
         segment             begin         allocated              size
000001c5c6390000  000001c5c6391000  000001c5d559ced0  0xf20bed0(253804240)
Heap Size:               Size: 0x13433eb8 (323174072) bytes.
------------------------------
Heap 1 (000001c1c487db90)
generation 0 starts at 0x000001c2491b6448
generation 1 starts at 0x000001c248645f38
generation 2 starts at 0x000001c246391000
ephemeral segment allocation context: none
         segment             begin         allocated              size
000001c246390000  000001c246391000  000001c24a8e5fe8  0x4554fe8(72699880)
Large object heap starts at 0x000001c5d6391000
         segment             begin         allocated              size
000001c5d6390000  000001c5d6391000  000001c5e5d946c8  0xfa036c8(262158024)
Heap Size:               Size: 0x13f586b0 (334857904) bytes.
------------------------------
Heap 2 (000001c1c48a74a0)
generation 0 starts at 0x000001c2c9131b70
generation 1 starts at 0x000001c2c81720a8
generation 2 starts at 0x000001c2c6391000
ephemeral segment allocation context: none
         segment             begin         allocated              size
000001c2c6390000  000001c2c6391000  000001c2cadd4fe8  0x4a43fe8(77873128)
Large object heap starts at 0x000001c5e6391000
         segment             begin         allocated              size
000001c5e6390000  000001c5e6391000  000001c5f62947e0  0xff037e0(267401184)
000001c655240000  000001c655241000  000001c655441070  0x200070(2097264)
Heap Size:               Size: 0x14b47838 (347371576) bytes.
------------------------------
(✂snip✂)
------------------------------
GC Heap Size:            Size: 0x9f5dd1b8 (2673725880) bytes.

ファイナライゼーションキューの情報を取得する: !FinalizeQueue

ファイナライゼーションキューとF-reachable キューの中身を確認できます。

ファイナライゼーションキューはFinalizer(つまりC#のデストラクタ)を持っているオブジェクトのキュー、F-reachable キューはFinalizerの呼び出しを待っているオブジェクトのキューです。それらのキューの状態を各ヒープ領域ごとに取得できます。

なおFinalize可能なオブジェクトというのはC#でデストラクタを実装しているクラスのオブジェクトのことで、参照がなくなるとファイナライゼーションキューからF-reachable Queueに移動してファイナライザーによって処理されます。

0:000> !FinalizeQueue
SyncBlocks to be cleaned up: 0
Free-Threaded Interfaces to be released: 0
MTA Interfaces to be released: 0
STA Interfaces to be released: 0
----------------------------------
------------------------------
Heap 0
generation 0 has 108834 finalizable objects (000001c652f54ba8->000001c6530294b8)
generation 1 has 0 finalizable objects (000001c652f54ba8->000001c652f54ba8)
generation 2 has 100717 finalizable objects (000001c652e90040->000001c652f54ba8)
Ready for finalization 0 objects (000001c6530294b8->000001c6530294b8)
------------------------------
Heap 1
generation 0 has 119727 finalizable objects (000001c6545021c8->000001c6545ebf40)
generation 1 has 0 finalizable objects (000001c6545021c8->000001c6545021c8)
generation 2 has 131121 finalizable objects (000001c654402040->000001c6545021c8)
Ready for finalization 0 objects (000001c6545ebf40->000001c6545ebf40)
------------------------------
Heap 2
generation 0 has 153746 finalizable objects (000001c6547c8048->000001c6548f44d8)
generation 1 has 0 finalizable objects (000001c6547c8048->000001c6547c8048)
generation 2 has 120833 finalizable objects (000001c6546dc040->000001c6547c8048)
Ready for finalization 0 objects (000001c6548f44d8->000001c6548f44d8)
------------------------------
(✂snip✂)
              MT    Count    TotalSize Class Name
00007ffab4266518        1           24 ConsoleApp15.B
00007ffb11b81960        1           32 Microsoft.Win32.SafeHandles.SafeFileMappingHandle
00007ffb11b818d0        1           32 Microsoft.Win32.SafeHandles.SafeViewOfFileHandle
00007ffb11b4c308        1           32 Microsoft.Win32.SafeHandles.SafePEFileHandle
00007ffb11b4d5a8        1           64 System.Threading.ReaderWriterLock
00007ffb11b4a318        2           64 Microsoft.Win32.SafeHandles.SafeFileHandle
00007ffb11b47e50        2          192 System.Threading.Thread
00007ffab4265bc0     2000       192000 ConsoleApp15.G
00007ffab4265fa0    20009      1920864 ConsoleApp15.F
00007ffab4266120   200096     19209216 ConsoleApp15.E
00007ffab42663a0  2000964    352169664 ConsoleApp15.D
Total 2223078 objects

出力の読み方

各ヒープ領域ごとに情報が出力され、最後に統計が出力されます。

• Ready for finalization
  • ファイナライザーによる実行を待っているオブジェクトの数
    • この値が異常に多い場合にはファイナライザースレッドが何らかの理由でブロックして止まっている可能性があります
    • See: ファイナライザーでのブロックを探すには
• generation N has <Number> finalizable objects (<from addr>-><to addr>)
  • 各ヒープのジェネレーション NにあるFinalizeメソッドを持つ(デストラクタを持つ)オブジェクトの数
    • このオブジェクトが必要なくなった時点でF-reachable キューにまわされます。ただし、ここにある=参照されていないという意味ではないことに注意が必要です
    • <from addr>, <to addr> はオブジェクトのポインタが含まれている領域のアドレスです(=ヒープの範囲ではない)
      • ポインタの一覧は dd で見れます
        • dd 000001c653df0ab0 000001c653df2c18-8
        • x86は<from addr> <to addr>-4、 x64なら <from addr> <to addr>-8
• Statistics for all finalizable objects (including all objects ready for finalization):
  • Finalizeメソッドを持つすべてのオブジェクトの種類と数とサイズです

MethodTable(型)から生きているオブジェクトの一覧を取得する: !DumpHeap -live -mt <MT addr>

MethodTableのアドレスを元に現在どこからか参照があるであろう(GCに回収されない)アドレスの一覧を表示します。

以下の例ではMT 00007ffab4265bc0 つまり ConsoleApp15.Gのオブジェクト一覧を出力しています。

0:000> !DumpHeap -live -mt 00007ffab4265bc0
         Address               MT     Size
000001c1c6fbccf8 00007ffab4265bc0       96     
000001c1c6fea618 00007ffab4265bc0       96     
000001c1c7017f38 00007ffab4265bc0       96     
000001c1c7045858 00007ffab4265bc0       96     
000001c1c7073178 00007ffab4265bc0       96     
(略)
000001c54820b9c0 00007ffab4265bc0       96     
000001c5482392e0 00007ffab4265bc0       96     
000001c548266c00 00007ffab4265bc0       96     
000001c548294520 00007ffab4265bc0       96     

Statistics:
              MT    Count    TotalSize Class Name
00007ffab4265bc0     1000        96000 ConsoleApp15.G
Total 1000 objects

この結果から1000オブジェクトが生きていることがわかります。

MethodTable(型)から死んでいるオブジェクトの一覧を取得する: !DumpHeap -dead -mt <MT addr>

MethodTableのアドレスを元に現在参照されていない(=次回のFull GCで回収される)オブジェクトのアドレスの一覧を表示します。

0:000> !DumpHeap -dead -mt 00007ffab4265bc0
         Address               MT     Size
000001c1c7fd5eb8 00007ffab4265bc0       96     
000001c1c80037f0 00007ffab4265bc0       96     
000001c1c8031110 00007ffab4265bc0       96     
000001c1c805ea30 00007ffab4265bc0       96     
000001c1c808c350 00007ffab4265bc0       96     
(略)
000001c54a4e0998 00007ffab4265bc0       96     
000001c54a50e2b8 00007ffab4265bc0       96     
000001c54a53bbd8 00007ffab4265bc0       96     
000001c54a5694f8 00007ffab4265bc0       96     
000001c54a596e18 00007ffab4265bc0       96     

Statistics:
              MT    Count    TotalSize Class Name
00007ffab4265bc0     1381       132576 ConsoleApp15.G
Total 1381 objects

オブジェクトの参照元を探す: !GCRoot <obj addr>

指定したオブジェクトの参照元を出力します。

例えば先ほどの生きているオブジェクトのアドレスの 000001c1c6fbccf8 に対して実行すると以下のような結果が得られます。

0:000> !GCRoot 000001c1c6fbccf8 
Thread 1f058:
*** WARNING: Unable to verify checksum for ConsoleApp15.exe
    0000000470fbeba0 00007ffab437098e ConsoleApp15.Program.Main(System.String[]) [C:\Projects\ConsoleApp15\ConsoleApp15\Program.cs @ 89]
        rdi: 
            ->  000001c2c6db1ff0 ConsoleApp15.G[]
            ->  000001c1c6fbccf8 ConsoleApp15.G

Found 1 unique roots (run '!GCRoot -all' to see all roots).

この結果からオブジェクト 000001c1c6fbccf8 のルートには オブジェクト 0000000470fbeba0 があることがわかります。

一方ですでに参照のなくなったオブジェクトのアドレス 000001c1c7fd5eb8 に対して実行するとルートとなるものがないことがわかります。

0:000> !GCRoot 000001c1c7fd5eb8 
Found 0 unique roots (run '!GCRoot -all' to see all roots).

場合によってはこれからファイナライザーが実行するぞいっとなっているとFinalizerQueueから参照されていることがあります。

0:000> !GCRoot 000001c54a596e18 
Finalizer Queue:
    000001c54a596e18
    -> 000001c54a596e18 ConsoleApp15.G

Warning: These roots are from finalizable objects that are not yet ready for finalization.
This is to handle the case where objects re-register themselves for finalization.
These roots may be false positives.
Found 1 unique roots (run '!GCRoot -all' to see all roots).

型情報を出力する: !DumpMT <MT addr> or !DumpMT -md <MT addr>

MethodTableのアドレスを指定して情報を出力します。-md オプションを付けて呼び出すとメソッド(MethodDescriptor)の一覧が出力されます。

0:000> !DumpMT -md 00007ffb11b49428 
EEClass:         00007ffb11561b80
Module:          00007ffb114b1000
Name:            System.Int32
mdToken:         00000000020000fb
File:            C:\WINDOWS\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
BaseSize:        0x18
ComponentSize:   0x0
Slots in VTable: 56
Number of IFaces in IFaceMap: 5
--------------------------------------
MethodDesc Table
           Entry       MethodDesc    JIT Name
00007ffb118ed018 00007ffb115988b0   NONE System.Int32.ToString()
00007ffb118ed000 00007ffb11598868   NONE System.Int32.Equals(System.Object)
00007ffb118ed028 00007ffb11598898   NONE System.Int32.GetHashCode()
00007ffb1195ce50 00007ffb114b7580 PreJIT System.Object.Finalize()
00007ffb118ecff8 00007ffb11598838   NONE System.Int32.CompareTo(System.Object)
00007ffb118ecff0 00007ffb11598850   NONE System.Int32.CompareTo(Int32)
00007ffb11922858 00007ffb11598880   NONE System.Int32.Equals(Int32)
00007ffb11922838 00007ffb115988d8   NONE System.Int32.ToString(System.IFormatProvider)
00007ffb118ed010 00007ffb115988f0   NONE System.Int32.ToString(System.String, System.IFormatProvider)
00007ffb118ed020 00007ffb11598968   NONE System.Int32.GetTypeCode()
00007ffb11922878 00007ffb11598980   NONE System.Int32.System.IConvertible.ToBoolean(System.IFormatProvider)
00007ffb11922848 00007ffb11598998   NONE System.Int32.System.IConvertible.ToChar(System.IFormatProvider)
00007ffb11922810 00007ffb115989b0   NONE System.Int32.System.IConvertible.ToSByte(System.IFormatProvider)
00007ffb11922818 00007ffb115989c8   NONE System.Int32.System.IConvertible.ToByte(System.IFormatProvider)
00007ffb11922868 00007ffb115989e0   NONE System.Int32.System.IConvertible.ToInt16(System.IFormatProvider)
00007ffb11922820 00007ffb115989f8   NONE System.Int32.System.IConvertible.ToUInt16(System.IFormatProvider)
00007ffb118ed030 00007ffb11598a10   NONE System.Int32.System.IConvertible.ToInt32(System.IFormatProvider)
(略)

型情報を出力する: !DumpClass <EEClass addr>

EEClassのアドレスを指定して情報を出力します。

0:000> !DumpClass 00007ffb114b18c0
Class Name:      System.String
mdToken:         0000000002000073
File:            C:\WINDOWS\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Parent Class:    00007ffb114b1968
Module:          00007ffb114b1000
Method Table:    00007ffb11b469f8
Vtable Slots:    1b
Total Method Slots:  1d
Class Attributes:    102101  
Transparency:        Transparent
NumInstanceFields:   2
NumStaticFields:     1
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ffb11b49428  400026f        8         System.Int32  1 instance           m_stringLength
00007ffb11b47bb0  4000270        c          System.Char  1 instance           m_firstChar
00007ffb11b469f8  4000274       90        System.String  0   shared           static Empty

ファイナライザースレッドがブロック状態かどうかを調べる

ファイナライザースレッドがブロックした状態になると当然ですがF-reachable queueが一向に減らない状態となり、回収されずにたまっていく一方となります。ではファイナライザースレッドがブロックしているかどうかを調べるにはどうするかというお話です。

まず は !Threads コマンドでファイナライザースレッドを特定します。

0:000> !Threads
ThreadCount:      11
UnstartedThread:  0
BackgroundThread: 9
PendingThread:    0
DeadThread:       0
Hosted Runtime:   no
                                                                                                        Lock  
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
   0    1 1f058 000001c1c484ea70    2a020 Preemptive  000001C4CA773470:000001C4CA773FD0 000001c1c4824720 1     MTA 
  13    2 50754 000001c1c62dbd60    2b220 Preemptive  0000000000000000:0000000000000000 000001c1c4824720 0     MTA (Finalizer) 
  15    3 5378 000001c651bd8970    2b020 Preemptive  0000000000000000:0000000000000000 000001c1c4824720 0     MTA 
  16    4 1af00 000001c651bdb5f0    21220 Preemptive  0000000000000000:0000000000000000 000001c1c4824720 0     Ukn 
  17    5 424b0 000001c651bdcc50    21220 Preemptive  0000000000000000:0000000000000000 000001c1c4824720 0     Ukn 
  18    6 4c5c0 000001c651bde2b0    21220 Preemptive  0000000000000000:0000000000000000 000001c1c4824720 0     Ukn 
  19    7 24d80 000001c651bdf910    21220 Preemptive  0000000000000000:0000000000000000 000001c1c4824720 0     Ukn 
  20    8 42834 000001c651be0f70    21220 Preemptive  0000000000000000:0000000000000000 000001c1c4824720 0     Ukn 
  21    9 496cc 000001c651bebe50    21220 Preemptive  0000000000000000:0000000000000000 000001c1c4824720 0     Ukn 
  22   10 1d224 000001c651becd10    21220 Preemptive  0000000000000000:0000000000000000 000001c1c4824720 0     Ukn 
  23   11 18248 000001c651bee3e0    21220 Preemptive  0000000000000000:0000000000000000 000001c1c4824720 0     Ukn 

このリストでは2番目にFinalizerと書いてあるのでこれがファイナライザースレッドです。なおスレッドは ~* でも一覧できます(!ThreadsはCLRが知っている範囲の出力になります)。対象となるファイナライザースレッドが見つかったら先頭のIDを確認します。ここでは 13 となっていることがわかります。

スレッドを特定出来たら次にそのスレッドのスタックを見てみましょう。~[ID]k を実行するとネイティブスタックを確認できます。

0:013> ~13k
 # Child-SP          RetAddr           Call Site
00 00000004`71aff518 00007ffb`1f10a966 ntdll!NtWaitForMultipleObjects+0x14
01 00000004`71aff520 00007ffb`13b21b1e KERNELBASE!WaitForMultipleObjectsEx+0x106
02 00000004`71aff820 00007ffb`139def64 clr!FinalizerThread::WaitForFinalizerEvent+0xb6
03 00000004`71aff860 00007ffb`13966751 clr!FinalizerThread::FinalizerThreadWorker+0x54
04 00000004`71aff8a0 00007ffb`139666cc clr!ManagedThreadBase_DispatchInner+0x39
05 00000004`71aff8e0 00007ffb`1396660a clr!ManagedThreadBase_DispatchMiddle+0x6c
06 00000004`71aff9e0 00007ffb`13a628ba clr!ManagedThreadBase_DispatchOuter+0x75
07 00000004`71affa70 00007ffb`13b2222f clr!FinalizerThread::FinalizerThreadStart+0x10a
08 00000004`71affb10 00007ffb`1f711fe4 clr!Thread::intermediateThreadProc+0x86
09 00000004`71affbd0 00007ffb`2227ef91 kernel32!BaseThreadInitThunk+0x14
0a 00000004`71affc00 00000000`00000000 ntdll!RtlUserThreadStart+0x21

正常な場合にはこのようなスタック状態になるかと思います。WaitForFinalizerEventで次の呼び出しシグナルを待っているような感じでしょうか。

• See: ほぼ似た実装であることが期待できるCoreCLRでもそんな感じなっている

次にマネージコード上で無限ループに陥った場合のスタックです。

0:000> ~13k
 # Child-SP          RetAddr           Call Site
00 0000001e`a677f038 00007ffb`1f108dba ntdll!NtDelayExecution+0x14
01 0000001e`a677f040 00007ffb`13965263 KERNELBASE!SleepEx+0x9a
02 0000001e`a677f0e0 00007ffb`139c4dc0 clr!EESleepEx+0x33
03 0000001e`a677f110 00007ffb`139c4c9d clr!Thread::UserSleep+0xa5
04 0000001e`a677f170 00007ffb`1196d32a clr!ThreadNative::Sleep+0xad
05 0000001e`a677f2d0 00007ffa`b434142e mscorlib_ni+0x4bd32a
06 0000001e`a677f300 00007ffb`13965976 0x00007ffa`b434142e
07 0000001e`a677f330 00007ffb`139dfde1 clr!FastCallFinalizeWorker+0x6
08 0000001e`a677f360 00007ffb`139dfd69 clr!FastCallFinalize+0x55
09 0000001e`a677f3b0 00007ffb`139dfc9a clr!MethodTable::CallFinalizer+0xb5
0a 0000001e`a677f400 00007ffb`139dfb55 clr!CallFinalizer+0x5e
0b 0000001e`a677f440 00007ffb`139dee94 clr!FinalizerThread::DoOneFinalization+0x95
0c 0000001e`a677f520 00007ffb`139defcb clr!FinalizerThread::FinalizeAllObjects+0xbf
0d 0000001e`a677f560 00007ffb`13966751 clr!FinalizerThread::FinalizerThreadWorker+0xbb
0e 0000001e`a677f5a0 00007ffb`139666cc clr!ManagedThreadBase_DispatchInner+0x39
0f 0000001e`a677f5e0 00007ffb`1396660a clr!ManagedThreadBase_DispatchMiddle+0x6c
10 0000001e`a677f6e0 00007ffb`13a628ba clr!ManagedThreadBase_DispatchOuter+0x75
11 0000001e`a677f770 00007ffb`13b2222f clr!FinalizerThread::FinalizerThreadStart+0x10a
12 0000001e`a677f810 00007ffb`1f711fe4 clr!Thread::intermediateThreadProc+0x86
13 0000001e`a677f8d0 00007ffb`2227ef91 kernel32!BaseThreadInitThunk+0x14
14 0000001e`a677f900 00000000`00000000 ntdll!RtlUserThreadStart+0x21

FinalizeAllObjects や CallFinalizer という文字列が見え、何やら処理中であることがわかります。

このようにマネージコード実行中であるスレッドに対しては ~[ID]e!clrstack を実行するとCLR上のスタックを確認できます。

0:000> ~13e!clrstack
OS Thread Id: 0x8760 (13)
        Child SP               IP Call Site
0000001ea677f1d8 00007ffb222b04c4 [HelperMethodFrame: 0000001ea677f1d8] System.Threading.Thread.SleepInternal(Int32)
0000001ea677f2d0 00007ffb1196d32a System.Threading.Thread.Sleep(Int32)
0000001ea677f300 00007ffab434142e *** WARNING: Unable to verify checksum for ConsoleApp15.exe
ConsoleApp15.G.Finalize() [C:\\Projects\ConsoleApp15\ConsoleApp15\Program.cs @ 202]
0000001ea677f728 00007ffb13965976 [DebuggerU2MCatchHandlerFrame: 0000001ea677f728] 

スタックから ConsoleApp15.G.Finalize を実行中っぽいことがわかり、ファイナライザーがブロックされている可能性を疑えます(タイミングによっては単に実行中なだけかもしれませんが)。

また他にも同期ロックによるデッドロックなどがある場合にも引っかかります(!SyncBlkコマンドや!DumpHeap -thinlockなどがつかえそう)。

Appendix

WinDbgでもっと簡単に詳しく

WinDbgとSOS拡張でいろいろ見れて便利!と思いきや、静的なフィールドの中身などをカジュアルに見ることはできません。そこでSOSEXというWinDbgの拡張を公開している方がいらっしゃるのでこれをありがたく使わせてもらいます。

.load C:\Path\To\sosex.dll

このSOSEXを使うと以下のようなSOS拡張を強力にしたようなコマンドを使えるようになります。

• !mk: マネージ、アンマネージが混在したスタックトレースを表示
• !finq: ファイナライゼーションキュー (Finalizerを持つオブジェクトのキュー)を表示
• !frq: F-reachable キュー (Finalize呼び出しまちキュー)を表示
• !mdt: 指定した型やオブジェクトのフィールドを表示(万能)
• !mlocks: ロックの一覧
• !strings: 文字列のダンプ

例えば !mdt を使えば指定した型の静的なフィールドの一覧を表示できます。

0:000> !mdt ConsoleApp18.Program
ConsoleApp18.Program
    [s]_values: System.Collections.Generic.List<ConsoleApp18.A>
        AppDomain 'ConsoleApp18.exe' (000001e5823c30c0): 000001e583e12e70[System.Collections.Generic.List`1[[ConsoleApp18.A, ConsoleApp18]]]

他にもあらかじめインデックスを作っておくことで走査を爆速にするとか強い機能があるので使いこなせるとよさそうです(最近知ったのでほとんど使ってなかったのです…)。

ファイナライザーの実行を.NETアプリケーションコードから知りたい

ファイナライザーの実行タイミングを.NETアプリケーションコードから知りたいということもあるかもしれません。そんな時は GC.RegisterForFullGCNotification と GC.WaitForFullGCApproach、 GC.WaitForFullGCComplete を組み合わせることで検出可能です。

ただしこの手法が有効なのはGCの設定が <gcConcurrent enabled="false" /> の場合に限るので素直にパフォーマンスモニターなどに頼るほうが良いかと思います。

GC.RegisterForFullGCNotification(99, 99);
_thread = new Thread(() =>
{
    while(true)
    {
        var notification = GC.WaitForFullGCApproach();
        if (notification == GCNotificationStatus.Succeeded)
        {
            Console.WriteLine("GC Raised.");
        }

        notification = GC.WaitForFullGCComplete();
        if (notification == GCNotificationStatus.Succeeded)
        {
            Console.WriteLine("GC Completed.");
        }

        Thread.Sleep(500);
    }
});
_thread.Start();

まとめ

.NETアプリケーションを実行していると時に解決がなかなか難しい問題にあたることがあり、そんなときメモリダンプが解決の糸口になる可能性があります。もちろんダンプを眺めただけでは解決しない問題や、問題を発見したとしてもそもそもどうやって修正するのかというのはまた別の話です。

しかしながら解決の難しい問題は一つ一つ原因のようなものに見当をつけつつ追い詰めていく、その為にダンプを調査できるようになっておくのは悪くないと思いますのでお役に立てば幸いです。