레이블이 trace인 게시물을 표시합니다. 모든 게시물 표시
레이블이 trace인 게시물을 표시합니다. 모든 게시물 표시

vscode godef 느림 현상

# vscode go extension 는 godef 툴을 설치해 함수 정의 부분을 찾을 수 있다.
# godef 커맨드라인에서 사용
# godef 는 파일에서 찾을 단어(identifier)를 offset 으로 입력받는다.
# vscode show-offset extension 을 설치하면 상태바에 offset:xxx 로 확인할 수 있다.
# time 으로 수행시간 측정, godef -t 타입정보보기, -f 파일, -o 오프셋
time godef -t -f main.go -o 2214

# 위와 같이 커맨드를 사용하며 빠르게 위치를 출력해주지만
# vscode go to definition(정의로 가기, F12)에서는 3초가 걸린다.
# godef 수동으로 설치해보자
# gomodule 사용하는 경우 다음과 같이 설치하면 $GOPATH/bin/godef 가 생긴다.
GO111MODULE=on go get -u github.com/rogpeppe/godef

# 이제 vscode 정의로 가기하면 빨리 된다.
# godef 저장소에 에 go.mod가 있어서인지 GO111MODULE=on 으로 설치하면
# 새로운 godef 바이너리가 설치되면서 조금 빨라졌다.
# 하지만 1초가 넘어가는것이 아직도 좀 느리것 같다.
time godef -t -f main.go -o 2214
godef -t -f main.go -o 2214  1.15s user 0.58s system 313% cpu 0.552
total

# 같은 이슈인것 같은데 위 방법으로 해결되지 않는 경우가 있다.
# godef 는 내부적으로 go list 사용하고 여기서 시간을 많이 잡는것 같다.
# -trace 옵션으로 trace 파일을 만들고
time godef -t -f main.go -o 2214 -trace out.trace
# http://127.0.0.1:xxxx -> Syscall blocking profile 항목을 확인해보면
go tool trace out.trace
https://github.com/rogpeppe/godef/issues/114#issuecomment-478680734

golang pprof trace - request canceled

# golang client 에서 'request canceled' 로 커넥션자체가 안되는 경우가 발생한다.
# net/http/transport.go 에 다음과 같이 정의 되어 있다.
var errRequestCanceled = errors.New("net/http: request canceled")

# 찾아보면 위 에러가 발생할 수 있는 경우는 다음과 같다.
net/http/transport.go:2024 -> roundTrip() 에서 reqcanceler 를  replace 하다 실패하는 경우
net/http/transport.go:601 -> CancelRequest() 로 호출되는 경우

# 우선 프로그램 내부 상태 파악을 위해 네트워크 타임아웃 프로파일링을 해보자.
# 참고 https://yoonbh2714.blogspot.com/2016/02/golang-pprof_47.html
# golang trace 2초 덤프를 2초 간격으로 100개 생성해본다.
#!/bin/bash
for cnt in {1..100}
do
    curTime=$(date +%H:%M:%S)
    sleep 
    curl 'http://localhost:9000/debug/pprof/trace?seconds=2' -o trace${cnt}-${curTime}.out
done

# 생성된 덤프파일을 하나씩 열어
go tool trace trace1-xx:xx:xx.out

# Goroutine analysis -> 네트워크를 사용하는 함수 선택하면 다음과 같이 해당 함수를 여러개의 고루틴들이 수행중이였음을 보여준다.
# 참고로 아래 캡쳐 화면중 빈 공간은 비공개 내용으로 삭제처리함


# 이중 timeout(>1000ms)을 넘는 루틴을 클릭해보면 다음과 같은 타임라인이 보이고
# 화살표로 보고 싶은 타임라인의 영역 드래그하면 아래 해당 영역에서 사용중인 함수리스트가 보인다.


# 문제가 되는 setRequestCancel 함수를 클릭 -> incoming flow go(link) 에서 스택을 확인할 수 있다.



# 위 스택을 보면 net/http/client.go:248 에서 다음과 같이 setRequest 를 호출하고 있고
stopTimer, didTimeout := setRequestCancel(req, rt, deadline)

# net/http/client.go:320 에서 다음과 같이 고루틴에서 timeOut 이 발생할 수 있다.
go func() {
    select {
    case <-initialReqCancel:
        doCancel()
        timer.Stop()
    case <-timer.C:
        timedOut.setTrue()
        doCancel()
    case <-stopTimerCh:
        timer.Stop()
    }
}()

# doCancel() -> CancelRequest() 가 호출된다.

golang panic trace

# golang 에서 panic 발생시 recover 에 다음 함수들로
debug.Stack() []byte
debug.PrintStack()

# 스택 정보를 파악할 수 있다.
goroutine 1 [running]:
runtime/debug.Stack(0x275, 0x0, 0x0)
/usr/local/Cellar/go/1.10.3/libexec/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
/usr/local/Cellar/go/1.10.3/libexec/src/runtime/debug/stack.go:16 +0x22
main.makePanicAndRecover.func1()
/Users/ysoftman/workspace/test_code/golang/panic_recover/panic_recover.go:48 +0x3e1
panic(0x10a98c0, 0x113a400)
/usr/local/Cellar/go/1.10.3/libexec/src/runtime/panic.go:502 +0x229
main.makePanicAndRecover(0x1, 0x0)
/Users/ysoftman/workspace/test_code/golang/panic_recover/panic_recover.go:54 +0x194
main.main()
/Users/ysoftman/workspace/test_code/golang/panic_recover/panic_recover.go:17 +0xb7
runtime error: integer divide by zero

# 맨줄의 숫자는 고루틴에 부여되는 특정 이름(id)로 보인다.
# 다음과 같은 코드에서 첫번재, 두번째는 같은 goroutine id 로 표시되고, 나머지 go루틴 2개는 각각 다른 id 로 표시된다.
debug.PrintStack()
debug.PrintStack()
go func() {
debug.PrintStack()
}()
go func() {
debug.PrintStack()
}()

# GOTRACEBACK 의 레벨에 따라 스택 출력 내용이 달라진다. (go env 에선 안보임)
# GOTRACEBACK=none 모든 고루틴 스택 내용 출력 안함
# GOTRACEBACK=single 패닉 발생 고루린 스택만 출력
# GOTRACEBACK=all 현재돌고 있는 사용자 고루틴 모두 (default)
# GOTRACEBACK=system 시스템을 사용하는 고루틴 모두 출력
# GOTRACEBACK=crash 크래시 발생
# 실행)
# env GOTRACEBACK=all go run panic_recover.go

# 참고
# stack trace 정보 설명
https://www.ardanlabs.com/blog/2015/01/stack-traces-in-go.html
# https://golang.org/pkg/runtime/
# https://dave.cheney.net/tag/gotraceback

golang pprof 사용하기

# golang 에서의 pprof 프로파일링 패키지를 사용해서 코드를 점검할 수 있다.
# 사용하기 위해서는 패키지와 웹리스너용 고루틴 하나 추가하면 된다.
// ysoftman
// pprof 사용 테스트
package main

import (
"fmt"
"log"
"net/http"
_ "net/http/pprof"
"time"
)

func main() {
go func() {
log.Println(http.ListenAndServe("localhost:6060", nil))
}()
for {
time.Sleep(100 * time.Millisecond)
fmt.Println("ysoftman")
}
select {}
}

# pprof.go init()에 이미 다음과 핸들러 들이 등록되 있어 별도로 등록하지 않아도 된다.
func init() {
http.Handle("/debug/pprof/", http.HandlerFunc(Index))
http.Handle("/debug/pprof/cmdline", http.HandlerFunc(Cmdline))
http.Handle("/debug/pprof/profile", http.HandlerFunc(Profile))
http.Handle("/debug/pprof/symbol", http.HandlerFunc(Symbol))
http.Handle("/debug/pprof/trace", http.HandlerFunc(Trace))
}

# 만약 별도 선언 후 /debug/pprof/trace 등 사용시 404 NOT FOUND 가 발생한다면
# 다음과 같이 pprof.Trace 등을 사용하도록 해야 한다.
r.HandleFunc("/pprof/cmdline", pprof.Cmdline)
r.HandleFunc("/pprof/symbol", pprof.Symbol)
r.HandleFunc("/pprof/profile", pprof.Profile)
r.HandleFunc("/pprof/trace", pprof.Trace)
...

# 이제 프로그램을 실행시키고 다음 url 로 접속하면 기본적으로
# block, goroutine, heap, threadcreate 등의 정보를 파악할 수 있다.
http://localhost:6060/debug/pprof/

# heap pprof 수행
# pprof 명령은 help 로 파악할 수 있다.
# -http=:9999 를 사용하면 웹(브라우저로 볼 수 있다.)
go tool pprof http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /Users/ysoftman/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.009.pb.gz
Type: inuse_space
Time: Apr 9, 2019 at 4:48pm (KST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 514.63kB, 100% of 514.63kB total
      flat  flat%   sum%        cum   cum%
  514.63kB   100%   100%   514.63kB   100%  math/rand.NewSource
         0     0%   100%   514.63kB   100%  math/rand.init.ializers
         0     0%   100%   514.63kB   100%  runtime.main
(pprof) exit

# 5초(디폴트30초)간 cpu 프로파일링
go tool pprof http://localhost:6060/debug/pprof/profile?seconds=5
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=5
Please wait... (5s)
Saved profile in /Users/ysoftman/pprof/pprof.samples.cpu.004.pb.gz
Type: cpu
Time: Apr 9, 2019 at 4:55pm (KST)
Duration: 5s, Total samples = 0
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) exit

# 위에서 저장된 프로파일링 파일을 다시 웹으로 볼 수 있다.
go tool pprof -http=:9999 /Users/ysoftman/pprof/pprof.samples.cpu.004.pb.gz

# 또는 go tool 을 이용해 콘솔에서 프로파일링할 수 있다.
# 5초동안 트레이스 덤프
curl 'http://localhost:6060/debug/pprof/trace?seconds=5' -o trace.out

# 트레이스 덤프 보기, http://127.0.0.1:xxxx 로 확인
go tool trace trace.out

# 힙 메모리 덤프
curl 'http://localhost:6060/debug/pprof/heap' -o heap.out

# 힙 메모리중 가장 많이 사용하 부분 보기
go tool pprof heap.out
(pprof) top

# golang 1.11 pprof 부터 flamegrpah 로 볼 수 있다.
go tool pprof -http=:8080 heap.out 으로 웹페이지 띄우고 view -> flame graph


#####

# gin web framework 사용시는 다음과 같이 사용한다.
# timeoutmiddleware 등이 설정되어 있다면 /debug/pprof 경로는 타임아웃대상에서 예외 처리하자.
import "github.com/gin-contrib/pprof"
func main() {
  router := gin.Default()

  pprof.Register(router, "/debug/pprof")
  // 또는 pprof 접근을 admin 으로 제한하고 싶을때
  adminGroup := router.Group("/admin", func(c *gin.Context) {
    if c.Request.Header.Get("Authorization") != "foobar" {
      c.AbortWithStatus(http.StatusForbidden)
      return
    }
    c.Next()
  })
  pprof.RouteRegister(adminGroup, "pprof")

  router.Run(":8080")
}

# 프로파일링 및 결과 보기
curl 'http://localhost:8080/debug/pprof/heap?seconds=10' -o heap.out
go tool pprof -http=:9090 heap.out

curl 'http://localhost:8080/debug/pprof/profile?seconds=10' -o profile.out
go tool pprof -http=:9090 profile.out