VPN経由のpsql時間計測:ネットワーク待ちとクエリ処理の切り分け

psqlは文ごとに経過時間を一つだけ報告するため、遅いVPNはそれを膨らませる。どちら側を調整する前に、接続・実行・転送・往復の時間を分けて測る。

データベースホスト上ではおよそ一秒、VPN経由では四秒でレポートが終わり、psqlが表示する数値はデータベースをまっすぐ指している。その数値はクライアント側のストップウォッチであり、サーバーの計測ではない。文が送り出されるまで、応答を待つ時間、行が戻ってくる時間のすべてを含んでいる。この三つを分けることだけが、どちら側を調整すべきかを知る方法である。

psqlのタイマーが実際に測っているもの

\timing on は、クライアントが文をソケットに書き込む直前にストップウォッチを開始し、その結果の最後の行が読み終わったときに止める。サーバー自身の実行はその時間枠のどこかにあり、パケットがトンネル内で費やす一ミリ秒も同じ枠に入る。出力のどこにも両者は分けて示されない。EXPLAINも数値を表示するが、それはサーバーが生成し、クライアントの待ち時間を含まない。二つの数値、二つの異なる問いである。

一つのセッションを開始し、計測を有効にしたまま、気になる文をその中から実行する。セッションを再利用すれば、接続コストが最初の計測に入らない。

psql "host=db.internal port=5432 dbname=appdb user=app" \
  -c "\timing on" \
  -c "select count(*) from orders where created_at > now() - interval '1 day';"

数値には結果の転送がまだ含まれており、ここではそれが望ましい。新しい呼び出しが加える接続と認証のやり取りは、もう含まれていない。

一つの文を三つの経路で比較する

同じ文をUnixソケット、LANアドレス、VPNホスト名の順に実行し、三つを比較する。最後だけが遅いなら、クエリは変数ではない。

各呼び出しはまず接続し、その後に文を計測するので、接続コストは数値の外に残り、転送は中に残る。WHERE句、行数、クライアントマシンを同一に保たなければ、経路ではなく作業量を比較することになる。

psql -h /var/run/postgresql -U app -d appdb -c "\timing on" -c "select count(*) from orders;"
psql -h 10.40.0.12 -U app -d appdb -c "\timing on" -c "select count(*) from orders;"
psql -h db.vpn.internal -U app -d appdb -c "\timing on" -c "select count(*) from orders;"

LANでは差は通常、無視できるほど小さい。VPN経由ではそうでないことが多い。三つの結果を並べれば、どの待ち時間を攻めるべきかが分かる。

ローカルソケットが遅いなら、サーバーの処理か計画である。LANの結果が遅いなら、クエリかそれが動かす量である。VPNの結果だけが遅いなら、経路上の遅延、MTU、利用可能な帯域であり、インデックスの変更では直らない。

サーバー自身の実行時間を取り出す

サーバーは費やした時間を報告できる。クライアントの数値と並べるべきはその数値である。EXPLAINにANALYZEを付けると文を実行し、計画の中に計画時間と実行時間を表示する。BUFFERSはキャッシュの挙動を加え、温まった実行と冷えた実行の違いをしばしば説明する。書き込むつもりがないなら、書き込み文に向けてはならない。読み取り専用レプリカは始めるのに最も安全な場所であり、psqlリファレンスが、タイマーのクライアント側の範囲を記録している。

アプリケーションがすでに実行している文については、pg_stat_statementsが何も再実行せずにサーバー側の実行を集計する。行は正規化されたクエリごとなので、一つの項目が複数の呼び出し箇所を覆うことがある。

select calls, round(mean_exec_time::numeric, 2) as mean_ms, rows
from pg_stat_statements
order by mean_exec_time desc
limit 5;

列名はリリースによって異なる。PostgreSQL 13以降はmean_exec_timeを公開し、古いバージョンはmean_timeと呼ぶので、そのクエリがエラーになる場合は\d pg_stat_statementsで確認する。これらの値は計画を含まず、クライアントまでの往復も含まない。この除外があるからこそ、比較に役立つ。

ミリ秒だけでなく往復回数を数える

小さな依存文二百個で組まれたレポートは、経路が加える遅延を二百倍にする。百万行を返す一文はその遅延を一度だけ払い、その後は長く帯域を払う。どちらもクライアントのタイマーでは同じに見え、正反対の対処を必要とする。

推測ではなく文の数を測る。合計を読み、レポートを一度実行し、もう一度読んで引く。

select sum(calls) as calls from pg_stat_statements;
-- run the report here
select sum(calls) as calls from pg_stat_statements;

差分が大きく、各文がサーバーで安いなら、バッチ化が効く対処である。依存するクエリをまとめるか、集合ベースの一文を使うか、カーソルからループを回す。対話的なpsqlでは、\set FETCH_COUNT 1000大きな結果が分割して届くようになり、転送とクライアントメモリの挙動が変わる。サーバーの処理は減らないので、遅いクエリを救うことはない。

トンネルの再送とMTUの停止を確認する

小さな文は速いのに大きな結果が途中で止まるなら、クエリはたいてい正常で経路がそうではない。MTUが下位のリンクより低いトンネルに、遮断されたICMPが重なると、まさにそのパターンになる。最初のパケットは届き、大きなものは消え、転送は再試行するまで止まったままになる。クライアント側の再送カウンタがそれを示す。

意図的に遅い転送を走らせながら、ソケットとカーネルのカウンタを見る。再送の合計は累積なので、一つのサンプルを読むのではなく前後で記録する。

ss -tin dst 10.40.0.12
netstat -s | grep -iE "retransmit|segments retransmitted"
ping -M do -s 1400 -c 3 10.40.0.12

転送中に増える再送と、1400バイトでは成功し1472では失敗するpingが、データベースではなくMTUの問題を指す。トンネルインターフェースのMTUを下げるか、ゲートウェイでMSSを絞るのが通常の修正であり、同じ三つのコマンドで後から確認できる。転送がまだ遅いのに再送が横ばいなら、損失ではなくトンネルに許された帯域を見る。

短い手順で次の遅いレポートを覆える。一つの文をローカル、LAN、VPNで比較し、サーバーの実行をEXPLAINかpg_stat_statementsから読み、一度実行する前後で呼び出しを数え、大きな結果が動く間の再送を見る。各手順は経路の片側を除外する。どれも、どのコンポーネントを再起動するかを推測する必要はない。

関連記事