詳解 システム・パフォーマンス - 第5章：アプリケーション

アプリケーション層で観測すべきこと

インフラ（CPU/メモリ/ディスク）が正常でもアプリが遅い場合、アプリ内部を観測する。

観測対象	具体例	ツール
CPU 消費	どの関数が重いか	perf, async-profiler
メモリ割り当て	GC・メモリリーク	Valgrind, memleak
I/O パターン	どのファイル・どのサイズで読み書き	strace, opensnoop
ロック競合	スレッドが何を待っているか	perf, strace（futex）
レイテンシ	リクエスト処理時間の内訳	bpftrace, uprobe

---

プロファイリング vs トレーシング

	プロファイリング	トレーシング
手法	定期的にスタックをサンプリング	イベント発生ごとに記録
オーバーヘッド	低（サンプリングレートで調整）	高（全イベント記録）
向き不向き	CPU消費の傾向をつかむ	特定のイベントを詳細に追う
代表ツール	perf record -F 99	strace, bpftrace

---

CPU プロファイリング

# アプリ全体の CPU プロファイル（30秒サンプリング）
perf record -F 99 -g -p <PID> sleep 30
perf report

# フレームグラフで視覚化（最もわかりやすい）
perf record -F 99 -a -g -- sleep 60
perf script | ./FlameGraph/stackcollapse-perf.pl | \
  ./FlameGraph/flamegraph.pl --colors=hot > cpu-flame.svg

# フレームグラフの読み方：
# - X軸の幅 = CPU消費時間の割合（広いほど重い）
# - Y軸の高さ = コールスタックの深さ
# - 一番上の関数が実際に CPU を使っている関数
# - 根本（下）が呼び出し元

---

言語別のプロファイリング

Java

# async-profiler（Java の CPU/Heap プロファイリング）
./profiler.sh -d 30 -f cpu-flame.html <PID>

# JFR（Java Flight Recorder）- JDK 11以降無料
java -XX:+FlightRecorder \
     -XX:StartFlightRecording=duration=60s,filename=recording.jfr \
     -jar myapp.jar
jfr print recording.jfr

# GC ログ出力
java -Xlog:gc*:file=gc.log -jar myapp.jar
# → GC 発生頻度・時間を確認

Go

# pprof 経由（HTTP エンドポイント追加が必要）
import _ "net/http/pprof"

# CPU プロファイル取得
go tool pprof http://localhost:6060/debug/pprof/profile?seconds=30

# goroutine のスタックダンプ
curl http://localhost:6060/debug/pprof/goroutine?debug=1

# メモリプロファイル
go tool pprof http://localhost:6060/debug/pprof/heap

Node.js

# --prof フラグで V8 プロファイリング
node --prof app.js

# 結果を人間が読める形に変換
node --prof-process isolate-*.log > processed.txt

# または clinic.js
npx clinic doctor -- node app.js
npx clinic flame -- node app.js  # フレームグラフ

Python

# cProfile（標準ライブラリ）
python -m cProfile -o output.prof app.py
python -m pstats output.prof

# py-spy（本番向け、ゼロオーバーヘッド）
pip install py-spy
py-spy record -o profile.svg --pid <PID>
py-spy top --pid <PID>  # リアルタイム表示

---

システムコールレベルのトレース

アプリが何をしているかを syscall レベルで把握する。

# syscall 別の実行時間集計（5秒）
strace -c -p <PID>
# 出力例：
# % time  seconds  calls  syscall
#  80.0   0.0080    1000  epoll_wait  ← イベント待ち（正常なアイドル）
#  15.0   0.0015     500  read
#   5.0   0.0005     100  write

# ファイルI/Oのみ追跡
strace -e trace=file -p <PID> 2>&1 | head -30

# ネットワークI/Oのみ追跡
strace -e trace=network -p <PID> 2>&1 | head -30

# 実行時間付きで追跡（どの syscall が遅いか）
strace -T -p <PID> 2>&1 | head -30
# 各行の末尾に <0.000123> で実行時間が表示される

# よくある問題のパターン
# futex が多い → スレッド間のロック競合
# epoll_wait が多い → イベント待ち（通常は正常）
# read(fd=X, count=1) が多い → バッファリングなしの非効率な読み込み

---

ロック競合の検出

マルチスレッドアプリでスレッドが mutex/ロックを待っている状態を検出する。

# futex（ロック）の待ち時間を確認
strace -e trace=futex -T -p <PID> 2>&1 | head -30
# futex(lock, FUTEX_WAIT, ...) が長ければロック待ちが多い

# スレッドの状態を一括確認
ps -p <PID> -L -o pid,lwp,stat,wchan
# wchan: カーネル内の待ち場所（futex_wait → ロック待ち）

# bpftrace でロック待ちを可視化
sudo bpftrace -e '
  tracepoint:syscalls:sys_enter_futex /pid == <PID>/ {
    @start[tid] = nsecs;
  }
  tracepoint:syscalls:sys_exit_futex /pid == <PID> && @start[tid]/ {
    @latency = hist(nsecs - @start[tid]);
    delete(@start[tid]);
  }
'

---

メモリ割り当てのトレース

# malloc() の呼び出し元を特定（BCC tool）
sudo memleak -p <PID> -a 5
# -a 5: 上位5スタックを表示

# strace でメモリ割り当て syscall を追跡
strace -e trace=mmap,munmap,brk -p <PID> 2>&1 | head -30

# /proc から詳細確認
cat /proc/<PID>/status | grep -E "VmRSS|VmPeak|VmSwap"
# VmRSS: 実際の物理メモリ使用量
# VmPeak: 仮想メモリの最大値

---

アプリのパフォーマンス改善チェックリスト

CPU が高い場合
□ フレームグラフを取得して、ホットパスを特定する
□ N+1 クエリ（ループ内での繰り返し DB 呼び出し）を確認
□ 不要なシリアライゼーション・デシリアライゼーションを確認
□ GC の頻度が高くないか（Java/Go/Node.js）

メモリが増え続ける場合
□ memleak / Valgrind でリークを検出
□ キャッシュに TTL を設定しているか確認
□ グローバル変数・クロージャでの参照保持を確認

レイテンシが高い場合
□ strace -T で遅い syscall を特定
□ 外部依存（DB・API）のレイテンシを測定
□ タイムアウト・リトライの設定を確認