記事一覧
ツールPythonC/C++備忘録

【備忘録】PythonとC/C++におけるプロファイリングとか調査とか解析とか

投稿日: 2023/8/22 23:07
更新日: 2023/8/31 22:44

概要

PythonとC/C++におけるプロファイリングやメモリリーク調査、コアダンプ調査とかの方法をまとめた備忘録。

※随時更新。なお2022/8現在C/C++の要素が強い。

※自分への備忘録のため、第三者がみて分かりづらい表現や曖昧さがある表現、厳密性に欠ける表現、誤った解釈があるかと思いますがご了承ください。

※明らかに誤りである情報を見つけた場合はご連絡ください。→ Twitter (X)

ツール導入

後述するツールの導入方法を記述しておく。

　

Valgrindインストール

$ sudo apt install valgrind

graphviz(dot), gprof2dotインストール

$ sudo apt install graphviz
$ pip3 install gprof2dot

　

ツール導入と関係ないが、C/C++においては前提として、デバッグオプションを付けてビルドする。最適化も無効にする。

g++ -o {output_program} {soruce_file} -g -O0

プロファイリング

プログラムのプロファイリング方法についてまとめる。

Pythonでのプロファイリング

$ python -m cProfile -o {output_file_path}.pstats {target_script}.py

コマンドライン引数がある場合は、対象スクリプトパスの後ろにそのまま付加する。

　

Flatプロファイリング

flat-profileとかかっこいい名前してるが、要はテキストベースでプロファイリング結果出すだけ。

下のコードでpstatsファイルを読み取り出力する。

from pstats import Stats

pstats_path = "./test_cv_script.pstats"
stats = Stats(pstats_path)
stats.sort_stats("tottime") # 各関数の実行に要した時間(サブ関数の呼び出し時間除く)でソート
stats.print_stats(10) # 上位10件を出力

出力サンプル ↓

Wed Aug 23 20:50:41 2023    ./sample_py.pstats

         1006 function calls in 0.000 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)       
        1    0.000    0.000    0.000    0.000 {built-in method builtins.print}
...

各項目の説明は下の表の通り。

tottime

各関数の実行に要した時間 (サブ関数の呼び出し時間除く)

percall

tottime / ncalls

cumtime

各関数の実行に要した時間 (サブ関数の呼び出し時間含む)

percall

cumtime / ncalls

filename:lineno(function)

ファイル名:行数(関数名)

　

コールグラフ作成

$ gprof2dot -f pstats {input_file_path}.pstats | dot -Tpng -o {output_file_path}.png

出力サンプル ↓

Pythonコールグラフ

C/C++でのプロファイリング

$ valgrind --tool=callgrind --callgrind-out-file={output_file_path} {target_exec}

コマンドライン引数がある場合は、対象実行ファイルパスの後ろにそのまま付加する。

　

コールグラフ作成

$ gprof2dot -f callgrind {input_file_path} | dot -Tpng -o {output_file_path}.png

出力はPythonのと同じ。

パフォーマンス測定

[編集中]

メモ:

　処理時間計測： time

　メモリ使用量計測: free, vmstat, /proc/$pid/status

　CPU使用率: mpstat, top -d 1 -b -p $(pgrep "PROCESS_NAME") | awk '{if($12 == $(pgrep "PROCESS_NAME")) pring $9}'

メモリリーク調査

Memcheck(Valgrind)

Valgrindに収録されてるメモリリーク検出ツール。

最小限コマンド

valgrind --tool=memcheck --log-file={log_file_path} --leak-check=full {target_exec}

私的推奨コマンド

valgrind --tool=memcheck --log-file={log_file_path} --leak-check=full --show-leak-kinds=all --keep-debuginfo=yes -s {target_exec}

オプション説明

　

オプション

説明

--log-file

ログファイル出力パス

--leak-check

メモリリーク検索の有効/無効

full : 検索有効
summary : 検索無効 (検知数のみ出力)

--show-leak-kinds

表示するリーク項目

definite : 確実なロスト
indirect : 間接的なロスト
possible : 可能性のあるロスト
reachable : 到達可能
all : すべての項目

--keep-debuginfo

デバッグ情報を保持するか

yes : 保持する

-s

プログラム実行中のエラーをリスト表示する

--show-error-list=yesと同等

ヒープサマリ

プログラム終了時点で確保されてるメモリ量と、プログラム実行中に確保・解放した回数と割り当てられた総バイト数が出力されている。

==340== HEAP SUMMARY:
==340==     in use at exit: 573,983 bytes in 4,575 blocks  <--- プログラム終了時点で約560.5KB(4,575 blocks)確保されている。
==340==   total heap usage: 257,566 allocs, 252,991 frees, 1,706,413,665 bytes allocated  <--- 257,566回メモリ確保し、252,991回解放した。総バイト数約1.59GB。

理想はin use at exitが0バイト/0ブロックでallocs <= freesとなっていることだが...非常に簡単なコードでない限りそれは無理だと思う...

少なくともOpenCVなどの外部ライブラリを使うと出力サンプルのような結果になる。

しかし通常、これらのメモリはプログラム終了後に解放される"はず"なので、ここでの結果が理想と違っても即座に問題とはならない。

そしてこれらのメモリブロックのほとんどは後述するstill reachableに該当するブロックである。

※極稀なケースとして、プログラム終了後にも関わらずメモリ解放されない→メモリリークを起こしている可能性も考えられるが、Memcheckでは実行終了後のメモリ操作を捕捉できないためここではどうしようもない。

リークサマリ

名前の通り、リーク概要。

確保したメモリブロックに到達不可能であることを"lost"と言ってる。

※メモリブロックを参照する術を失い、ブロックだけ取り残され(メモリリーク)、メモリ領域を食い潰していきクラッシュする

==340== LEAK SUMMARY:
==340==    definitely lost: 0 bytes in 0 blocks            <--- 確実なロスト。
==340==    indirectly lost: 0 bytes in 0 blocks            <--- 間接的なロスト。
==340==      possibly lost: 10,088 bytes in 32 blocks      <--- 可能性のあるロスト。
==340==    still reachable: 563,895 bytes in 4,543 blocks  <--- 到達可能(Not lost)。
==340==                       of which reachable via heuristic:  <--- ヒューリスティック分析によるオブジェクト内訳
==340==                         newarray           : 1,536 bytes in 16 blocks  <--- 1.5KBものarrayが確保され到達可能。
==340==         suppressed: 0 bytes in 0 blocks            <--- Memcheck実行時に意図的に検査を無視(警告抑制)した分のブロック。

各ロスト項目の説明は以下の通り。

  • definitely lost

    確実にロストしたメモリブロック。

    これが0 bytesでないとアウト。

  • indirectly lost

    間接的にロストしたメモリブロック。

    definitely lostとされるメモリブロックに関連付けられたメモリブロックが道連れとなりロストしたケース。

  • possibly lost

    ロストの可能性があるメモリブロック。

    ブロックには到達可能であるが、参照ポインタが開始ポインタではなく内部ポインタである/が含まれる。

    即座に問題とはならないが、意図的に内部ポインタとしていない場合は問題となる。(偶然、ポインタがそのブロックを指し示しているだけの可能性があるため)

    　

    ※開始ポインタとは、ブロックの先頭を指し示すポインタ。通常すべてのポインタは開始ポインタである。

    ※内部ポインタとは、ブロックの先頭以外を指し示すポインタ。

    　意図的あるいは強制的に先頭部から移動させたり、new[]で割り当てた配列へのポインタ、多重継承を使用したオブジェクト内部へのポインタなどがそれに該当する。

  • still reachable

    到達可能なメモリブロック。

    すなわちメモリリークの原因とならないブロックである。

    　

    このうち、ブロック参照ポインタが内部ポインタであったメモリブロックで、ヒューリスティック分析により健全であると判断されれば、

    of which reachable via heuristic:にその実体(オブジェクト)とメモリサイズが出力される。

    つまり通常、内部ポインタである/が含む場合はpossibly lostとされるが、ヒューリスティック分析により意図的に内部ポインタになったと確実に言える場合であればstill reachableと判断される。

    stdstring(文字列), length64(なにこれ), newarray(配列), multipleinheritance(多重継承オブジェクト)などは健全な内部ポインタである。

  • suppressed

    警告抑制により無視されたメモリブロック。

    Memcheckは誤検出をしばしば起こすもので、明らかにバグでないときでもロストしたと警告することがある。

    そういった場合に、作業者が"suppression"と呼ばれる警告抑制のファイルを作成し、意図的の特定の処理のメモリリーク検査を無視させることがある。

    そこで無視されたメモリブロックがここに出力される。

　

各ロスト項目のイメージ↓

Memcheckロストイメージ

注意

Memcheck実行により得た結果からメモリリークの有無を判断するにあたって、動作環境に差異があることを念頭におくべきである。

Memcheckでは、malloc()といったメモリ操作関連の関数が、標準ライブラリの関数からMemcheckがもつライブラリの関数に置き換えられる。

またMemcheckはその動作の性質上、ネイティブの実行環境と差異が発生するために、通常のプログラム実行では起こり得なかったエラーがMemcheck実行により発生することがしばしばある。(その逆もある)

以上のような環境差異を考慮したうえで適切な判断をするよう心がける。

　

出力サンプル ↓

==340== Memcheck, a memory error detector
==340== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==340== Using Valgrind-3.15.0 and LibVEX; rerun with -h for copyright info
==340== Command: _old/test_cv_program data/test_video.mp4
==340== Parent PID: 17
==340== 
==340== 
==340== HEAP SUMMARY:
==340==     in use at exit: 573,983 bytes in 4,575 blocks
==340==   total heap usage: 257,566 allocs, 252,991 frees, 1,706,413,665 bytes allocated
==340== 
==340== 1 bytes in 1 blocks are still reachable in loss record 1 of 3,800
==340==    at 0x483B7F3: malloc (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so)
==340==    by 0x8E0FAFE: VSIStrdup (in /usr/lib/libgdal.so.26.0.4)
==340==    by 0x8E0FE9A: VSIStrdupVerbose (in /usr/lib/libgdal.so.26.0.4)
==340==    by 0x8DBADB6: CSLAddStringMayFail (in /usr/lib/libgdal.so.26.0.4)
==340==    by 0x8DBAE5C: CSLAddString (in /usr/lib/libgdal.so.26.0.4)
==340==    by 0x88A30EB: GDALMultiDomainMetadata::SetMetadata(char**, char const*) (in /usr/lib/libgdal.so.26.0.4)
==340==    by 0x88A323C: GDALMultiDomainMetadata::SetMetadataItem(char const*, char const*, char const*) (in /usr/lib/libgdal.so.26.0.4)
==340==    by 0x87DD695: GDALRegister_VRT (in /usr/lib/libgdal.so.26.0.4)
==340==    by 0x850CBB6: GDALAllRegister (in /usr/lib/libgdal.so.26.0.4)
==340==    by 0x588C9A4: ??? (in /usr/lib/x86_64-linux-gnu/libopencv_imgcodecs.so.4.2.0)
==340==    by 0x5880B28: ??? (in /usr/lib/x86_64-linux-gnu/libopencv_imgcodecs.so.4.2.0)
==340==    by 0x587D009: ??? (in /usr/lib/x86_64-linux-gnu/libopencv_imgcodecs.so.4.2.0)
~ 中略 ~
==340== LEAK SUMMARY:
==340==    definitely lost: 0 bytes in 0 blocks
==340==    indirectly lost: 0 bytes in 0 blocks
==340==      possibly lost: 10,088 bytes in 32 blocks
==340==    still reachable: 563,895 bytes in 4,543 blocks
==340==                       of which reachable via heuristic:
==340==                         newarray           : 1,536 bytes in 16 blocks
==340==         suppressed: 0 bytes in 0 blocks
==340== 
==340== ERROR SUMMARY: 20 errors from 20 contexts (suppressed: 0 from 0)

AddressSanitizer(ASan)

gcc(g++)に組み込まれてるメモリリーク検出ツール。

プログラムのビルド時にフラグを立てる必要がある。

g++でビルド

g++ -o sample_prof sample_prof.cpp -g -O0 -fsanitize=address

mesonでビルド

meson builddir --buildtype=debug -Db_sanitize=address -Db_lundef=false && ninja -C builddir

　

あとは通常通りプログラムを実行するだけ。

出力サンプル ↓

$ ./sample_prog

=================================================================
==3913==ERROR: LeakSanitizer: detected memory leaks

Direct leak of 4 byte(s) in 1 object(s) allocated from:
    #0 0x7f8033f65587 in operator new(unsigned long) ../../../../src/libsanitizer/asan/asan_new_delete.cc:104
    #1 0x55d1a752c27e in main /home/himazin/work/DemoScript/sample_prog.cpp:5
    #2 0x7f803393c082 in __libc_start_main ../csu/libc-start.c:308

SUMMARY: AddressSanitizer: 4 byte(s) leaked in 1 allocation(s).

メモリリークもなく、特にエラーもなければそのまま終了される。

mtrace

mcheck.hのmtrace()を使ったメモリリーク検出。

怪しい箇所に絞って検証することができる。

　

サンプルコード

#include <iostream>
#include <mcheck.h>

int main() {
    mtrace();   // メモリリークの検出開始

    int* dynamicInt = new int;
    *dynamicInt = 42;

    // delete dynamicInt; // 解放漏れ

    muntrace(); // メモリリークの検出終了

    return 0;
}

検出結果を確認する流れは以下の通り。

$ export MALLOC_TRACE="/home/himazin/work/DemoScript/sample_mtrace.log"  <-- 検出結果の出力先
$ ./sample_prog
$ mtrace sample_prog sample_mtrace.log  <-- 結果の解析

Memory not freed:
-----------------
           Address     Size     Caller
0x0000557ee9cc32a0      0x4  at 0x7faa444d8b29

うーん... 4 Byteなにかがリークしてるっていうのはわかるけど...って感じだ。

今回はコードが超簡単なので原因がすぐわかるのだが、小規模なコードでも原因を追うのは難しそう...

コアダンプ調査

[編集中]

メモ:

　gdb

参考


記事一覧

もっとみる...

ジャンル

もっとみる...

タグ

もっとみる...