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