본문으로 건너뛰기

관측성과 배포

이 챕터에서 다루는 것​

서비스를 관찰 가능하게 만들고 배포 가능한 형태로 묶는다. 그리고 실제로 부하를 걸어 프로파일을 읽는다 — 이 챕터의 숫자는 전부 이 머신(darwin/arm64, Go 1.26.5)에서 실행한 결과다.

마지막 절은 93개 챕터에 대한 회고와 다음 학습 경로다.

기동 로그 한 줄이 답해야 하는 것​

프로세스가 뜨자마자 찍는 로그가 나중에 사고를 조사할 때 첫 번째 단서가 된다. "어떤 버전이 어떤 설정으로 떠 있었는가"에 그 한 줄이 답해야 한다.

examples/13-capstone/cmd/taskd/main.go
	// 시작 로그 한 줄. 무엇이 어떤 설정으로 떴는지가 여기 다 있다.
	logger.LogAttrs(ctx, slog.LevelInfo, "starting",
		slog.String("build", buildinfo.Read().Short()),
		slog.Any("config", cfg),
	)

실제 출력이다. 개행은 읽기 위해 넣은 것이고 실제로는 한 줄이다.

time=2026-08-13T13:35:02.315+09:00 level=INFO msg=starting
  build="dev (bb77c87) go1.26.5 darwin/arm64"
  config.env=dev config.server.addr=127.0.0.1:8080 config.server.admin_addr=127.0.0.1:6060
  config.server.handler_timeout=10s config.server.drain_delay=3s config.server.shutdown_grace=15s
  config.db.dsn="file:.../taskd.db?_pragma=busy_timeout(5000)" config.db.max_open_conns=25
  config.db.slow_query=200ms config.auth.secret=REDACTED config.auth.issuer=taskd
  config.auth.access_ttl=15m0s config.worker.concurrency=4 config.worker.poll=500ms
  config.worker.visibility=30s config.worker.max_attempts=5
  config.rate_limit.rps=20 config.rate_limit.burst=40
  config.log.level=INFO config.log.json=false

두 가지를 보라.

config.auth.secret=REDACTED. 설정을 통째로 찍었는데 시크릿은 안 나왔다. applog.Secret이 slog.LogValuer를 구현하기 때문이다(12-2). 이것을 테스트로도 못 박아 둔다.

examples/13-capstone/internal/config/config_test.go
	var buf bytes.Buffer
	applog.New(&buf, applog.Options{Stable: true}).Info("starting", "config", cfg)

	if strings.Contains(buf.String(), secret) {
		t.Errorf("시크릿이 로그에 새어 나왔다:\n%s", buf.String())
	}

build="dev (bb77c87) go1.26.5 darwin/arm64". -ldflags로 버전을 박지 않고 go run으로 띄웠는데도 커밋 해시가 나온다. runtime/debug.ReadBuildInfo()의 vcs.revision에서 온 것이다(12-6).

컨테이너에서는 JSON으로 나온다.

{"time":"2026-08-13T04:37:48.559527296Z","level":"INFO","msg":"starting","build":"v0.1.0 (bb77c87) go1.26.5 linux/arm64","config":{"env":"dev","server":{"addr":":8080","admin_addr":"127.0.0.1:6060",...},"auth":{"secret":"REDACTED","issuer":"taskd","access_ttl":"15m0s"},...}}

v0.1.0이 -ldflags로 박힌 값이다.

관리 포트​

서비스 포트와 관리 포트를 나눈다. 12-4에서 다룬 이유 그대로다 — pprof가 공개되면 /debug/pprof/profile을 반복 호출해 서비스를 느리게 만들 수 있고, 힙 프로파일에는 메모리에 있던 문자열의 흔적이 남는다.

examples/13-capstone/cmd/taskd/main.go
// adminMux는 관리 포트다. 절대 서비스 포트에 붙이지 않는다.
//
// pprof가 공개되면 /debug/pprof/profile을 반복 호출해 서비스를 느리게
// 만들 수 있고, 힙 프로파일에는 메모리에 있던 문자열의 흔적이 남는다.
// config.Validate가 addr과 admin_addr이 같은지 검사하는 이유다.
func adminMux(reg *health.Registry, level *slog.LevelVar) http.Handler {
	mux := http.NewServeMux()

	mux.Handle("GET /healthz", health.LivenessHandler())
	mux.Handle("GET /readyz", reg.ReadinessHandler())
	// 12-2 연습문제 1이 요구한 엔드포인트. 재배포 없이 로그 레벨을 바꾼다.
	mux.Handle("/admin/loglevel", applog.LevelHandler(level))

	mux.HandleFunc("/debug/pprof/", pprof.Index)
	mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
	mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
	mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
	mux.HandleFunc("/debug/pprof/trace", pprof.Trace)
	return mux
}

"실수로 같은 포트에 붙이는 것"은 설정으로도 막는다.

examples/13-capstone/internal/config/config.go
	if c.Server.Addr == c.Server.AdminAddr {
		errs = append(errs, fmt.Errorf("config: server.addr과 admin_addr이 같다 (%s). "+
			"관리 포트를 서비스 포트에 노출하면 pprof가 공개된다", c.Server.Addr))
	}

prod에서는 관리 포트가 루프백이어야 한다는 검증도 있다.

examples/13-capstone/internal/config/config.go
		if !strings.HasPrefix(c.Server.AdminAddr, "127.0.0.1:") {
			errs = append(errs, fmt.Errorf("config: prod에서 admin_addr은 루프백이어야 한다 (%s)", c.Server.AdminAddr))
		}

실제로 붙어 있는지 확인한다.

$ curl -s http://127.0.0.1:6060/healthz
ok

$ curl -s http://127.0.0.1:6060/readyz
{
  "ready": true,
  "details": {
    "db": "ok",
    "jobs": "ok"
  }
}

$ curl -s http://127.0.0.1:6060/debug/pprof/goroutine?debug=1 | head -1
goroutine profile: total 14

고루틴이 14개다. 워커 4개, 디스패처 1개, 리스너 2개, 그리고 런타임과 net/http가 쓰는 것들이다. 이 숫자를 알아 두는 것이 중요하다. 운영 중에 이 값이 계속 늘어나면 누수이고, 12-4에서 본 그 증상이다.

헬스체크는 무엇을 확인하고 무엇을 확인하지 않는가​

examples/13-capstone/cmd/taskd/main.go
	reg := health.New(2 * time.Second)
	reg.Register("db", func(ctx context.Context) error { return sqlDB.PingContext(ctx) })
	reg.Register("jobs", func(ctx context.Context) error {
		counts, err := store.CountByStatus(ctx)
		if err != nil {
			return err
		}
		// 이 검사가 확인하는 것은 "잡 테이블에 질의가 되는가"까지다.
		// 큐가 밀리는 것 자체는 레디니스 실패로 만들지 않는다. 트래픽을
		// 빼도 해결되지 않고, 오히려 큐를 비울 일꾼까지 빠지기 때문이다.
		// 그래서 개수는 읽고 버린다.
		_ = counts
		return nil
	})

큐가 밀리는 것을 레디니스 실패로 만들지 않는 것이 판단 지점이다. 트래픽을 빼도 큐는 안 줄어든다. 오히려 다른 인스턴스로 부하가 몰려 상황이 나빠진다. 큐 적체는 알림으로 다루지 헬스체크로 다루지 않는다.

jobs 검사가 남아 있는 이유는, DB에 쿼리를 하나 더 던져 보는 것 자체가 "읽기가 되는가"를 확인해 주기 때문이다. Ping은 커넥션만 본다.

정상 종료를 실제로 관찰한다​

12-8이 정한 순서가 코드에 그대로 있다.

examples/13-capstone/cmd/taskd/main.go
	// 1. 레디니스를 내린다. 로드밸런서가 이 인스턴스를 뺀다.
	reg.Drain()

	// 2. 로드밸런서가 알아챌 시간만큼 기다린다. 이 단계를 빠뜨리는 것이
	//    가장 흔한 실수이고, 배포할 때마다 짧은 502가 나는 원인이다.
	//    이미 라우팅이 결정된 요청이 아직 도착하지 않았을 수 있다.
	time.Sleep(cfg.Server.DrainDelay.D())

SIGTERM을 보내고 그 3초 사이에 헬스 엔드포인트를 찔러 보면 이렇다.

# 핸들러는 들여쓴 JSON을 주므로, 아래는 jq로 한 줄로 줄인 것이다.
$ curl -s http://127.0.0.1:6060/readyz | jq -c .        # 종료 전
{"ready":true,"details":{"db":"ok","jobs":"ok"}}

$ kill -TERM $PID

$ curl -s -o /dev/null -w '%{http_code}\n' http://127.0.0.1:6060/readyz
503
$ curl -s http://127.0.0.1:6060/readyz | jq -c .
{"ready":false,"details":{"status":"draining"}}

$ curl -s -o /dev/null -w '%{http_code}\n' http://127.0.0.1:6060/healthz
200

레디니스는 503, 라이브니스는 200. 이 조합이 정확히 우리가 원하는 것이다. 로드밸런서는 트래픽을 빼고, 오케스트레이터는 프로세스를 죽이지 않는다. 라이브니스까지 실패하면 SIGKILL이 날아와 배수가 무의미해진다.

로그로는 이렇게 보인다.

level=INFO msg="shutting down" cause="terminated signal received" by_signal=true
level=INFO msg="worker stopped" claimed=1 succeeded=1 retried=0 buried=0 panicked=0
level=INFO msg=stopped

첫 줄과 둘째 줄 사이가 3.003초였다. drain_delay가 3초이므로 예상한 값이다.

로그 레벨을 재시작 없이 바꾼다​

12-2 연습문제 1의 답이다. 장애를 보는데 debug 로그가 필요한 상황에서 재배포를 하면 문제 상황 자체가 사라진다.

$ curl -s http://127.0.0.1:6060/admin/loglevel
{"level":"INFO"}

$ curl -s -X PUT -d debug http://127.0.0.1:6060/admin/loglevel
{"level":"DEBUG"}

$ curl -s -w ' [%{http_code}]\n' -X PUT -d nonsense http://127.0.0.1:6060/admin/loglevel
{"error":"slog: level string \"nonsense\": unknown name","level":"DEBUG"}
 [400]

실패했을 때도 현재 레벨을 함께 돌려준다. 장애 중에 한 번 더 물어보지 않게 하려는 것이다. 바꾼 사실 자체도 로그에 남는다.

level=WARN msg="log level changed" level=DEBUG

컨테이너 이미지​

12-7의 멀티스테이지 빌드를 그대로 쓴다. CGO_ENABLED=0이 가능한 것은 SQLite 드라이버가 순수 Go이기 때문이다.

examples/13-capstone/Dockerfile
# CGO_ENABLED=0으로 정적 링크한다. distroless/static이 요구하는 조건이고,
# 이 서비스가 순수 Go SQLite 드라이버를 쓰기 때문에 가능하다.
#
# gorm.io/driver/sqlite가 mattn/go-sqlite3를 끌어오지만, CGO가 꺼져 있으면
# 그 패키지의 C 코드는 하나도 컴파일되지 않고 !cgo 스텁만 남는다. 스텁은
# sqlite3라는 이름으로만 등록되므로 modernc의 sqlite와 부딪히지 않는다.
# 실제로 쓰는 드라이버는 modernc.org/sqlite다.
ARG VERSION=dev
ARG COMMIT=none
ARG BUILD_TIME=unknown
RUN CGO_ENABLED=0 GOOS=linux go build \
      -trimpath \
      -ldflags "-s -w \
        -X example.com/capstone/internal/buildinfo.Version=${VERSION} \
        -X example.com/capstone/internal/buildinfo.Commit=${COMMIT} \
        -X example.com/capstone/internal/buildinfo.BuildTime=${BUILD_TIME}" \
      -o /out/taskd ./cmd/taskd

셸이 없으므로 헬스체크는 바이너리 자신을 부른다.

examples/13-capstone/Dockerfile
# 셸이 없으므로 HEALTHCHECK는 바이너리 자신을 부른다.
# CMD를 문자열로 쓰면 /bin/sh -c로 감싸려다 실패한다.
# 반드시 exec 형식(JSON 배열)이어야 한다.
HEALTHCHECK --interval=10s --timeout=3s --start-period=3s --retries=3 \
  CMD ["/taskd", "-healthcheck"]

-healthcheck 모드는 설정을 읽기 전에 처리한다.

examples/13-capstone/cmd/taskd/main.go
// healthcheck는 -healthcheck 모드다. Dockerfile의 HEALTHCHECK가 부른다.
//
// distroless 이미지에는 셸도 curl도 없다. 바이너리가 자기 자신을
// 헬스체크 클라이언트로도 쓸 수 있게 만들어 두면 그 문제가 사라진다.
func healthcheck(adminAddr string) error {

읽기 전용 루트 파일시스템을 가정해 DSN도 바꿔 둔다.

examples/13-capstone/Dockerfile
# 기본 DSN을 쓰기 가능한 경로로 바꾼다. 컨테이너의 루트 파일시스템은
# 읽기 전용으로 마운트하는 것이 보통이고, 그러면 작업 디렉터리에
# DB 파일을 만들 수 없다. 실제 운영에서는 SQLite가 아니라 외부 DB를 쓴다.
ENV TASKD_DB_DSN="file:/tmp/taskd.db?_pragma=busy_timeout(5000)&_pragma=journal_mode(WAL)"
ENV TASKD_LOG_JSON=true

빌드하고 재 봤다.

docker build -t taskd:demo --build-arg VERSION=v0.1.0 --build-arg COMMIT=bb77c87 .
docker images --format '{{.Repository}}:{{.Tag}}\t{{.Size}}' | grep -E 'distroless|taskd'
taskd:demo	42.6MB
gcr.io/distroless/static-debian12:nonroot	6.13MB

이미지 안의 바이너리를 꺼내 재면 26,542,242바이트(약 25.3 MiB)다.

:::note 이 크기 숫자에 대해 정직하게 6.13 + 25.3이 42.6이 아니다. Docker가 docker images에 보고하는 크기는 이 머신(Docker 29.5.2, containerd 이미지 저장소, arm64)에서 압축·비압축 계층을 어떻게 세느냐에 따라 달라진다. docker image inspect는 같은 이미지에 대해 10,606,130을 보고했다. --no-cache로 다시 빌드하면 10,606,288이 나오기도 한다 — 같은 소스, 같은 빌드 인자인데도 그렇다. 이 문단의 논지를 그 숫자가 스스로 증명한다.

절대값을 인용하지 말고 비교에 쓰라는 뜻이다. "distroless로 바꿨더니 golang:alpine 대비 몇 배 줄었다"는 유효한 비교이고, "우리 이미지는 42.6MB다"는 다음 사람이 다른 숫자를 보게 될 문장이다.

확실한 것은 하나다. 바이너리가 26.5MB이고 베이스가 그보다 작다. 이미지의 거의 전부가 우리 바이너리이고, 줄이려면 Go 쪽을 줄여야 한다. -s -w는 이미 붙어 있고, 다음 후보는 의존성 정리다. 다만 13-1에서 본 mattn/go-sqlite3는 후보가 아니다. CGO가 꺼져 있으면 그 패키지에서 남는 것은 함수 몇 개짜리 스텁뿐이라 지워도 줄어들 것이 없다. 크기를 지배하는 것은 실제로 쓰는 쪽 — GORM, Gin, modernc.org/sqlite다. :::

컨테이너를 띄우면 HEALTHCHECK가 실제로 동작한다.

$ docker run --rm -d --name taskd-demo -p 18080:8080 taskd:demo
$ docker ps --filter name=taskd-demo --format '{{.Status}}'
Up 4 seconds (health: starting)
...
Up 22 seconds (healthy)

빌드 정보도 확인한다.

$ docker run --rm --entrypoint /taskd taskd:demo -version
version:     v0.1.0
commit:      bb77c87
built:       unknown
go:          go1.26.5
module:      example.com/capstone
platform:    linux/arm64
cgo:         0
trimpath:    true
vcs.rev:     (없음)
vcs.time:    (없음)
vcs.dirty:   (없음)

cgo: 0과 trimpath: true가 우리가 의도한 대로다. vcs.rev가 비어 있는 것은 빌드 컨텍스트에 .git이 없어서다 — -buildvcs가 동작하려면 저장소가 필요하고, 그래서 COMMIT을 --build-arg로 따로 넘긴다. built: unknown은 --build-arg BUILD_TIME을 안 준 실행이라 그렇다.

:::tip 재현 가능한 빌드 BUILD_TIME에 date를 넣으면 같은 커밋을 두 번 빌드해도 다른 바이너리가 나온다. 12-6의 build.sh가 git show -s --format=%cI HEAD를 쓴 이유가 그것이다. CI에서도 같게 한다.

--build-arg BUILD_TIME="$(git show -s --format=%cI HEAD)"

:::

CI​

12-8의 파이프라인에 이 서비스에만 필요한 스텝 두 개를 더했다.

examples/13-capstone/ci.yml
      # 3. 마이그레이션 파일은 up/down이 반드시 짝이어야 한다.
      #    down이 없는 마이그레이션은 롤백할 수 없고, 그 사실을
      #    되돌려야 하는 순간에 알게 된다.
      - name: 마이그레이션 짝 확인
        run: |
          cd internal/gormstore/migrations
          for up in *.up.sql; do
            down="${up%.up.sql}.down.sql"
            if [ ! -f "$down" ]; then
              echo "짝이 없는 마이그레이션: $up"
              exit 1
            fi
          done
examples/13-capstone/ci.yml
      # 6. 테스트 + 커버리지.
      #    계층 규칙 테스트(internal/arch)가 여기서 돈다. 이것이
      #    이 파이프라인에서 가장 값싸게 큰 사고를 막는 스텝이다.
      - name: 테스트
        run: go test -count=1 -coverprofile=cover.out ./...

-race는 마지막에 따로 돈다. 워커 풀이 있는 서비스에서 생략할 수 없다.

examples/13-capstone/ci.yml
      # 7. 레이스 검출기. 느리므로 마지막에.
      #    워커 풀이 있는 서비스에서는 생략할 수 없다.
      - name: 레이스 검출
        run: go test -race -count=1 ./...

이미지 빌드도 CI에서 확인한다. Dockerfile이 깨져 있는 것을 배포 직전에 아는 것은 최악이다.

examples/13-capstone/ci.yml
      # 9. 이미지 빌드. Dockerfile이 실제로 도는지 확인한다.
      - name: 이미지 빌드
        run: |
          docker build -t taskd:ci \
            --build-arg VERSION="${GITHUB_REF_NAME}" \
            --build-arg COMMIT="$(git rev-parse --short HEAD)" \
            --build-arg BUILD_TIME="$(git show -s --format=%cI HEAD)" \
            .

부하를 걸고 프로파일을 읽는다​

여기서부터가 이 챕터의 본론이다. 12-4에서 프로파일 읽는 법을 배웠지만, 그때는 일부러 만든 부하였다. 이번에는 실제 서비스다.

부하를 주면서 15초짜리 CPU 프로파일을 뜬다.

# 요청 제한을 사실상 끄고 띄운다
TASKD_RATE_LIMIT_RPS=100000 TASKD_RATE_LIMIT_BURST=100000 TASKD_LOG_LEVEL=warn \
  ./taskd -addr 127.0.0.1:8080 -admin-addr 127.0.0.1:6060 &

# 프로파일을 뜨는 동안 할 일 4000개를 만든다 (동시 16)
go tool pprof -proto -output cpu.pb.gz \
  'http://127.0.0.1:6060/debug/pprof/profile?seconds=15' &
seq 1 4000 | xargs -P 16 -I{} curl -s -o /dev/null \
  -X POST -H "Authorization: Bearer $TOKEN" -H 'Content-Type: application/json' \
  -d '{"title":"부하 {}"}' http://127.0.0.1:8080/v1/tasks
go tool pprof -top -nodecount=15 taskd cpu.pb.gz
File: taskd
Type: cpu
Duration: 15.09s, Total samples = 2s (13.25%)
Showing nodes accounting for 1.91s, 95.50% of 2s total
      flat  flat%   sum%        cum   cum%
     1.06s 53.00% 53.00%      1.06s 53.00%  syscall.rawsyscalln
     0.30s 15.00% 68.00%      0.30s 15.00%  runtime.pthread_cond_signal
     0.17s  8.50% 76.50%      0.17s  8.50%  runtime.kevent
     0.16s  8.00% 84.50%      0.16s  8.00%  runtime.pthread_cond_wait
     0.08s  4.00% 88.50%      0.08s  4.00%  runtime.usleep
     0.02s  1.00% 89.50%      0.02s  1.00%  internal/runtime/atomic.(*UnsafePointer).Load
     0.02s  1.00% 90.50%      0.19s  9.50%  modernc.org/sqlite/lib._sqlite3MemMalloc
     0.02s  1.00% 91.50%      0.04s  2.00%  runtime.adjustframe
     0.02s  1.00% 92.50%      0.04s  2.00%  runtime.pcvalue
     0.01s   0.5% 93.00%      0.01s   0.5%  bytes.(*Buffer).WriteString

Total samples = 2s (13.25%)가 첫 번째 정보다. 15초 동안 CPU를 2초밖에 쓰지 않았다. 이 서비스는 CPU 바운드가 아니다. 프로파일에서 뭔가를 최적화하기 전에 이 숫자를 먼저 봐야 한다 — 13%밖에 안 쓰는 CPU를 20% 빠르게 만들어 봐야 전체는 거의 안 변한다.

syscall.rawsyscalln이 53%. 그 2초 중 절반이 시스템 콜이다. cum 뷰가 어디서 오는지 말해 준다.

go tool pprof -top -cum -nodecount=12 taskd cpu.pb.gz
      flat  flat%   sum%        cum   cum%
    1060ms 53.00% 53.00%     1060ms 53.00%  syscall.rawsyscalln
         0     0% 53.00%     1050ms 52.50%  syscall.syscalln
         0     0% 53.00%     1030ms 51.50%  net/http.(*conn).serve
         0     0% 53.00%      950ms 47.50%  database/sql.withLock
         0     0% 53.00%      900ms 45.00%  example.com/capstone/internal/httpapi.New.(*api).recovery.func5
         0     0% 53.00%      900ms 45.00%  github.com/gin-gonic/gin.(*Context).Next
         0     0% 53.00%      900ms 45.00%  modernc.org/sqlite/lib.Xsqlite3_step
         0     0% 53.00%      900ms 45.00%  modernc.org/sqlite/lib._sqlite3VdbeExec

읽으면 이렇다. 요청 처리 시간의 45%가 SQLite 안에 있고, 그 대부분이 시스템 콜이다. SQLite의 시스템 콜은 디스크 쓰기와 fsync다. 우리 Go 코드 — Gin 라우팅, JSON 인코딩, JWT 검증 — 는 프로파일에서 거의 보이지 않는다.

결론은 "최적화할 것이 없다"가 아니라 "최적화할 곳이 우리 코드가 아니다"다. 여기서 할 수 있는 일은 이런 것들이다.

  • 쓰기를 묶는다. 할 일 하나에 INSERT 두 개(할 일 + 잡)가 나가고 있다.
  • journal_mode(WAL)을 쓴다(이미 켜져 있다). synchronous=NORMAL도 후보다.
  • SQLite를 벗어난다. 실제 서비스라면 PostgreSQL이다.

Go 코드를 튜닝하는 것은 목록에 없다. 12-5에서 배운 sync.Pool이나 할당 줄이기를 여기 적용하면, 2초 중 0.1초를 아끼려고 코드를 어렵게 만드는 셈이다.

힙도 봤다.

go tool pprof -top -nodecount=5 -sample_index=inuse_space taskd \
  'http://127.0.0.1:6060/debug/pprof/heap'
Showing nodes accounting for 6047.08kB, 85.52% of 7071.12kB total
      flat  flat%   sum%        cum   cum%
 3596.27kB 50.86% 50.86%  3596.27kB 50.86%  runtime.mallocgc
  913.83kB 12.92% 63.78%  1425.84kB 20.16%  modernc.org/libc/honnef.co/go/netdb.init.0
  512.56kB  7.25% 71.03%   512.56kB  7.25%  compress/flate.newHuffmanEncoder
  512.34kB  7.25% 78.28%   512.34kB  7.25%  regexp.onePassCopy
  512.08kB  7.24% 85.52%  1024.42kB 14.49%  regexp.compile

힙 전체가 7MB다. 4000개 요청을 처리한 뒤에도. 그리고 그중 상당 부분이 init 시점 할당(netdb.init.0, regexp.compile)이다 — 요청과 무관하게 프로세스가 뜰 때 한 번 잡히는 메모리다.

메모리도 문제가 아니라는 뜻이고, GOMEMLIMIT을 고민할 이유가 없다.

:::warning 부하 생성기가 병목이면 측정이 아니다 같은 조건에서 2000개 요청을 재 보니 784 req/s가 나왔다. 이 숫자는 서비스의 처리량이 아니다. curl 프로세스를 2000번 띄우는 비용이 대부분이다.

xargs -P 16은 프로세스를 16개씩 fork하고, 각 curl은 TLS 없는 연결이라도 프로세스 생성·DNS·연결·종료를 매번 한다. 서버 쪽 프로파일이 "CPU를 13%밖에 안 썼다"고 말하는 것이 그 증거다.

진짜 처리량을 재려면 hey, wrk, vegeta 같은 도구를 쓴다. 연결을 재사용하고 동시성을 정확히 제어한다. 여기서 curl 루프를 쓴 이유는 "부하를 걸어 프로파일을 뜬다"는 절차를 보이기 위해서이지 숫자를 재기 위해서가 아니다. :::

프로파일이 실제로 답을 준 사례가 13-4에 있다. 잡 처리량이 초당 8건에서 멈춰 있던 문제인데, 그것은 프로파일이 아니라 지표로 찾았다. pending이 안 줄어드는 것을 보고 산수를 해서 원인을 알았다. 프로파일은 "CPU를 어디에 쓰는가"에 답하고, 그 문제는 CPU를 안 쓰는 문제였다.

측정 도구를 고르는 것도 기술이다. 느린 원인이 CPU면 프로파일, 대기면 지표와 추적, 락 경합이면 블록·뮤텍스 프로파일이다.

감시해야 할 숫자​

이 서비스에서 대시보드에 올릴 값들이다. 전부 이미 코드에 있다.

숫자어디서무엇을 뜻하는가
jobs.pending/v1/admin/jobs계속 늘면 워커가 죽었거나 처리량이 모자라다
jobs.dead/v1/admin/jobs0이 아니면 사람이 봐야 한다
worker.panicked종료 로그, Stats()0이어야 한다. 아니면 버그다
worker.retriedStats()갑자기 늘면 외부 의존성 장애다
고루틴 수/debug/pprof/goroutine단조 증가면 누수다
db.Stats().WaitCountdatabase/sql늘면 풀 고갈이다(12-8)
5xx 비율접근 로그499는 여기서 빠져 있어야 한다

마지막 줄이 13-3에서 한 일의 값이다. context.Canceled를 499로 빼 놓지 않으면 이 그래프가 사용자 이탈률을 따라 움직인다.

흔한 실수​

pprof를 서비스 포트에 노출한다. net/http/pprof를 빈 import하면 http.DefaultServeMux에 자동 등록된다. 설정 검증으로 막는다.

라이브니스에 DB를 넣는다. 재시작 폭풍이다(12-8).

큐 적체를 레디니스 실패로 만든다. 트래픽을 빼도 안 줄어든다.

배수 대기를 빼먹는다. 배포할 때마다 짧은 502가 난다.

이미지 크기를 절대값으로 인용한다. 도구와 버전에 따라 다른 숫자가 나온다.

BUILD_TIME에 date를 넣는다. 재현 가능한 빌드가 깨진다.

부하 생성기가 병목인 채로 측정한다. 서버 프로파일이 CPU를 안 쓰고 있으면 그 신호다.

프로파일에 없는 것을 최적화한다. CPU를 13% 쓰는 서비스에서 Go 코드를 튜닝하는 것.

CI에서 이미지를 안 빌드한다. 배포 직전에 Dockerfile이 깨진 것을 안다.

정리​

  • 기동 로그 한 줄이 "무엇이 어떤 설정으로 떴는가"에 답한다. 시크릿은 LogValuer가 가린다.
  • 관리 포트를 나눈다. pprof, 헬스체크, 로그 레벨. 설정 검증이 실수를 막는다.
  • 배수 중 레디니스 503, 라이브니스 200. 실제로 그렇게 나오는 것을 확인했다.
  • 로그 레벨을 재시작 없이 바꾼다. 실패해도 현재 값을 알려 준다.
  • CGO_ENABLED=0 + distroless. 순수 Go 드라이버라서 가능하다.
  • 이미지 크기는 비교에 쓰고 절대값으로 인용하지 않는다.
  • CPU 프로파일의 첫 정보는 Total samples 비율이다. 13%면 CPU가 문제가 아니다.
  • 느린 원인마다 도구가 다르다. 잡 처리량 문제는 프로파일이 아니라 지표가 찾았다.

회고 — 93개 챕터가 무엇이었나​

실제로 다룬 것​

파트 1~5는 언어다. 문법 자체보다 왜 그렇게 생겼는가에 시간을 썼다. 암묵적 형 변환이 없는 이유, 예외 대신 에러 값을 쓰는 이유, 제네릭이 늦게 온 이유. 슬라이스의 배열 공유, nil 맵 쓰기, 루프 변수 캡처와 Go 1.22의 변경, defer의 인자 평가 시점, 인터페이스에 담긴 nil 포인터 — 함정을 미루지 않고 그때그때 밟아 봤다.

파트 6~9는 도구와 표준 라이브러리다. 모듈, 워크스페이스, 동시성, 테스트, net/http. 이 구간에서 "Go 프로그램을 쓴다"에서 "Go 프로그램을 관리한다"로 넘어갔다.

파트 10~11은 생태계다. Gin과 Fiber를 비교하고, GORM을 쓰고, sqlc와 sqlx를 봤다. 11-7에서 처음으로 같은 인터페이스에 구현 두 개를 붙였고, 그 구조가 파트 13까지 그대로 왔다.

파트 12는 운영이다. 에러 정책, 구조화 로깅, 설정, 프로파일, 빌드, 컨테이너, 종료 절차. 파트 13은 그것들을 하나의 서비스로 합쳤고, 합치는 과정에서 파트 12 코드의 결함이 하나 드러났다(apperr가 net/http를 끌어오던 것).

그것이 캡스톤의 값이다. 조각으로 볼 때 맞아 보이던 것이 합쳐 보면 안 맞는다.

이 서비스에 남아 있는 것​

정직하게 적어 둔다. 예제라서 생략했거나, 일부러 안 한 것들이다.

  • 계정 저장소가 메모리다. 인터페이스는 있으니 GORM 구현을 붙이면 되지만 안 붙였다. 이 서비스의 주제가 아니어서다.
  • 리프레시 토큰 폐기 목록이 없다. 회전은 하지만 이전 토큰이 만료까지 유효하다.
  • 요청 제한이 프로세스 로컬이다. 인스턴스가 셋이면 허용량도 셋 배다.
  • 지표를 스크레이프할 엔드포인트가 없다. 잡 통계는 관리 API로만 볼 수 있고, Prometheus 형식으로 내보내지 않는다.
  • 분산 추적이 없다. 요청 ID는 있지만 OpenTelemetry는 안 붙였다.
  • SQLite다. 단일 프로세스 예제로는 훌륭하지만, 인스턴스 두 개 이상을 쓰는 순간 파일을 공유할 수 없다.

이 목록 자체가 다음 할 일 목록이기도 하다.

커리큘럼이 의도적으로 뺀 것​

  • gRPC와 protobuf. Go 생태계에서 큰 부분이지만, HTTP/JSON을 제대로 다루는 것이 먼저다. 계층을 나눠 뒀으므로 전송만 하나 더 붙이는 일이다.
  • OpenTelemetry. 관측성의 세 축(로그·지표·추적) 중 추적을 안 다뤘다. slog와 요청 ID로 갈 수 있는 데까지 갔다.
  • 쿠버네티스. 라이브니스·레디니스·배수·정상 종료는 다뤘지만 매니페스트는 안 썼다. Go 이야기가 아니라 인프라 이야기라서다.
  • unsafe, reflect, cgo. 라이브러리를 쓸 때 만나기는 하지만 직접 쓸 일이 드물고, 잘못 쓰면 위험하다.
  • 어셈블리와 컴파일러 내부. go tool compile -S로 인라이닝과 이스케이프를 확인하는 정도는 12-5에서 했다.
  • WASM, 모바일, 임베디드. 각각 별도의 책이다.

다음 학습 경로​

추상적인 조언 대신 구체적인 것만 적는다.

1. 표준 라이브러리를 읽는다 — 이 순서로​

Go 표준 라이브러리는 읽으라고 쓰인 코드다. 순서를 정해 두면 완주 확률이 오른다.

  1. errors (약 200줄). Is/As/Join이 어떻게 동작하는지 30분이면 다 읽는다. errors.AsType이 Go 1.26에 어떻게 들어갔는지도 볼 수 있다.
  2. sort와 slices. 제네릭 이전과 이후의 같은 문제 풀이를 나란히 볼 수 있다. slices.SortFunc의 pdqsort 구현은 알고리즘 공부로도 좋다.
  3. sync — Once, WaitGroup, Mutex 순서로. Mutex의 기아 방지 모드 주석이 특히 좋다.
  4. context (약 800줄). 파트 7에서 쓴 것의 실제 구현이다. WithCancel이 부모에 자신을 등록하는 방식, propagateCancel의 고루틴이 언제 필요한지.
  5. net/http의 server.go — 여기서부터 길다. conn.serve부터 읽는다. 우리가 만든 것의 아래층이 전부 여기 있다.
  6. log/slog의 handler.go. 12-2에서 ContextHandler를 직접 만들어 봤으니 commonHandler가 왜 그렇게 생겼는지 읽힌다.

읽는 방법: go doc -src <pkg>.<Func>가 가장 빠르다. 에디터에서 정의로 이동(gopls)해도 된다.

2. 이 서비스를 계속 키운다​

새 프로젝트를 시작하는 것보다 이것을 키우는 편이 배우는 것이 많다. 계층이 이미 나뉘어 있으므로 "어디에 넣을지"를 매번 판단하게 되고, 그 판단이 실력이다.

난이도 순으로.

  1. 계정 저장소를 GORM 구현으로 바꾼다. storetest와 같은 적합성 테스트를 먼저 쓴다. 두 시간짜리 작업이고, 계층 설계가 실제로 값을 하는지 확인된다.
  2. Prometheus 지표 엔드포인트를 붙인다. 위 표의 숫자들을 /metrics로 낸다. prometheus/client_golang을 쓴다. 관리 포트에 붙인다.
  3. PostgreSQL로 바꾼다. gormstore의 Claim을 SELECT ... FOR UPDATE SKIP LOCKED로 바꿔 보고, SQLite 버전과 성능을 비교한다. 드라이버 충돌 문제도 사라진다.
  4. 인스턴스를 두 개 띄운다. 그러면 요청 제한, 마이그레이션 동시 실행, 잡 중복 처리가 전부 진짜 문제가 된다. 13장에서 만든 방어들이 실제로 동작하는지 확인할 수 있다.
  5. OpenTelemetry를 붙인다. 요청 ID를 트레이스 ID로 바꾸고, HTTP 요청과 DB 쿼리와 잡 처리를 하나의 트레이스로 잇는다. 워커 쪽에서 트레이스 컨텍스트를 잡 페이로드로 나르는 부분이 재미있는 문제다.

3. 오픈소스에 기여한다​

Go 프로젝트는 기여 장벽이 낮은 편이다. 코드 스타일 논쟁이 거의 없고 (gofmt가 끝내 준다) 테스트 문화가 확립되어 있다.

시작하기 좋은 곳:

  • golang/go 자체의 문서와 에러 메시지. help wanted + Documentation 라벨을 본다. 표준 라이브러리 문서의 예제를 추가하는 것은 좋은 첫 기여이고, 그 과정에서 go test의 Example 함수 규약을 확실히 익힌다.
  • golangci-lint의 새 린터. 규칙 하나를 추가하는 것은 go/ast 공부다. 파트 13의 arch_test.go를 린터로 만드는 것도 좋은 주제다.
  • 당신이 쓰는 라이브러리. GORM, Gin, golang-migrate 전부 이슈가 쌓여 있다. 이미 쓰고 있어서 문제를 아는 것이 가장 큰 자산이다.

기여의 순서: 이슈를 재현하는 테스트를 먼저 쓴다 → 이슈에 그 테스트를 붙여 "재현했다"고 남긴다 → 고칠 수 있으면 PR을 낸다. 첫 단계만 해도 유지보수자에게는 큰 도움이고, 거절당할 일이 없다.

4. 읽을 것​

  • Go 블로그의 Go 1.x 릴리스 노트 — 6개월마다 나온다. 훑기만 해도 언어가 어디로 가는지 보인다.
  • golang/go 저장소의 design/ 제안서들. 제네릭, errors, slog가 왜 그 모양이 됐는지 논쟁 과정이 다 남아 있다. Go 커뮤니티의 사고방식을 배우는 가장 빠른 길이다.
  • Russ Cox의 글. 특히 모듈 시스템(vgo 시리즈)과 errors 설계에 관한 것.
  • go 명령어의 소스. cmd/go/internal/modload는 모듈 해석이 실제로 어떻게 동작하는지 알려 준다. 파트 6에서 배운 것의 구현이다.

마지막으로​

93개 챕터를 관통한 것이 하나 있다면, "왜 이렇게 생겼는가"를 묻는 습관이다. Go는 뺀 것이 많은 언어라서 그 질문의 답이 대체로 명확하고, 답을 알면 다음에 비슷한 결정을 내려야 할 때 기준이 생긴다.

이 파트에서 만든 서비스도 그렇다. 계층을 세 겹으로 한 것, 배치 크기를 워커 수와 분리한 것, context.Canceled를 499로 뺀 것 — 전부 답할 수 있는 이유가 있다. 그리고 이유를 댈 수 없는 결정이 코드에 남아 있다면, 그것이 다음에 볼 곳이다.

연습문제​

  1. /metrics 엔드포인트를 만들어 위 표의 숫자를 Prometheus 형식으로 내보내 보자. 외부 라이브러리 없이 텍스트를 직접 만드는 것으로 시작해도 된다 (형식이 아주 단순하다). 그다음 prometheus/client_golang으로 바꿔 보고, 직접 만든 것과 무엇이 다른지 비교해 보자. 특히 히스토그램을 직접 만들려고 하면 왜 라이브러리가 필요한지 알게 된다.

  2. 이 서비스를 인스턴스 두 개로 띄워 보자. SQLite 파일을 공유할 수 없으므로 PostgreSQL이 필요하다. 띄운 뒤 확인할 것: 잡이 중복 처리되는가? 마이그레이션이 동시에 돌면 무슨 일이 일어나는가? 요청 제한이 의도한 대로 동작하는가? 세 질문 중 지금 코드가 못 막는 것이 하나 있는데, 무엇인가?

  3. 이 서비스에 gRPC 인터페이스를 추가해 보자. 13-1 연습문제 3에서 설계만 했던 것을 실제로 만든다. internal/grpcapi 패키지를 새로 만들고, httpapi는 손대지 않고, task와 auth도 손대지 않는 것이 목표다. 손댈 수밖에 없는 부분이 나온다면 그것이 계층 설계의 빈틈이다 — 어디였는지 기록해 두자.