Go中http超时问题的排查及解决方法
背景
最新有同事反馈，服务间有调用超时的现象，在业务高峰期发生的概率和次数比较高。从日志中调用关系来看，有2个调用链经常发生超时问题。
问题1：A服务使用http1.1发送请求到B服务超时。
问题2:A服务使用一个轻量级http-sdk(内部http2.0)发送请求到C服务超时。
Golang给出的报错信息时：
Posthttp://host/v1/xxxx:net/http:requestcanceledwhilewaitingforconnection(Client.Timeoutexceededwhileawaitingheaders)
通知日志追踪ID来排查，发现有的请求还没到服务方就已经超时。
有些已经到服务方了，但也超时。
这里先排查的是问题2，下面是过程。
排查
推测
调用方设置的http请求超时时间是1s。
请求已经到服务端了还超时的原因，可能是：
- 服务方响应慢。通过日志排查确实有部分存在。
- 客户端调用花了990ms，到服务端只剩10ms，这个肯定会超时。
请求没到服务端超时的原因，可能是：
- golangCPU调度不过来。通过cpu监控排除这个可能性
- golang网络库原因。重点排查
排查方法：
本地写个测试程序，1000并发调用测试环境的C服务:
n:=1000
varwaitGroutp=sync.WaitGroup{}
waitGroutp.Add(n)
fori:=0;i
报错：
toomanyopenfiles//这个错误是笔者本机ulimit太小的原因，可忽略net/http:requestcanceled(Client.Timeoutexceededwhileawaitingheaders)
并发数量调整到500继续测试，还是报同样的错误。
连接超时
本地如果能重现的问题，一般来说比较好查些。
开始跟golang的源码，下面是创建httpClient的代码，这个httpClient是全局复用的。
funccreateHttpClient(hoststring,tlsArg*TLSConfig)(*http.Client,error){
httpClient:=&http.Client{
Timeout:time.Second,
}
tlsConfig:=&tls.Config{InsecureSkipVerify:true}
transport:=&http.Transport{
TLSClientConfig:tlsConfig,
MaxIdleConnsPerHost:20,
}
http2.ConfigureTransport(transport)
returnhttpClient,nil
}
//使用httpClient
httpClient.Do(req)
跳到net/http/client.go的do方法
func(c*Client)do(req*Request)(retres*Response,reterrerror){
ifresp,didTimeout,err=c.send(req,deadline);err!=nil{
}
}
继续进send方法，实际发送请求是通过RoundTrip函数。
funcsend(ireq*Request,rtRoundTripper,deadlinetime.Time)(resp*Response,didTimeoutfunc()bool,errerror){
rt.RoundTrip(req)
}
send函数接收的rt参数是个inteface，所以要从http.Transport进到RoundTrip函数。
其中log.Println("getConntime",time.Now().Sub(start),x)是笔者添加的日志，为了验证创建连接耗时。
varnint
//roundTripimplementsaRoundTripperoverHTTP.
func(t*Transport)roundTrip(req*Request)(*Response,error){
//检查是否有注册http2，有的话直接使用http2的RoundTrip
ift.useRegisteredProtocol(req){
altProto,_:=t.altProto.Load().(map[string]RoundTripper)
ifaltRT:=altProto[scheme];altRT!=nil{
resp,err:=altRT.RoundTrip(req)
iferr!=ErrSkipAltProtocol{
returnresp,err
}
}
}
for{
//n++
//start:=time.Now()
pconn,err:=t.getConn(treq,cm)
//log.Println("getConntime",time.Now().Sub(start),x)
iferr!=nil{
t.setReqCanceler(req,nil)
req.closeBody()
returnnil,err
}
}
}
结论：加了日志跑下来，确实有大量的getConntime超时。
疑问
这里有2个疑问：
- 为什么Http2没复用连接，反而会创建大量连接？
- 创建连接为什么会越来越慢？
继续跟getConn源码,getConn第一步会先获取空闲连接，因为这里用的是http2，可以不用管它。
追加耗时日志，确认是dialConn耗时的。
func(t*Transport)getConn(treq*transportRequest,cmconnectMethod)(*persistConn,error){
ifpc,idleSince:=t.getIdleConn(cm);pc!=nil{
}
//n++
gofunc(xint){
//start:=time.Now()
//deferfunc(xint){
//log.Println("getConndialConntime",time.Now().Sub(start),x)
//}(n)
pc,err:=t.dialConn(ctx,cm)
dialc<-dialRes{pc,err}
}(n)
}
继续跟dialConn函数，里面有2个比较耗时的地方：
连接建立，三次握手。
tls握手的耗时，见下面http2章节的dialConn源码。
分别在dialConn函数中t.dial和addTLS的位置追加日志。
可以看到，三次握手的连接还是比较稳定的，后面连接的在tls握手耗时上面，耗费将近1s。
2019/10/2314:51:41DialTime39.511194mshttps.Handshake1.059698795s2019/10/2314:51:41DialTime23.270069mshttps.Handshake1.064738698s2019/10/2314:51:41DialTime24.854861mshttps.Handshake1.0405369s2019/10/2314:51:41DialTime31.345886mshttps.Handshake1.076014428s2019/10/2314:51:41DialTime26.767644mshttps.Handshake1.084155891s2019/10/2314:51:41DialTime22.176858mshttps.Handshake1.064704515s2019/10/2314:51:41DialTime26.871087mshttps.Handshake1.084666172s2019/10/2314:51:41DialTime33.718771mshttps.Handshake1.084348815s2019/10/2314:51:41DialTime20.648895mshttps.Handshake1.094335678s2019/10/2314:51:41DialTime24.388066mshttps.Handshake1.084797011s2019/10/2314:51:41DialTime34.142535mshttps.Handshake1.092597021s2019/10/2314:51:41DialTime24.737611mshttps.Handshake1.187676462s2019/10/2314:51:41DialTime24.753335mshttps.Handshake1.161623397s2019/10/2314:51:41DialTime26.290747mshttps.Handshake1.173780655s2019/10/2314:51:41DialTime28.865961mshttps.Handshake1.178235202s
结论：第二个疑问的答案就是tls握手耗时
http2
为什么Http2没复用连接，反而会创建大量连接？
前面创建http.Client时，是通过http2.ConfigureTransport(transport)方法，其内部调用了configureTransport：
funcconfigureTransport(t1*http.Transport)(*Transport,error){
//声明一个连接池
//noDialClientConnPool这里很关键，指明连接不需要dial出来的，而是由http1连接升级而来的
connPool:=new(clientConnPool)
t2:=&Transport{
ConnPool:noDialClientConnPool{connPool},
t1:t1,
}
connPool.t=t2
//把http2的RoundTripp的方法注册到，http1上transport的altProto变量上。
//当请求使用http1的roundTrip方法时，检查altProto是否有注册的http2，有的话，则使用
//前面代码的useRegisteredProtocol就是检测方法
iferr:=registerHTTPSProtocol(t1,noDialH2RoundTripper{t2});err!=nil{
returnnil,err
}
//http1.1升级到http2的后的回调函数，会把连接通过addConnIfNeeded函数把连接添加到http2的连接池中
upgradeFn:=func(authoritystring,c*tls.Conn)http.RoundTripper{
addr:=authorityAddr("https",authority)
ifused,err:=connPool.addConnIfNeeded(addr,t2,c);err!=nil{
goc.Close()
returnerringRoundTripper{err}
}elseif!used{
goc.Close()
}
returnt2
}
ifm:=t1.TLSNextProto;len(m)==0{
t1.TLSNextProto=map[string]func(string,*tls.Conn)http.RoundTripper{
"h2":upgradeFn,
}
}else{
m["h2"]=upgradeFn
}
returnt2,nil
}
TLSNextProto在http.Transport->dialConn中使用。调用upgradeFn函数，返回http2的RoundTripper，赋值给alt。
alt会在http.Transport中RoundTripper内部检查调用。
func(t*Transport)dialConn(ctxcontext.Context,cmconnectMethod)(*persistConn,error){
pconn:=&persistConn{
t:t,
}
ifcm.scheme()=="https"&&t.DialTLS!=nil{
//没有自定义DialTLS方法，不会走到这一步
}else{
conn,err:=t.dial(ctx,"tcp",cm.addr())
iferr!=nil{
returnnil,wrapErr(err)
}
pconn.conn=conn
ifcm.scheme()=="https"{
//addTLS里进行tls握手，也是建立新连接最耗时的地方。
iferr=pconn.addTLS(firstTLSHost,trace);err!=nil{
returnnil,wrapErr(err)
}
}
}
ifs:=pconn.tlsState;s!=nil&&s.NegotiatedProtocolIsMutual&&s.NegotiatedProtocol!=""{
ifnext,ok:=t.TLSNextProto[s.NegotiatedProtocol];ok{
//next调用注册的升级函数
return&persistConn{t:t,cacheKey:pconn.cacheKey,alt:next(cm.targetAddr,pconn.conn.(*tls.Conn))},nil
}
}
returnpconn,nil
}
结论：
当没有连接时，如果此时来一大波请求，会创建n多http1.1的连接，进行升级和握手，而tls握手随着连接增加而变的非常慢。
解决超时
上面的结论并不能完整解释，复用连接的问题。因为服务正常运行的时候，一直都有请求的，连接是不会断开的，所以除了第一次连接或网络原因断开，正常情况下都应该复用http2连接。
通过下面测试，可以复现有http2的连接时，还是会创建N多新连接：
sdk.Request()//先请求一次，建立好连接，测试是否一直复用连接。
time.Sleep(time.Second)
n:=1000
varwaitGroutp=sync.WaitGroup{}
waitGroutp.Add(n)
fori:=0;i
所以还是怀疑http1.1升级导致，这次直接改成使用http2.Transport
httpClient.Transport=&http2.Transport{
TLSClientConfig:tlsConfig,
}
改了后，测试发现没有报错了。
为了验证升级模式和直接http2模式的区别。这里先回到升级模式中的addConnIfNeeded函数中，其会调用addConnCall的run函数：
func(c*addConnCall)run(t*Transport,keystring,tc*tls.Conn){
cc,err:=t.NewClientConn(tc)
}
run参数中传入的是http2的transport。
整个解释是http1.1创建连接后，会把传输层连接，通过addConnIfNeeded->run->Transport.NewClientConn构成一个http2连接。因为http2和http1.1本质都是应用层协议，传输层的连接都是一样的。
然后在newClientConn连接中加日志。
func(t*Transport)newClientConn(cnet.Conn,singleUsebool)(*ClientConn,error){
//log.Println("http2.newClientConn")
}
结论：
升级模式下，会打印很多http2.newClientConn，根据前面的排查这是讲的通的。而单纯http2模式下，也会创建新连接，虽然很少。
并发连接数
那http2模式下什么情况下会创建新连接呢？
这里看什么情况下http2会调用newClientConn。回到clientConnPool中，dialOnMiss在http2模式下为true，getStartDialLocked里会调用dial->dialClientConn->newClientConn。
func(p*clientConnPool)getClientConn(req*http.Request,addrstring,dialOnMissbool)(*ClientConn,error){
p.mu.Lock()
for_,cc:=rangep.conns[addr]{
ifst:=cc.idleState();st.canTakeNewRequest{
ifp.shouldTraceGetConn(st){
traceGetConn(req,addr)
}
p.mu.Unlock()
returncc,nil
}
}
if!dialOnMiss{
p.mu.Unlock()
returnnil,ErrNoCachedConn
}
traceGetConn(req,addr)
call:=p.getStartDialLocked(addr)
p.mu.Unlock()
}
有连接的情况下，canTakeNewRequest为false，也会创建新连接。看看这个变量是这么得来的：
func(cc*ClientConn)idleStateLocked()(stclientConnIdleState){
ifcc.singleUse&&cc.nextStreamID>1{
return
}
varmaxConcurrentOkaybool
ifcc.t.StrictMaxConcurrentStreams{
maxConcurrentOkay=true
}else{
maxConcurrentOkay=int64(len(cc.streams)+1)
为了查问题，这里加了详细日志。测试下来，发现是maxConcurrentStreams超了，canTakeNewRequest才为false。
在http2中newClientConn的初始化配置中,maxConcurrentStreams默认为1000：
maxConcurrentStreams:1000,//"infinite",perspec.1000seemsgoodenough.
但实际测下来，发现500并发也会创建新连接。继续追查有设置这个变量的地方：
func(rl*clientConnReadLoop)processSettings(f*SettingsFrame)error{
caseSettingMaxConcurrentStreams:
cc.maxConcurrentStreams=s.Val
//log.Println("maxConcurrentStreams",s.Val)
}
运行测试，发现是服务传过来的配置，值是250。
结论：服务端限制了单连接并发连接数，超了后就会创建新连接。
服务端限制
在服务端框架中，找到ListenAndServeTLS函数，跟下去->ServeTLS->Serve->setupHTTP2_Serve-
>onceSetNextProtoDefaults_Serve->onceSetNextProtoDefaults->http2ConfigureServer。
查到new(http2Server)的声明，因为web框架即支持http1.1也支持http2，所以没有指定任何http2的相关配置，都使用的是默认的。
//ServerisanHTTP/2server.
typehttp2Serverstruct{
//MaxConcurrentStreamsoptionallyspecifiesthenumberof
//concurrentstreamsthateachclientmayhaveopenata
//time.Thisisunrelatedtothenumberofhttp.Handlergoroutines
//whichmaybeactiveglobally,whichisMaxHandlers.
//Ifzero,MaxConcurrentStreamsdefaultstoatleast100,per
//theHTTP/2spec'srecommendations.
MaxConcurrentStreamsuint32
}
从该字段的注释中看出，http2标准推荐至少为100，golang中使用默认变量http2defaultMaxStreams，它的值为250。
真相
上面的步骤，更多的是为了记录排查过程和源码中的关键点，方便以后类似问题有个参考。
简化来说：
- 调用方和服务方使用http1.1升级到http2的模式进行通讯
- 服务方http2Server限制单连接并发数是250
- 当并发超过250，比如1000时，调用方就会并发创建750个连接。这些连接的tls握手时间会越来越长。而调用超时只有1s，所以导致大量超时。
- 这些连接有些没到服务方就超时，有些到了但服务方还没来得及处理，调用方就取消连接了，也是超时。
- 并发量高的情况下，如果有网络断开，也会导致这种情况发送。
重试
A服务使用的轻量级http-sdk有一个重试机制，当检测到是一个临时错误时，会重试2次。
Temporary()bool//Istheerrortemporary?而这个超时错误，就属于临时错误，从而放大了这种情况发生。
解决办法
不是升级模式的http2即可。
httpClient.Transport=&http2.Transport{
TLSClientConfig:tlsConfig,
}
为什么http2不会大量创建连接呢？
这是因为http2创建新连接时会加锁，后面的请求解锁后，发现有连接没超过并发数时，直接复用连接即可。所以没有这种情况，这个锁在clientConnPool.getStartDialLocked源码中。
问题1
问题1：A服务使用http1.1发送请求到B服务超时。
问题1和问题2的原因一样，就是高并发来的情况下，会创建大量连接，连接的创建会越来越慢，从而超时。
这种情况没有很好的办法解决，推荐使用http2。
如果不能使用http2，调大MaxIdleConnsPerHost参数，可以缓解这种情况。默认http1.1给每个host只保留2个空闲连接，来个1000并发，就要创建998新连接。
该调整多少，可以视系统情况调整，比如50，100。
总结
以上所述是小编给大家介绍的Go中http超时问题的排查及解决方法,希望对大家有所帮助，如果大家有任何疑问请给我留言，小编会及时回复大家的。在此也非常感谢大家对毛票票网站的支持！如果你觉得本文对你有帮助，欢迎转载，烦请注明出处，谢谢！
声明：本文内容来源于网络，版权归原作者所有，内容由互联网用户自发贡献自行上传，本网站不拥有所有权，未作人工编辑处理，也不承担相关法律责任。如果您发现有涉嫌版权的内容，欢迎发送邮件至：czq8825#qq.com（发邮件时，请将#更换为@）进行举报，并提供相关证据，一经查实，本站将立刻删除涉嫌侵权内容。