sql >> データベース >  >> RDS >> PostgreSQL

perfを使用したPostgreSQLのトレース

    プロファイリングユーティリティperf Linuxカーネルに同梱されているものは、システム全体およびマルチプロセスの動作を調べるのに非常に役立ちますが、よく使用されるCPUプロファイリングよりもはるかに多くのことを行います。あなたはおそらくperftop -azを見たことがあるでしょう またはperftop -u postgres 出力しますが、それはそれができることのほんの少しにすぎません。 (TL / DRバージョンが必要な場合は、「ユーザースペース動的プローブ」にジャンプしてください。)

    perfの大きな利点の1つ 邪魔にならないということです。デバッガーを接続して実行を中断する必要はありません。特別な環境では、プロファイラーの直下でコマンドを実行する必要はありません。問題のあるワークロードをデバッグするためにサーバーを再起動する必要はなく、多くの場合、デバッグオプションを使用して再コンパイルする必要もありません。これは、ライブシステムのパフォーマンスの問題を追跡する場合に非常に役立ちます。これにより、何が起こっているのかについての理論を、最小限の影響ですばやくテストできます。

    perf プロファイラーだけでなく、トレースもサポートしています。プロファイリングは、ハードウェアまたはソフトウェアのパフォーマンスカウンターによってトリガーされたときのシステムの状態のサンプリングに基づいています。これは、システムが最も時間を費やすポイントの統計的サンプリングを提供します。代わりに、トレースは特定のトレースイベントが発生するたびにサンプルを取得するため、頻度は低いが重要なイベントの場合にはるかに役立ちます。

    perf の最もエキサイティングな機能の1つであるPostgreSQLを使用する場合 ユーザースペースプロセスを追跡する機能です 。 PostgreSQLがWALセグメントを交換する頻度、外部キールックアップを実行する頻度などを知りたいですか? 1つのPostgreSQLバックエンドの場合ですか、それともクラスター全体の場合ですか? perf それを助けることができます。

    ユーザースペースとカーネルスペースのトレースポイントを混在させることができ、パフォーマンスカウンターのプロファイリングと同時に使用して、システムの全体像を把握するのに役立てることができます。 perf カーネルとユーザースペースの両方からスタックトレースをキャプチャでき、統計的な視覚化も実行できます。ユーザースペースのトレースポイントは、動的プローブを使用して作成されます。カーネル空間のものは、事前定義することも、動的プローブにすることもできます。

    では、これらの機能のいくつかをどのように使用しますか?

    ツールをインストールする

    まず、現在のパフォーマンスを使用していることを確認します 。この記事は、Fedora19でperf 3.11.6を使用して作成されました。 x86_64で、一部の機能は比較的新しいものです。

    ユーザースペーススタックの結果が必要な場合は、探しているコードを -Og -ggdb -fno-omit-frame-pointerでビルドする必要があります。 。 perfを使用している場合 libunwindで構築 フレームポインタは必要ありません。このStackOverflowの投稿とRHBugzilla#1025603を参照してください。カーネル側のデータのみに関心がある場合は、これは必要ありません。ディストリビューションパッケージを使用している場合は、 -debuginfoをインストールする必要がある場合があります パッケージも。

    以下のすべてのテストは、 perf を使用して、http://yum.postgresql.org/のストックPGDGPostgreSQL9.2パッケージで実行されました。 libunwindで再構築 上記の手順に従ってサポートします。

    カーネルトレースポイントとプローブ

    perf 事前定義されたカーネルトレースポイントからデータをキャプチャできます。その一部は、メモリの断片化、ディスクI/Oなどの問題を調べるときに役立ちます。sudoperflistを使用してトレースポイントのリストを取得できます。 。トレースポイントリストを指定でき、ワイルドカードがサポートされています。たとえば、実行中のPostgreSQLインスタンスの書き込みとディスクフラッシュの統計を取得する場合は、次のように実行します。

    sudo perf record -g dwarf -e block:block_rq_issue,syscalls:sys_enter_fsync -u postgres sleep 10

    データをキャプチャします。スリープの代わりに、コマンドを使用せずにキャプチャが完了したらcontrol-Cを押すか、 psql -cなどの他のコマンドを使用できます。 測定するワークロードをトリガーします。

    -u postgres ユーザーpostgresとして実行されているすべてのプロセスのプロファイル 。代わりに-aを使用できます すべてのCPUにわたるシステム全体のプロファイリング用。 1つのバックエンドだけをトレースすることも可能です。 psqlを開始します 、 select pg_backend_pid()を実行します 、 perfを実行します -p $ the_pidを使用 、次に同じ psqlでワークロードを開始します セッション。

    PostgreSQLを使用している場合、デフォルトのターゲットプロセスは、 perfの制御下で実行されるコマンドです。 、 psql ではなく、バックエンドがほとんどの作業を行うため、通常はあまり役に立ちません。 。サブコマンドを使用してテストのワークロードとタイミングを制御することは依然として有用です。

    データをキャプチャしたら、パフォーマンスレポートを使用できます それを調べるために。ここで説明するには、結果の集約と簡略化、スタックトレースの表示、インタラクティブな呪いとテキストレポートの出力などを制御するためのオプションが多すぎます。

    このセッションを例として取り上げます。ここでは、シェルセッション(ターミナル「T2」)とデータベース「regress」に接続されたpostgresセッション(ターミナル「T1」)があります。

    T1| regress=> select pg_backend_pid();
    T1| pg_backend_pid 
    T1| ----------------
    T1|           4495
    T1|(1 row)
    T2| $ sudo perf record -g dwarf -e block:block_rq_*,syscalls:sys_enter_write,syscalls:sys_enter_fsync -p 4495
    T1| regress=> create table x as select a FROM generate_series(1,1000000) a;
    T1| regress=>
    T2| $ ^C
    T2| [ perf record: Woken up 332 times to write data ]
    T2| [ perf record: Captured and wrote 86.404 MB perf.data (~3775041 samples) ]
    T2|
    T2| $ sudo perf report -g

    パフォーマンスレポートを使用できます のcursesguiを使用してトレースを掘り下げるか、 perf report --stdioを使用できます。 stdoutにデータをストリーミングするためのオプション。たとえば、スタックトレースが必要な場合は、次のコマンドを実行できます。

    $ sudo perf report -g --stdio
    ... blah blah ...
    # Samples: 1  of event 'syscalls:sys_enter_fsync'
    # Event count (approx.): 1
    #
    # Overhead   Command  Shared Object                 Symbol
    # ........  ........  .............  .....................
    #
       100.00%  postgres  libc-2.17.so   [.] __GI___libc_fsync
                |
                --- __GI___libc_fsync
                    mdimmedsync
                    heap_sync
                    intorel_shutdown
                    standard_ExecutorRun
                    ExecCreateTableAs
                    PortalRunUtility
                    PortalRunMulti
                    PortalRun
                    PostgresMain
                    ServerLoop
                    PostmasterMain
                    main
                    __libc_start_main
                    _start
                    (nil)
    ... blah blah...

    イベントsyscalls:sys_enter_fsyncについてそれを示しています 上記のスタックで1つのイベントがありました。それは、 ExecCreateTableAsを介して呼び出されたfsyncです。 。

    (理由により、最後の fsync()をまだ特定できていません。 perfによってキャプチャされていないようです psqlの場合 perfの制御下で直接実行されます 。これはperfstatの問題ではありません 、perfレコードのみ 。そのため、フープを飛び越えて、上記のpidでバックエンドを事前に選択しています。)

    ユーザースペース動的プローブ

    PostgreSQLによってトリガーされるカーネル内のイベントよりも、PostgreSQL自体の中で起こっていることに関心がある場合があります。 perfの新しいバージョン ユーザースペースプログラムの呼び出しでトリガーされる動的トレースポイントを挿入することで、これを支援できます。

    WALアクティビティの視聴に興味があり、 XLogFlushがいつになるかを確認したいとします。 、 XLogFileInit またはXLogFileOpen と呼ばれます。 perf を使用して、これらの呼び出しの動的トレースポイントを挿入できます。 :

    sudo perf probe  -x `which postgres` XLogFileInit
    sudo perf probe  -x `which postgres` XLogFileOpen
    sudo perf probe  -x `which postgres` XLogFlush

    -ggdb を使用してビルドしない限り、外部シンボル(非静的、-fvisibilityフラグで非表示)のみをプローブできます。 。 perf 記号が見つかりませんと文句を言います 存在しないシンボルを使用しようとした場合。執筆時点でperf スタック分析には使用できますが、外部debuginfoを使用してプローブのシンボルを検索することはサポートされていません。一般に、 src / includeの外部の場合 perfで使用できます 。

    各トレースポイントは、作成されたトレースポイントの名前を出力し、 perf probe -lを使用できます。 とにかくそれらをすべてリストするには:

    $ sudo perf probe -l
      probe_postgres:XLogFileInit (on 0x000000000009a360)
      probe_postgres:XLogFileOpen (on 0x000000000009a860)
      probe_postgres:XLogFlush (on 0x00000000000a0670)

    これらのプローブは、パフォーマンスイベントとして使用できるようになりました。サンプルワークロード中のxlogアクティビティを見てみましょう。pgbenchを実行している間、クラスター全体を監視します。

    sudo perf record -g dwarf -u postgres -e probe_postgres:XLogFileInit,probe_postgres:XLogFileOpen,probe_postgres:XLogFlush

    perf report -gを使って自分で試してみてください 。結果は次のようになります。 -g fractal、0などのオプションを使用できます 詳細を制御します。あるスタックブランチまたは別のスタックブランチ、pidおよびプロセスなどから発生した特定のカウンターのヒットのパーセンテージを確認できます。-sort オプションを使用すると、集約とグループ化をより細かく制御できます。

    でも待ってください、まだまだあります

    perf statも確認する必要があります およびperftop コマンド。 perf recordと同じイベントリストを取得できます 、ただし、いくつかの奇妙な理由で、プロセスフィルターのサポートが異なります。

    ダミーのワークロードを実行し、実行中にI/Oカーネルトレースポイントを確認する例を次に示します。

    $ sudo perf stat -e block:block_rq_*,syscalls:sys_enter_write,syscalls:sys_enter_fsync -a -r 5 -- psql -q -U postgres craig -c "drop table if exists x; create table x as select a FROM generate_series(1,1000000) a;";
    
     Performance counter stats for 'psql -U postgres craig -c drop table if exists x; create table x as select a FROM generate_series(1,1000000) a;' (5 runs):
    
         0 block:block_rq_abort                       [100.00%]
         0 block:block_rq_requeue                     [100.00%]
        97 block:block_rq_complete      ( +- 14.82% ) [100.00%]
        96 block:block_rq_insert        ( +- 14.97% ) [100.00%] 
        98 block:block_rq_issue         ( +- 14.67% ) [100.00%]
         0 block:block_rq_remap                       [100.00%]
    10,607 syscalls:sys_enter_write     ( +-  0.17% ) [100.00%]
         1 syscalls:sys_enter_fsync                                    
    
    0.908835058 seconds time elapsed    ( +- 18.31% )

    10kのwrite()で平均約100のブロックレイヤーI / O要求を実行し、単一のfsync()を実行していることがわかります。すべてのシステムプロファイリングを行っているため、その一部はシステムのバックグラウンドノイズです( -a )、ただし、システムはかなりアイドル状態であるため、それほど多くはなく、5回の実行で平均化されます。

    同様に、前に追加した動的プローブを使用して、pgbenchの実行中のxlogアクティビティを監視します。

    $ sudo perf stat -e probe_postgres:XLogFileInit,probe_postgres:XLogFileOpen,probe_postgres:XLogFlush -a -- /usr/pgsql-9.2/bin/pgbench -U postgres craig -c 2 -t 10000
    starting vacuum...end.
    transaction type: TPC-B (sort of)
    scaling factor: 100
    query mode: simple
    number of clients: 2
    number of threads: 1
    number of transactions per client: 10000
    number of transactions actually processed: 20000/20000
    tps = 715.854663 (including connections establishing)
    tps = 716.092133 (excluding connections establishing)
    
     Performance counter stats for '/usr/pgsql-9.2/bin/pgbench -U postgres craig -c 2 -t 10000':
    
          64 probe_postgres:XLogFileInit       [100.00%]
           0 probe_postgres:XLogFileOpen       [100.00%]
      55,440 probe_postgres:XLogFlush                                    
    
     27.987364469 seconds time elapsed

    perfプローブを使用してローカル変数の状態をキャプチャするなど、できることは他にもたくさんあります。 。その有用な例を後でいくつか書きます。それまでの間、新しい診断ツールを使って遊んだり、探索したり、楽しんだりしてください。

    更新: Michael Paquierは最近、systemtapを使用したPostgreSQLのトレースに関する関連記事を作成しました。これは、この記事の読者の興味を引く可能性があります。このアプローチを使用するには、Pgを再コンパイルする必要がありますが、構文が優れており、他にもいくつかの利点があります。


    1. テーブル式の基礎、パート9 –ビュー、派生テーブルおよびCTEとの比較

    2. ステップバイステップpostgres_fdw

    3. 不正な整数(2147483647)がMySQLに挿入されていますか?

    4. MySQLi count(*)は常に1を返します