Olivine: Building a Redis-Compatible Service in Go. · 章節目錄

第 15 章

[Day 15] Profiling with pprof

Go provides profiling tools pprof, it is an useful tools for developers to check performance issues.

There’re 2 types of pprof tool:

  1. Use pprof.StartCPUProfile(*os.File) and pprof.StopCPUProfile() directly.
  2. Import _ "net/http/pprof" directly, it registers some profiling routes of HTTP Server.

For most of daemon service, use "net/http/pprof" is a greate choice.

Benchmarking and Profiling

Initialize HTTP Server

There’s no http server in this service, we need to create one.

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

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

Start a web server, and don’t forget to handle shutdowning:

	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
		}

Create *http.Server, and import _ "net/http/pprof" to register pprof routes:

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

Note 1: pprof includes a lots of debug info, DO NOT expose to public, that’s why use Addr: "localhost:6060"

Note 2: "net/http/pprof" uses func init() to register routes automatically, it provides /debug/pprof/* routes.

Benchmark

To profile service performance, we need to make some pressure by redis-benchmark. It is a tool provided by Redis.

There’re some arguments for redis-benchmark, let’s take examples:

$ 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

It generates a report after benchmarking:

$ 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

We want to profile when server is working, to start a benchmarking by first. (Use -n 1000000000 to avoid finish benchmarking too early.)

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

Access GET http://localhost:6060/debug/pprof/profile to get profiling, it takes 30 seconds by default.

To analyze profile, use go tool pprof:

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

Note: it works by go tool pprof http://localhost:6060/debug/pprof/profile, but I prefer to save a file.

Understand Profiling

We can get a flame graph after benchmarking and profiling:

Image

Obviously, server tooks about 80% CPU time on conn.Write(), it’s not acceptable.

Fixing

Click server.(*simpleSrv).serve on flame graph, and checkout a “Source” view on top navigator.

Image

The conn.Write(ret.Marshal()) tooks 151.55s, it waste a lot with syscall when conn.Write(). We can use buffered writer instead.

// 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 {
		// ...
	}

When there’s no buffered input on resp.Reader, flush to write.

Add resp.(*Reader).Buffered:

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

Flush buffered writer when resp.(*Reader).Buffered == 0:

		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
			}
		}
	}

Verifiy

Benchmarking and profiling again, we can get another flame graph.

Image

The net.(*conn).Write decreased from 151.53s to 21.37s, it’s a big step!

One more thing

I wrote a shell script that can help us to profile servcie, but it works in progress:

#!/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