您当前的位置:首页 > 电脑百科 > 程序开发 > 语言 > Go语言

Go 中 http 超时问题的排查

时间:2019-12-09 16:18:54  来源:  作者:

Go 中 http 超时问题的排查

 

作者:蘑菇先生

出处:http://mushroom.cnblogs.com/

 

背景

最新有同事反馈,服务间有调用超时的现象,在业务高峰期发生的概率和次数比较高。从日志中调用关系来看,有2个调用链经常发生超时问题。

问题1:A 服务使用 http1.1 发送请求到 B 服务超时。

问题2: A 服务使用一个轻量级 http-sdk(内部 http2.0) 发送请求到 C 服务超时。

Golang 给出的报错信息时:

Post http://host/v1/xxxx: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)

通知日志追踪 ID 来排查,发现有的请求还没到服务方就已经超时。有些已经到服务方了,但也超时。这里先排查的是问题2,下面是过程。

排查

推测

调用方设置的 http 请求超时时间是1s。请求已经到服务端了还超时的原因,可能是:

  1. 服务方响应慢。通过日志排查确实有部分存在。
  2. 客户端调用花了990ms,到服务端只剩 10ms,这个肯定会超时。

请求没到服务端超时的原因,可能是:

  1. golang CPU 调度不过来。通过 cpu 监控排除这个可能性
  2. golang 网络库原因。重点排查

排查方法:

本地写个测试程序,1000 并发调用测试环境的 C 服务:

n := 1000
var waitGroutp = sync.WaitGroup{}
waitGroutp.Add(n)
for i := 0; i < n; i++ {
 go func(x int) {
 httpSDK.Request()
 }
}
waitGroutp.Wait()

 

报错:

too many open files // 这个错误是笔者本机ulimit太小的原因,可忽略
net/http: request canceled (Client.Timeout exceeded while awaiting headers)

并发数量调整到 500 继续测试,还是报同样的错误。
 

连接超时

本地如果能重现的问题,一般来说比较好查些。

开始跟 golang 的源码,下面是创建 httpClient 的代码,这个 httpClient 是全局复用的。

func createHttpClient(host string, 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)
 return httpClient, nil
}
// 使用httpClient
httpClient.Do(req)

跳到 net/http/client.go 的 do 方法

func (c *Client) do(req *Request) (retres *Response, reterr error) {
 if resp, didTimeout, err = c.send(req, deadline); err != nil {
 }
}

继续进 send 方法,实际发送请求是通过 RoundTrip 函数。

func send(ireq *Request, rt RoundTripper, deadline time.Time) (resp *Response, didTimeout func() bool, err error) {
 rt.RoundTrip(req) 
}

send 函数接收的 rt 参数是个 inteface,所以要从 http.Transport 进到 RoundTrip 函数。其中 log.Println("getConn time", time.Now().Sub(start), x) 是笔者添加的日志,为了验证创建连接耗时。

var n int
// roundTrip implements a RoundTripper over HTTP.
func (t *Transport) roundTrip(req *Request) (*Response, error) {
 // 检查是否有注册http2,有的话直接使用http2的RoundTrip
 if t.useRegisteredProtocol(req) {
 altProto, _ := t.altProto.Load().(map[string]RoundTripper)
 if altRT := altProto[scheme]; altRT != nil {
 resp, err := altRT.RoundTrip(req)
 if err != ErrSkipAltProtocol {
 return resp, err
 }
 }
 }
 for {
 //n++
 // start := time.Now()
 pconn, err := t.getConn(treq, cm)
 // log.Println("getConn time", time.Now().Sub(start), x)
 if err != nil {
 t.setReqCanceler(req, nil)
 req.closeBody()
 return nil, err
 }
 }
}

结论:加了日志跑下来,确实有大量的 getConn time 超时。

 

疑问

这里有2个疑问:

  1. 为什么 Http2 没复用连接,反而会创建大量连接?
  2. 创建连接为什么会越来越慢?

继续跟 getConn 源码, getConn 第一步会先获取空闲连接,因为这里用的是http2,可以不用管它。追加耗时日志,确认是 dialConn 耗时的。

func (t *Transport) getConn(treq *transportRequest, cm connectMethod) (*persistConn, error) {
 if pc, idleSince := t.getIdleConn(cm); pc != nil {
 }
 //n++
 go func(x int) {
 // start := time.Now()
 // defer func(x int) {
 // log.Println("getConn dialConn time", time.Now().Sub(start), x)
 // }(n)
 pc, err := t.dialConn(ctx, cm)
 dialc <- dialRes{pc, err}
 }(n)
}

继续跟 dialConn 函数,里面有2个比较耗时的地方:

  1. 连接建立,三次握手。
  2. tls握手的耗时,见下面 http2 章节的 dialConn 源码。

分别在 dialConn 函数中 t.dial 和 addTLS 的位置追加日志。可以看到,三次握手的连接还是比较稳定的,后面连接的在 tls 握手耗时上面,耗费将近 1s。

2019/10/23 14:51:41 DialTime 39.511194ms https.Handshake 1.059698795s
2019/10/23 14:51:41 DialTime 23.270069ms https.Handshake 1.064738698s
2019/10/23 14:51:41 DialTime 24.854861ms https.Handshake 1.0405369s
2019/10/23 14:51:41 DialTime 31.345886ms https.Handshake 1.076014428s
2019/10/23 14:51:41 DialTime 26.767644ms https.Handshake 1.084155891s
2019/10/23 14:51:41 DialTime 22.176858ms https.Handshake 1.064704515s
2019/10/23 14:51:41 DialTime 26.871087ms https.Handshake 1.084666172s
2019/10/23 14:51:41 DialTime 33.718771ms https.Handshake 1.084348815s
2019/10/23 14:51:41 DialTime 20.648895ms https.Handshake 1.094335678s
2019/10/23 14:51:41 DialTime 24.388066ms https.Handshake 1.084797011s
2019/10/23 14:51:41 DialTime 34.142535ms https.Handshake 1.092597021s
2019/10/23 14:51:41 DialTime 24.737611ms https.Handshake 1.187676462s
2019/10/23 14:51:41 DialTime 24.753335ms https.Handshake 1.161623397s
2019/10/23 14:51:41 DialTime 26.290747ms https.Handshake 1.173780655s
2019/10/23 14:51:41 DialTime 28.865961ms https.Handshake 1.178235202s

结论:第二个疑问的答案就是 tls 握手耗时

http2

为什么 Http2 没复用连接,反而会创建大量连接?前面创建 http.Client 时,是通过 http2.ConfigureTransport(transport) 方法,其内部调用了configureTransport :

func configureTransport(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就是检测方法
 if err := registerHTTPSProtocol(t1, noDialH2RoundTripper{t2}); err != nil {
 return nil, err
 }
 // http1.1 升级到http2的后的回调函数,会把连接通过 addConnIfNeeded 函数把连接添加到http2的连接池中
 upgradeFn := func(authority string, c *tls.Conn) http.RoundTripper {
 addr := authorityAddr("https", authority)
 if used, err := connPool.addConnIfNeeded(addr, t2, c); err != nil {
 go c.Close()
 return erringRoundTripper{err}
 } else if !used {
 go c.Close()
 }
 return t2
 }
 if m := t1.TLSNextProto; len(m) == 0 {
 t1.TLSNextProto = map[string]func(string, *tls.Conn) http.RoundTripper{
 "h2": upgradeFn,
 }
 } else {
 m["h2"] = upgradeFn
 }
 return t2, nil
}

TLSNextProto 在 http.Transport-> dialConn 中使用。调用upgradeFn函数,返回http2的RoundTripper,赋值给 alt。alt 会在 http.Transport 中 RoundTripper 内部检查调用。

func (t *Transport) dialConn(ctx context.Context, cm connectMethod) (*persistConn, error) {
 pconn := &persistConn{
 t: t,
 }
 if cm.scheme() == "https" && t.DialTLS != nil {
 // 没有自定义DialTLS方法,不会走到这一步
 } else {
 conn, err := t.dial(ctx, "tcp", cm.addr())
 if err != nil {
 return nil, wrapErr(err)
 }
 pconn.conn = conn
 if cm.scheme() == "https" {
 // addTLS 里进行 tls 握手,也是建立新连接最耗时的地方。
 if err = pconn.addTLS(firstTLSHost, trace); err != nil {
 return nil, wrapErr(err)
 }
 }
 }
 if s := pconn.tlsState; s != nil && s.NegotiatedProtocolIsMutual && s.NegotiatedProtocol != "" {
 if next, ok := t.TLSNextProto[s.NegotiatedProtocol]; ok {
 // next 调用注册的升级函数
 return &persistConn{t: t, cacheKey: pconn.cacheKey, alt: next(cm.targetAddr, pconn.conn.(*tls.Conn))}, nil
 }
 }
 return pconn, nil
}

结论:

当没有连接时,如果此时来一大波请求,会创建 n 多 http1.1 的连接,进行升级和握手,而 tls 握手随着连接增加而变的非常慢。
 

解决超时

上面的结论并不能完整解释,复用连接的问题。因为服务正常运行的时候,一直都有请求的,连接是不会断开的,所以除了第一次连接或网络原因断开,正常情况下都应该复用 http2 连接。

通过下面测试,可以复现有 http2 的连接时,还是会创建 N 多新连接:

sdk.Request() // 先请求一次,建立好连接,测试是否一直复用连接。
time.Sleep(time.Second)
n := 1000
var waitGroutp = sync.WaitGroup{}
waitGroutp.Add(n)
for i := 0; i < n; i++ {
 go func(x int) {
 sdk.Request()
 }
}
waitGroutp.Wait()

所以还是怀疑 http1.1 升级导致,这次直接改成使用 http2.Transport

httpClient.Transport = &http2.Transport{
 TLSClientConfig: tlsConfig,
}

改了后,测试发现没有报错了。

为了验证升级模式和直接 http2 模式的区别。这里先回到升级模式中的 addConnIfNeeded 函数中,其会调用 addConnCall 的 run 函数:

func (c *addConnCall) run(t *Transport, key string, 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(c net.Conn, singleUse bool) (*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, addr string, dialOnMiss bool) (*ClientConn, error) {
 p.mu.Lock()
 for _, cc := range p.conns[addr] {
 if st := cc.idleState(); st.canTakeNewRequest {
 if p.shouldTraceGetConn(st) {
 traceGetConn(req, addr)
 }
 p.mu.Unlock()
 return cc, nil
 }
 }
 if !dialOnMiss {
 p.mu.Unlock()
 return nil, ErrNoCachedConn
 }
 traceGetConn(req, addr)
 call := p.getStartDialLocked(addr)
 p.mu.Unlock()
 }

有连接的情况下,canTakeNewRequest 为false,也会创建新连接。看看这个变量是这么得来的:

func (cc *ClientConn) idleStateLocked() (st clientConnIdleState) {
 if cc.singleUse && cc.nextStreamID > 1 {
 return
 }
 var maxConcurrentOkay bool
 if cc.t.StrictMaxConcurrentStreams {
 maxConcurrentOkay = true
 } else {
 maxConcurrentOkay = int64(len(cc.streams)+1) < int64(cc.maxConcurrentStreams)
 }
 st.canTakeNewRequest = cc.goAway == nil && !cc.closed && !cc.closing && maxConcurrentOkay &&
 int64(cc.nextStreamID)+2*int64(cc.pendingRequests) < math.MaxInt32
 // if st.canTakeNewRequest == false {
 // log.Println("clientConnPool", cc.maxConcurrentStreams, cc.goAway == nil, !cc.closed, !cc.closing, maxConcurrentOkay, int64(cc.nextStreamID)+2*int64(cc.pendingRequests) < math.MaxInt32)
 // }
 st.freshConn = cc.nextStreamID == 1 && st.canTakeNewRequest
 return
}

为了查问题,这里加了详细日志。测试下来,发现是 maxConcurrentStreams 超了,canTakeNewRequest 才为 false。在 http2中newClientConn 的初始化配置中, maxConcurrentStreams 默认为 1000:

maxConcurrentStreams: 1000, // "infinite", per spec. 1000 seems good enough.

但实际测下来,发现 500 并发也会创建新连接。继续追查有设置这个变量的地方:

ffunc (rl *clientConnReadLoop) processSettings(f *SettingsFrame) error {
 case SettingMaxConcurrentStreams:
 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 的相关配置,都使用的是默认的。

// Server is an HTTP/2 server.
type http2Server struct {
 // MaxConcurrentStreams optionally specifies the number of
 // concurrent streams that each client may have open at a
 // time. This is unrelated to the number of http.Handler goroutines
 // which may be active globally, which is MaxHandlers.
 // If zero, MaxConcurrentStreams defaults to at least 100, per
 // the HTTP/2 spec's recommendations.
 MaxConcurrentStreams uint32
} 

从该字段的注释中看出,http2 标准推荐至少为 100,golang 中使用默认变量 http2defaultMaxStreams, 它的值为 250。
 

真相

上面的步骤,更多的是为了记录排查过程和源码中的关键点,方便以后类似问题有个参考。

简化来说:

  1. 调用方和服务方使用 http1.1 升级到 http2 的模式进行通讯
  2. 服务方 http2Serve r限制单连接并发数是 250
  3. 当并发超过 250,比如 1000 时,调用方就会并发创建 750 个连接。这些连接的tls握手时间会越来越长。而调用超时只有1s,所以导致大量超时。
  4. 这些连接有些没到服务方就超时,有些到了但服务方还没来得及处理,调用方就取消连接了,也是超时。

并发量高的情况下,如果有网络断开,也会导致这种情况发送。
 

重试

A服务使用的轻量级 http-sdk 有一个重试机制,当检测到是一个临时错误时,会重试 2 次。

Temporary() bool // Is the error temporary?

而这个超时错误,就属于临时错误,从而放大了这种情况发生。

解决办法

不是升级模式的 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。



Tags:Go   点击:()  评论:()
声明:本站部分内容及图片来自互联网,转载是出于传递更多信息之目的,内容观点仅代表作者本人,如有任何标注错误或版权侵犯请与我们联系(Email:2595517585@qq.com),我们将及时更正、删除,谢谢。
▌相关推荐
一. 配置yum源在目录 /etc/yum.repos.d/ 下新建文件 google-chrome.repovim /etc/yum.repos.d/google-chrome.repo按i进入编辑模式写入如下内容:[google-chrome]name=googl...【详细内容】
2021-12-23  Tags: Go  点击:(7)  评论:(0)  加入收藏
昨日谷歌宣布,自2022年12月19日开始停止对OnHub的软件支持,OnHub路由器仍将提供Wi-Fi信号,但用户无法用谷歌Home应用程序管理它。无法更新Wi-Fi网络设置、添加额外的Wifi设备或...【详细内容】
2021-12-22  Tags: Go  点击:(5)  评论:(0)  加入收藏
zip 是一种常见的归档格式,本文讲解 Go 如何操作 zip。首先看看 zip 文件是如何工作的。以一个小文件为例:(类 Unix 系统下)$ cat hello.textHello!执行 zip 命令进行归档:$ zip...【详细内容】
2021-12-17  Tags: Go  点击:(13)  评论:(0)  加入收藏
流水线(Pipeline)是把一个重复的过程分解为若干个子过程,使每个子过程与其他子过程并行进行的技术。本文主要介绍了诞生于云原生时代的流水线框架 Argo。 什么是流水线?在计算机...【详细内容】
2021-11-30  Tags: Go  点击:(21)  评论:(0)  加入收藏
大家好,我是 polarisxu。前段时间,Russ Cox 明确了泛型相关的事情,原计划在标准库中加入泛型相关的包,改放到 golang.org/x/exp 下。目前,Go 泛型的主要设计者 ianlancetaylor 完...【详细内容】
2021-11-30  Tags: Go  点击:(24)  评论:(0)  加入收藏
前言最近因为项目需要写了一段时间的 Go ,相对于 Java 来说语法简单同时又有着一些 Python 之类的语法糖,让人大呼”真香“。 但现阶段相对来说还是 Python 写的多一些,偶尔还...【详细内容】
2021-11-25  Tags: Go  点击:(29)  评论:(0)  加入收藏
前几节课我们学习了Django加载网页数据的相关知识,今天我们讲一下怎么加载静态文件,我们以加载图片为例,学习怎么配置静态文件。 1.思路讲解 首先我们需要新建文件(test2)作为我...【详细内容】
2021-11-23  Tags: Go  点击:(43)  评论:(0)  加入收藏
在本教程中,我们将介绍如何使用 Django 发送电子邮件。我们将介绍如何配置 Django SMTP 连接,如何为您的电子邮件提供商设置应用程序密码,以及如何通过 Django shell 发送电子...【详细内容】
2021-11-10  Tags: Go  点击:(22)  评论:(0)  加入收藏
golang context 很好用,就使用php实现了github地址 : https://github.com/qq1060656096/php-go-context context使用闭坑指南1. 将一个Context参数作为第一个参数传递给传入和...【详细内容】
2021-11-05  Tags: Go  点击:(41)  评论:(0)  加入收藏
谷歌宣布调整服务费费率,从明年起Google Play上所有付费订阅的抽成将从30%降低到15%。此外,电子书和点播音乐流媒体服务还将有资格享受低至10%的费率。此前,Google Play上的开...【详细内容】
2021-10-28  Tags: Go  点击:(38)  评论:(0)  加入收藏
▌简易百科推荐
zip 是一种常见的归档格式,本文讲解 Go 如何操作 zip。首先看看 zip 文件是如何工作的。以一个小文件为例:(类 Unix 系统下)$ cat hello.textHello!执行 zip 命令进行归档:$ zip...【详细内容】
2021-12-17  Go语言中文网    Tags:Go语言   点击:(13)  评论:(0)  加入收藏
大家好,我是 polarisxu。前段时间,Russ Cox 明确了泛型相关的事情,原计划在标准库中加入泛型相关的包,改放到 golang.org/x/exp 下。目前,Go 泛型的主要设计者 ianlancetaylor 完...【详细内容】
2021-11-30  Go语言中文网    Tags:slices 包   点击:(24)  评论:(0)  加入收藏
前言最近因为项目需要写了一段时间的 Go ,相对于 Java 来说语法简单同时又有着一些 Python 之类的语法糖,让人大呼”真香“。 但现阶段相对来说还是 Python 写的多一些,偶尔还...【详细内容】
2021-11-25  crossoverJie    Tags:Go   点击:(29)  评论:(0)  加入收藏
go-micro是基于 Go 语言用于开发的微服务的 RPC 框架,主要功能如下:服务发现,负载均衡 ,消息编码,请求/响应,Async Messaging,可插拔接口,最后这个功能牛p安装步骤安装proto...【详细内容】
2021-09-06    石老师小跟班  Tags:go-micro   点击:(197)  评论:(0)  加入收藏
GoLand 2021.2 EAP 5 现已发布。用户可以从工具箱应用程序中获得 EAP 构建,也可以从官方网站手动下载。并且从此 EAP 开始,只有拥有有效的 JetBrains 帐户才能加入该计划。手...【详细内容】
2021-06-29  IT实战联盟  今日头条  Tags:GoLand   点击:(185)  评论:(0)  加入收藏
作者:HDT3213今天给大家带来的开源项目是 Godis:一个用 Go 语言实现的 Redis 服务器。支持: 5 种数据结构(string、list、hash、set、sortedset) 自动过期(TTL) 发布订阅、地理位...【详细内容】
2021-06-18  HelloGitHub  今日头条  Tags:Go   点击:(125)  评论:(0)  加入收藏
统一规范篇合理规划目录本篇主要描述了公司内部同事都必须遵守的一些开发规矩,如统一开发空间,既使用统一的开发工具来保证代码最后的格式的统一,开发中对文件和代码长度的控制...【详细内容】
2021-05-18  1024课堂    Tags:Go语言   点击:(232)  评论:(0)  加入收藏
闭包概述 闭包不是Go语言独有的概念,在很多编程语言中都有闭包 闭包就是解决局部变量不能被外部访问的一种解决方案 是把函数当作返回值的一种应用 代码演示总体思想:在函数...【详细内容】
2021-05-14  HelloGo  今日头条  Tags:Go语言   点击:(223)  评论:(0)  加入收藏
一时想不开,想了解一下Go语言,于是安装了并体验了一下。下载1. 进入golang.google.cn 点击Download Go 2.选择对应的操作系统,点击后开始下载。 安装1. windows下执行傻瓜式安...【详细内容】
2021-05-12  程序员fearlazy  fearlazy  Tags:Go语言   点击:(237)  评论:(0)  加入收藏
1.简介channel是Go语言的一大特性,基于channel有很多值得探讨的问题,如 channel为什么是并发安全的? 同步通道和异步通道有啥区别? 通道为何会阻塞协程? 使用通道导致阻塞的协程...【详细内容】
2021-05-10  程序员麻辣烫  今日头条  Tags:Go通道   点击:(274)  评论:(0)  加入收藏
最新更新
栏目热门
栏目头条