Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
hxmhlt opened this issue May 9, 2019 · 10 comments
Open

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

hxmhlt opened this issue May 9, 2019 · 10 comments

Comments

@hxmhlt
Copy link

hxmhlt commented May 9, 2019

将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。

fangyincheng pushed a commit to fangyincheng/getty that referenced this issue Jul 20, 2019
@63isOK
Copy link

63isOK commented Sep 25, 2021

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

@AlexStocks AlexStocks reopened this Sep 25, 2021
@AlexStocks
Copy link
Owner

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

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

@fingthinking
Copy link

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

@Lvnszn
Copy link
Collaborator

Lvnszn commented Nov 16, 2021

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

你用的是什么版本的呀?

@AlexStocks
Copy link
Owner

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

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

@fingthinking
Copy link

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

你用的是什么版本的呀?

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

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

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

@AlexStocks
Copy link
Owner

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

你用的是什么版本的呀?

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

@AlexStocks
Copy link
Owner

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

你用的是什么版本的呀?

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

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

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

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

@fingthinking
Copy link

fingthinking commented Nov 18, 2021

问题分析:

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
Copy link
Owner

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants