AlexStocks / getty

a netty like asynchronous network I/O library based on tcp/udp/websocket; a bidirectional RPC framework based on JSON/Protobuf; a microservice framework based on zookeeper/etcd
Apache License 2.0
886 stars 184 forks source link

当compress_encoding设置成false,会出现i/o timeout的问题 #14

Open hxmhlt opened 5 years ago

hxmhlt commented 5 years ago

将compress_encoding设置成false,tcp_read_timeout设置成5s。 经过debug发现,conn.go line 252会返回read tcp xxx:xxx->xxx:xxx: i/o timeout的错误。实际的read时间,大概只有2s多一点,并不是tcp_read_timeout设置的5s。

63isOK commented 2 years ago

@AlexStocks 大佬,tcp写超时设置为30s,同样是compress_encoding: false, 也出现了timeout,实际上从调用到报超时,1ms也没有,请问一下,这个是什么原因,该如何修改,麻烦给个思路.

AlexStocks commented 2 years ago

@AlexStocks 大佬,tcp写超时设置为30s,同样是compress_encoding: false, 也出现了timeout,实际上从调用到报超时,1ms也没有,请问一下,这个是什么原因,该如何修改,麻烦给个思路.

你加我钉钉群没有?我们可以在钉钉群 23331795 交流下

fingthinking commented 2 years ago

@AlexStocks 大佬,这个问题有没有相关的分析呀,求指点一下。我们准备现在也遇到这个现象了,暂时未明确原因。

Lvnszn commented 2 years ago

@AlexStocks 大佬,这个问题有没有相关的分析呀,求指点一下。我们准备现在也遇到这个现象了,暂时未明确原因。

你用的是什么版本的呀?

AlexStocks commented 2 years ago

@AlexStocks 大佬,这个问题有没有相关的分析呀,求指点一下。我们准备现在也遇到这个现象了,暂时未明确原因。

github.com/apache/dubbo-getty 试试这个分支,看看还有没有这个现象

fingthinking commented 2 years ago

@AlexStocks 大佬,这个问题有没有相关的分析呀,求指点一下。我们准备现在也遇到这个现象了,暂时未明确原因。

你用的是什么版本的呀?

@AlexStocks 大佬,这个问题有没有相关的分析呀,求指点一下。我们准备现在也遇到这个现象了,暂时未明确原因。

github.com/apache/dubbo-getty 试试这个分支,看看还有没有这个现象

当前使用的版本是: github.com/apache/dubbo-getty v1.4.3

AlexStocks commented 2 years ago

@AlexStocks 大佬,这个问题有没有相关的分析呀,求指点一下。我们准备现在也遇到这个现象了,暂时未明确原因。

你用的是什么版本的呀?

可能的原因就是上次说的,session 的 wLastDeadline 和 rLastDeadline 这些成员没有加锁保护。

AlexStocks commented 2 years ago

@AlexStocks 大佬,这个问题有没有相关的分析呀,求指点一下。我们准备现在也遇到这个现象了,暂时未明确原因。

你用的是什么版本的呀?

@AlexStocks 大佬,这个问题有没有相关的分析呀,求指点一下。我们准备现在也遇到这个现象了,暂时未明确原因。

github.com/apache/dubbo-getty 试试这个分支,看看还有没有这个现象

当前使用的版本是: github.com/apache/dubbo-getty v1.4.3

你进钉钉群 23331795,然后 at 我【群主 于雨】,我们聊下。

fingthinking commented 2 years ago

问题分析:

type gettyConn struct {
 // 其他field忽略
 rTimeout      time.Duration // network current limiting
 wTimeout      time.Duration
 rLastDeadline time.Time // lastest network read time
 wLastDeadline time.Time // lastest network write time
}
// 在dubbo-go的实现中,每一次写操作会更新设置wTimeout的值,即调用改方法
func (c *gettyConn) SetWriteTimeout(wTimeout time.Duration) {
 if wTimeout < 1 {
  panic("@wTimeout < 1")
 }

 c.wTimeout.Store(wTimeout)
 if c.rTimeout.Load() == 0 {
  c.rTimeout.Store(wTimeout)
 }
}
// tcp connection write
func (t *gettyTCPConn) send(pkg interface{}) (int, error) {
 // 仅保留问题的关键代码
 if t.compress == CompressNone && t.wTimeout.Load() > 0 {
  // Optimization: update write deadline only if more than 25%
  // of the last write deadline exceeded.
  // See https://github.com/golang/go/issues/15133 for details.
  currentTime = time.Now()
  // 每一次请求都会同步等待socket的写操作完成,为了避免网络故障等造成conn长时间阻塞当前gorouting,必须设置一个write deadline
  // 此处基于issue 15133中的问题为了避免每次写deadline的开销(会创建大量的timer,造成cpu调度的开销),妥协做的在超过1/4的时候才更新timeout
  if currentTime.Sub(t.wLastDeadline.Load()) > t.wTimeout.Load()>>2 {
   if err = t.conn.SetWriteDeadline(currentTime.Add(t.wTimeout.Load())); err != nil {
    return 0, perrors.WithStack(err)
   }
   t.wLastDeadline.Store(currentTime)
  }
 }
}

上述代码中如果存在如下场景时,将会出现i/o timeout的场景不符合预期

两个协程r1,r2, 其deadlineTimeout时间分别设置为3s和20s
gettyTCPConn中wLastDeadline是存的lastUpdateTimestamp,而不是真正的lastDeadlineTimestamp
就会出现如下场景超时
r1在time=3时刻设置了conn的Deadline更新到time=6, 并设置wLastDeadline=3
r2在time=6.1时刻的时候,sub wLastDeadline = 3.1 =  < 20 / 4, 不会更新conn的Deadline,则此时deadline仍然为time=6
此时r2执行的时候会直接报i/o timeout

同时存在的问题,是为了避免每次writeDeadline都会创建一个timer,造成对cpu的影响。上述代码中做了优化为每1/4的timeout才会执行一次setWriteDeadline。那么某个request的真实write执行时间只要是大于3/4就必然会出现i/o timeout,此时与业务上承诺的timeout时间存在1/4的时间差,这块儿的逻辑打破了对用户的时间承诺,业务上用户会问设置的时间未达到就超时,是感觉不符合预期的。参考netty中是由独立的io线程去执行写操作,getty这部分有些相当于是同步写操作,就要求getty connector这一层必须设置一个writeDeadline。就个人观点,写操作应由外部提交任务(可以通过channel实现)给getty并获取对应的callback,外部需要由专有gorouting处理deadline的任务,与此同时getty由协程池来负责对conn的Write操作(实现细节部分待详细设计)。

如果去掉1/4的优化每次都setWriteDeadline会导致timer大量的add/remove,表现如下图(在runtime/time.go的dodeltimer/dodeltimer0/doaddtimer等函数中增加打点)

=== timer add ===>  334
=== timer rm0 ===>  333
=== timer add ===>  334
=== timer rm0 ===>  333
=== timer add ===>  334
=== timer rm0 ===>  333
=== timer add ===>  334
=== timer rm0 ===>  333
=== timer add ===>  5
=== timer rm0 ===>  332
=== timer add ===>  333
=== timer rm0 ===>  332
=== timer add ===>  333
=== timer rm0 ===>  332
=== timer add ===>  333
=== timer rm0 ===>  332
=== timer add ===>  333
=== timer rm0 ===>  332
AlexStocks commented 4 months ago

不建议把超时时间设置的太长(如 30s),设置为 3s 即可。