Olivine：以 Go 建構與 Redis 相容的服務 · 章節目錄

第 15 章

Day 15：使用 pprof 分析效能

Go 的 pprof 能協助找出效能問題。

有兩種使用方式：

  1. 直接呼叫 pprof.StartCPUProfile(*os.File) 與 pprof.StopCPUProfile()。
  2. 匯入 _ "net/http/pprof"，在 HTTP server 註冊 profiling routes。

對長時間執行的服務而言，net/http/pprof 很方便。

Benchmarking 與 Profiling

初始化 HTTP Server

目前服務沒有 HTTP server，先加入一個：

// file: cmd/olivine/app.go
type App struct {
	cfg *data.Config

	worker  service.Worker
	server  server.Server
+	httpsrv *http.Server
}

啟動時也要處理 shutdown：

	g.Go(func() error {
		slog.Info("starting web server")
		if err := app.httpsrv.ListenAndServe(); err != nil && !errors.Is(err, http.ErrServerClosed) {
			return err
		}
		return nil
	})
		if err := app.httpsrv.Shutdown(shutdownCtx); err != nil {
			return err
		}

建立 *http.Server，並匯入 _ "net/http/pprof"：

			httpsrv: &http.Server{
				Addr: "localhost:6060",
			},
	_ "net/http/pprof"

注意：pprof 包含大量除錯資訊，不要暴露到公開網路，因此使用 Addr: "localhost:6060"。

注意：net/http/pprof 透過 init() 自動註冊 /debug/pprof/* routes。

Benchmark

Profiling 需要服務正在處理負載，可以使用 Redis 提供的 redis-benchmark。

以下是參數示範：

$ redis-benchmark -t GET,SET # Olny test with GET/SET RESP commands
$ redis-benchmark -n 1000000 # Request 1M totally
$ redis-benchmark -c 500     # Create 500 parallel clients 
$ redis-benchmark -P 16      # Send 16 RESP commands in single TCP connection

測試完成後會產生報告。以下是我這次測試的執行結果：

$ redis-benchmark -p 16379 -t GET
WARNING: Could not fetch server CONFIG
====== GET ======
  100000 requests completed in 1.00 seconds
  50 parallel clients
  3 bytes payload
  keep alive: 1
  multi-thread: no

Latency by percentile distribution:
0.000% <= 0.039 milliseconds (cumulative count 2)
50.000% <= 0.263 milliseconds (cumulative count 51164)
75.000% <= 0.279 milliseconds (cumulative count 76752)
87.500% <= 0.295 milliseconds (cumulative count 88450)
93.750% <= 0.319 milliseconds (cumulative count 94498)
96.875% <= 0.351 milliseconds (cumulative count 96963)
98.438% <= 0.455 milliseconds (cumulative count 98444)
99.219% <= 1.167 milliseconds (cumulative count 99221)
99.609% <= 1.759 milliseconds (cumulative count 99612)
99.805% <= 1.895 milliseconds (cumulative count 99805)
99.902% <= 1.959 milliseconds (cumulative count 99911)
99.951% <= 2.039 milliseconds (cumulative count 99957)
99.976% <= 2.063 milliseconds (cumulative count 99978)
99.988% <= 2.087 milliseconds (cumulative count 99988)
99.994% <= 2.127 milliseconds (cumulative count 99994)
99.997% <= 2.183 milliseconds (cumulative count 99997)
99.998% <= 2.367 milliseconds (cumulative count 99999)
99.999% <= 2.415 milliseconds (cumulative count 100000)
100.000% <= 2.415 milliseconds (cumulative count 100000)

Cumulative distribution of latencies:
0.060% <= 0.103 milliseconds (cumulative count 60)
1.352% <= 0.207 milliseconds (cumulative count 1352)
91.288% <= 0.303 milliseconds (cumulative count 91288)
98.120% <= 0.407 milliseconds (cumulative count 98120)
98.586% <= 0.503 milliseconds (cumulative count 98586)
98.848% <= 0.607 milliseconds (cumulative count 98848)
99.020% <= 0.703 milliseconds (cumulative count 99020)
99.121% <= 0.807 milliseconds (cumulative count 99121)
99.161% <= 0.903 milliseconds (cumulative count 99161)
99.181% <= 1.007 milliseconds (cumulative count 99181)
99.200% <= 1.103 milliseconds (cumulative count 99200)
99.248% <= 1.207 milliseconds (cumulative count 99248)
99.324% <= 1.303 milliseconds (cumulative count 99324)
99.368% <= 1.407 milliseconds (cumulative count 99368)
99.402% <= 1.503 milliseconds (cumulative count 99402)
99.430% <= 1.607 milliseconds (cumulative count 99430)
99.506% <= 1.703 milliseconds (cumulative count 99506)
99.688% <= 1.807 milliseconds (cumulative count 99688)
99.816% <= 1.903 milliseconds (cumulative count 99816)
99.934% <= 2.007 milliseconds (cumulative count 99934)
99.992% <= 2.103 milliseconds (cumulative count 99992)
100.000% <= 3.103 milliseconds (cumulative count 100000)

Summary:
  throughput summary: 99601.60 requests per second
  latency summary (msec):
          avg       min       p50       p95       p99       max
        0.280     0.032     0.263     0.327     0.695     2.415

Profiling

先執行 benchmark。以 -n 1000000000 避免負載太早結束：

$ redis-benchmark -p 16379 -t SET -P 16 -n 1000000000

存取 GET http://localhost:6060/debug/pprof/profile 取得 CPU profile，預設收集 30 秒。

再使用 go tool pprof 分析：

$ curl -o profile http://localhost:6060/debug/pprof/profile
$ go tool pprof -http=:8000 profile

注意：也可以直接執行 go tool pprof http://localhost:6060/debug/pprof/profile，但我偏好先存成檔案。

理解 Profiling

收集後能查看 flame graph：

Image

我觀察到約 80% CPU 時間花在 conn.Write()，希望改善這個成本。

改善

點選 flame graph 的 server.(*simpleSrv).serve，再切換到上方的 Source view：

Image

該次結果顯示 conn.Write(ret.Marshal()) 花費 151.55 秒，頻繁 syscall 成本很高，可以改用 buffered writer。

// file: internal/server/server.go
func (s *simpleSrv) serve(conn net.Conn) {
	defer conn.Close()
	defer func() {
		s.mu.Lock()
		defer s.mu.Unlock()

		delete(s.conns, conn)
	}()

	rd := resp.NewReader(conn)
+	wr := bufio.NewWriter(conn)
+	defer wr.Flush()

	for {
		// ...
	}

當 resp.Reader 沒有緩衝輸入時，flush 輸出。

加入 resp.(*Reader).Buffered：

func (r *Reader) Buffered() int {
	return r.rd.Buffered()
}

當 Buffered() == 0 時 flush：

		if rd.Buffered() == 0 {
			if err := wr.Flush(); err != nil {
				if s.inShutdown.Load() {
					return
				}

				slog.Error("failed to flush", slog.Any("error", err))
				return
			}
		}
	}

驗證

再次執行 benchmark 與 profiling，得到以下 flame graph：

Image

net.(*conn).Write 從 151.53 秒降到 21.37 秒。

其他工具

我也寫了協助 profiling 的 shell script，但仍在開發中：

#!/usr/bin/env bash

set -Eeuo pipefail

project_root="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)"
output_dir="$project_root/scripts/out"
olivine_pid=""
benchmark_pid=""

cleanup() {
  local status=$?

  trap - EXIT INT TERM

  if [[ -n "$benchmark_pid" ]] && kill -0 "$benchmark_pid" 2>/dev/null; then
    kill "$benchmark_pid" 2>/dev/null || true
    wait "$benchmark_pid" 2>/dev/null || true
  fi

  if [[ -n "$olivine_pid" ]] && kill -0 "$olivine_pid" 2>/dev/null; then
    kill "$olivine_pid" 2>/dev/null || true
    wait "$olivine_pid" 2>/dev/null || true
  fi

  make clean
  exit "$status"
}

usage() {
  echo "Usage: $0 profile [redis-benchmark flags...]" >&2
}

wait_for_pprof() {
  local attempt

  for attempt in {1..30}; do
    if curl --fail --silent --output /dev/null --max-time 1 \
      http://127.0.0.1:6060/debug/pprof/; then
      return 0
    fi
    sleep 1
  done

  echo "Olivine pprof server did not become ready on 127.0.0.1:6060." >&2
  return 1
}

if [[ $# -lt 1 || "$1" != "profile" ]]; then
  usage
  exit 2
fi

shift

if ! command -v redis-benchmark >/dev/null 2>&1; then
  echo "redis-benchmark is required but was not found in PATH." >&2
  exit 1
fi

if ! command -v curl >/dev/null 2>&1; then
  echo "curl is required but was not found in PATH." >&2
  exit 1
fi

cd "$project_root"
trap cleanup EXIT INT TERM

make gen
make build

mkdir -p "$output_dir"
./bin/olivine &
olivine_pid=$!

wait_for_pprof

redis-benchmark "$@" -p 16379 &
benchmark_pid=$!

profile_path="$output_dir/$(date +%Y-%m-%d_%H:%M:%S).profile"
curl --fail --show-error --output "$profile_path" \
  http://localhost:6060/debug/pprof/profile