[golang] HTTP 서버 프로파일링 하는법 (gin 서버 profiling하는 법

앞 글에서 profiling이 무엇인지에 대해서 알아보았다. profiling이 어떤건지 감이 아직 안잡힌 독자는 아래 글을 읽어보고 오는 것을 추천한다.

 

https://etloveguitar.tistory.com/147

[golang] profile 간단 이해(profiling, 프로파일링에 대하여)

 

 

 

특정 코드를 정해두고 프로파일링을 진행하는 경우도 있지만, 실제로 동작하고 있는 웹서버에 대한 프로파일링이 필요할 때가 있다. 따라서 본 글에서는 프로파일링이 무엇인지 안다는 전제 하에 pprof 패키지의 API를 활용해 현재 동작하고 있는 서버에 대한 live profile을 얻어낼 수 있는 방법에 집중하겠다. 사실 prod 환경에서 동작하고 있는 live 웹서버를 프로파일링 하는건 상당히 위험하다. 정말 급박한 상황(도무지 비슷한 부하를 넣어볼 수 없다거나)이 아니고서야 해선 안된다. 필자는 perf환경에서 prod환경과 최대한 환경과 비슷한 부하를 넣어가며 테스트를 했다. 

 

우선 live profile를 얻어내기 위해서는 기본적으로 net/http/pprof를 import해야 한다.

import _ "net/http/pprof"

위와 같이 import하고 나면 아래서 필요한 profile들에 대한 init이 수행된다.

func init() {
    http.HandleFunc("/debug/pprof/", Index)
    http.HandleFunc("/debug/pprof/cmdline", Cmdline)
    http.HandleFunc("/debug/pprof/profile", Profile)
    http.HandleFunc("/debug/pprof/symbol", Symbol)
    http.HandleFunc("/debug/pprof/trace", Trace)
}

위에서 확인할 수 있듯이, DefaultServerMux에 profiling에 필요한 handler들을 등록하고 있고,

따라서 HTTP server를 하나 실행하기만 하면, DefaultServerMux에 등록된 Handler를 통해 profile를 다운받을 수 있게 된다.

 

참고로 만약 DefaultServeMux를 사용하지 않는다고 하면, 직접 mux에 Handler를 다음과 같이 등록해주어야 한다. mymux.HandleFunc("…", pprof.Index) 아니면 그냥 별개의 port에서 default mux를 사용하는 서버를 하나 더 실행하는 방법도 있다.

 

추가로 gin을 사용하는 경우 [github.com/gin-contrib/pprof](http://github.com/gin-contrib/pprof) 에서 제공하는 Register를 사용해, DefaultServerMux에 등록된 profiling 관련 handler들을 해당 gin Engine에 등록할 수 있다.

// Register the standard HandlerFuncs from the net/http/pprof package with
// the provided gin.Engine. prefixOptions is a optional. If not prefixOptions,
// the default path prefix is used, otherwise first prefixOptions will be path prefix.
pprof.Register(g)

• 자세한 예제는 https://github.com/gin-contrib/pprof 여기 참고

 

 

예제 서버 실행

필자는 gin을 주로 사용하기 때문에, gin을 활용해서 기본 서버를 한번 실행해보도록 하겠다. 사실 실제 사용할 때는 http 패키지에서 서버를 생성하고 gin으로 래핑하는 방식을 주로 사용하지만, 본 글에서는 프로파일링을 어떻게 하는지에 대해 설명하기 때문에 해당 부분은 생략했다. 

package main

import (
    "bytes"
    "encoding/json"
    "fmt"
    "io"
    "math/rand"
    "net/http"
    "time"

    "github.com/gin-contrib/pprof"
    "github.com/gin-gonic/gin"
)

func logHandler(c *gin.Context) {
    ch := make(chan int)

    go func() {
        obj := make(map[string]interface{})
        body, err := c.GetRawData()
        // body, err := c.Request.GetBody()
        if err != nil {
            fmt.Println("err", err)
        }
        bodyReader := io.NopCloser(bytes.NewBuffer(body))
        if err := json.NewDecoder(bodyReader).Decode(&obj); err != nil {
            fmt.Println("decode error", err, string(body))
            ch <- http.StatusBadRequest
            return
        }
        // simulation of a time consuming process like writing logs into db
        time.Sleep(time.Duration(rand.Intn(400)) * time.Millisecond)
        ch <- http.StatusOK
    }()

    select {
    case status := <-ch:
        c.Writer.WriteHeader(status)

    case <-time.After(200 * time.Millisecond):
        c.Writer.WriteHeader(http.StatusRequestTimeout)
    }
}

func main() {
    router := gin.Default()
    pprof.Register(router)
    router.POST("/log", logHandler)
    router.Run(":8080")
}

 

위와 같이 실행하고 간단하게 hey라는 툴을 호 부하를 살짝 넣어보자

hey -n 10 -c 2 -m POST -T "application/json" -d '{"username":1,"message":"hello"}' http://localhost:8080/log

실행후에 브라우저에서

http://localhost:8080/debug 를 실행해보면 아래와 같은 화면을 볼 수 있다.

 

위 화면에서 하나하나 눌러보면서 실시간으로 확인하는 방법도 있지만 알개와 같이 pprof tool을 설치해서 직접 사용해볼 수도 있다.

일단 pprof를 설치하자

go get -u github.com/google/pprof

Interactive mode로 보는 법

pprof -alloc_objects http://:8080/debug/pprof/allocs

위 커맨드를 실행하면, interactive shell에 들어가서, pprof 명령어를 입력하면 report를 출력할 수 있다.

 

예를 들어 아래는 CPU profiling에 대한 예시인데, top 을 실행하면, top cpu consumer를 확인할 수 있다.

(pprof) top
Showing nodes accounting for 25.58s, 99.46% of 25.72s total
Dropped 25 nodes (cum <= 0.13s)
Showing top 10 nodes out of 23
      flat  flat%   sum%        cum   cum%
    16.87s 65.59% 65.59%     16.87s 65.59%  main.getExchangeRate
     6.15s 23.91% 89.50%      6.15s 23.91%  runtime.memclrNoHeapPointers
     2.03s  7.89% 97.40%      2.03s  7.89%  runtime.nanotime
     0.24s  0.93% 98.33%      0.24s  0.93%  main.getRatePerNight
     0.21s  0.82% 99.14%      0.21s  0.82%  runtime.(*mspan).init (inline)
     0.07s  0.27% 99.42%     23.62s 91.84%  main.getTurnover
     0.01s 0.039% 99.46%      6.44s 25.04%  runtime.growslice
         0     0% 99.46%     23.63s 91.87%  main.main
         0     0% 99.46%      6.42s 24.96%  runtime.(*mcache).nextFree
         0     0% 99.46%      6.42s 24.96%  runtime.(*mcache).nextFree.func1

 

참고로 아래와 같은 SVG 그래프를 그려보고 싶다면, 앞 글의 (2)번 부분을 읽어보길 바란다.

 

자 이렇게 실제 동작하고 있는 HTTP 서버를 프로파일링 하는 방법에 대해서 알아보았다. 이제 성능 개선을 해볼 시간이다~