こんにちは、@mayukiです。
以前、このブログにてダンプ解析入門 - Visual Studioでの可視化によるC#トラブルシューティングというスタックオーバーフローのような問題を調査する方法について触れましたが、今回はダンプを元にメモリ周りの状態を見ていく方法について調べたので少しまとめてみました。
長い時間実行するようなアプリケーション(アプリケーションサーバーなど)ではメモリの使用状況やメモリリークなどを調査したいというケースがたまにやってきます。そんなときにはプロセスのメモリダンプを取得して解析することで問題の原因がわかりそう…そんなシチュエーションで役立つかもしれません。
お品書き
- お品書き
- 前提
- ダンプのみどころ
- どのツールで解析すれば?
- Visual Studioを試してみる
- DebugDiagを試してみる
- WinDbgを試してみる
- インストール
- ダンプファイルを開いてまずはSOS
- 雑基礎知識
- WinDbgでの解析のやっていきかた
- WinDbgコマンドいろいろ
- メモ: トラブルシューティング
- ヒープのオブジェクト統計情報を取得する: !DumpHeap -stat
- ヒープの状況を取得する: !HeapStat or !EEHeap -gc
- ファイナライゼーションキューの情報を取得する: !FinalizeQueue
- MethodTable(型)から生きているオブジェクトの一覧を取得する: !DumpHeap -live -mt <MT addr>
- MethodTable(型)から死んでいるオブジェクトの一覧を取得する: !DumpHeap -dead -mt <MT addr>
- オブジェクトの参照元を探す: !GCRoot <obj addr>
- 型情報を出力する: !DumpMT <MT addr> or !DumpMT -md <MT addr>
- 型情報を出力する: !DumpClass <EEClass addr>
- ファイナライザースレッドがブロック状態かどうかを調べる
- Appendix
- まとめ
前提
まずダンプを取得する対象の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 (x86)で開いて、SOSも読み込んだのに
- 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を利用してメモリの状態を調べてみましょう。
メモリリークの原因を突き止める場合、一体何が多く残っているのか、何が理由で残っているのかといったことを探るのが定石です。その調査として出来そうな手順は以下のような感じでしょうか。
- オブジェクトの統計情報を出力する
- 怪しそうな型を見つける
- 例えば数が想定外に多いとか、GCに回収されていることを期待しているにもかかわらず残っているとか…
- 型から生きているオブジェクトの一覧を出力する
- オブジェクトからGCのルートとなるオブジェクトを探す
- 残っているのが正しいかどうかはアプリ次第…
- 正しければまたやり直し 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: 00007ffaというようなエラーが表示されるeab47c11 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
- ポインタの一覧は
- 各ヒープのジェネレーション NにあるFinalizeメソッドを持つ(デストラクタを持つ)オブジェクトの数
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で次の呼び出しシグナルを待っているような感じでしょうか。
次にマネージコード上で無限ループに陥った場合のスタックです。
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アプリケーションを実行していると時に解決がなかなか難しい問題にあたることがあり、そんなときメモリダンプが解決の糸口になる可能性があります。もちろんダンプを眺めただけでは解決しない問題や、問題を発見したとしてもそもそもどうやって修正するのかというのはまた別の話です。
しかしながら解決の難しい問題は一つ一つ原因のようなものに見当をつけつつ追い詰めていく、その為にダンプを調査できるようになっておくのは悪くないと思いますのでお役に立てば幸いです。
