레이블이 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

tags: , , , , comments: 0 4/01/2019

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() 가 호출된다.

tags: , , comments: 0 12/24/2018

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


tags: , , comments: 0 2/18/2016