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

"write tcp xxx:17947->yyy:20000: i/o timeout" occurs frequently #104

Closed
rnben opened this issue Jan 9, 2024 · 5 comments
Closed

"write tcp xxx:17947->yyy:20000: i/o timeout" occurs frequently #104

rnben opened this issue Jan 9, 2024 · 5 comments

Comments

@rnben
Copy link

rnben commented Jan 9, 2024

What happened:

2024/01/09 20:41:03 client response result: Hello, this request cost 7s
2024/01/09 20:41:12 client response result: Hello, this request cost 9s
2024/01/09 20:41:19 client response result: Hello, this request cost 7s
2024/01/09 20:41:27 client response result: Hello, this request cost 8s
2024/01/09 20:41:32 client response result: Hello, this request cost 5s
2024/01/09 20:41:38 client response result: Hello, this request cost 6s
2024/01/09 20:41:43 client response result: Hello, this request cost 5s
2024/01/09 20:41:48 client response result: Hello, this request cost 5s
2024/01/09 20:41:56 client response result: Hello, this request cost 8s
2024-01-09 20:41:56     WARN    getty/getty_client.go:269       session {client:TCP_CLIENT:5:192.168.123.192:17947<->192.168.123.192:20000}, Read Bytes: 393, Write Bytes: 389, Read Pkgs: 4, Write Pkgs: 4, [session.WritePkg] @s.Connection.Write(pkg:[]byte{0xda, 0xbb, 0xc2, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x4e, 0x0, 0x0, 0x1, 0x41, 0x5, 0x32, 0x2e, 0x30, 0x2e, 0x32, 0x30, 0x27, 0x6f, 0x72, 0x67, 0x2e, 0x61, 0x70, 0x61, 0x63, 0x68, 0x65, 0x2e, 0x64, 0x75, 0x62, 0x62, 0x6f, 0x2e, 0x44, 0x75, 0x62, 0x62, 0x6f, 0x44, 0x65, 0x6d, 0x6f, 0x50, 0x72, 0x6f, 0x76, 0x69, 0x64, 0x65, 0x72, 0x2e, 0x54, 0x65, 0x73, 0x74, 0x9, 0x6d, 0x79, 0x76, 0x65, 0x72, 0x73, 0x69, 0x6f, 0x6e, 0x8, 0x53, 0x61, 0x79, 0x48, 0x65, 0x6c, 0x6c, 0x6f, 0x1f, 0x4c, 0x6f, 0x72, 0x67, 0x2f, 0x61, 0x70, 0x61, 0x63, 0x68, 0x65, 0x2f, 0x64, 0x75, 0x62, 0x62, 0x6f, 0x2f, 0x44, 0x75, 0x62, 0x62, 0x6f, 0x52, 0x65, 0x71, 0x75, 0x65, 0x73, 0x74, 0x3b, 0x43, 0x1d, 0x6f, 0x72, 0x67, 0x2e, 0x61, 0x70, 0x61, 0x63, 0x68, 0x65, 0x2e, 0x64, 0x75, 0x62, 0x62, 0x6f, 0x2e, 0x44, 0x75, 0x62, 0x62, 0x6f, 0x52, 0x65, 0x71, 0x75, 0x65, 0x73, 0x74, 0x91, 0x7, 0x72, 0x65, 0x71, 0x75, 0x65, 0x73, 0x74, 0x60, 0x48, 0x4, 0x63, 0x6f, 0x73, 0x74, 0x2, 0x36, 0x73, 0x5a, 0x48, 0x9, 0x69, 0x6e, 0x74, 0x65, 0x72, 0x66, 0x61, 0x63, 0x65, 0x30, 0x27, 0x6f, 0x72, 0x67, 0x2e, 0x61, 0x70, 0x61, 0x63, 0x68, 0x65, 0x2e, 0x64, 0x75, 0x62, 0x62, 0x6f, 0x2e, 0x44, 0x75, 0x62, 0x62, 0x6f, 0x44, 0x65, 0x6d, 0x6f, 0x50, 0x72, 0x6f, 0x76, 0x69, 0x64, 0x65, 0x72, 0x2e, 0x54, 0x65, 0x73, 0x74, 0x5, 0x67, 0x72, 0x6f, 0x75, 0x70, 0xa, 0x6d, 0x79, 0x41, 0x70, 0x70, 0x47, 0x72, 0x6f, 0x75, 0x70, 0x7, 0x76, 0x65, 0x72, 0x73, 0x69, 0x6f, 0x6e, 0x9, 0x6d, 0x79, 0x76, 0x65, 0x72, 0x73, 0x69, 0x6f, 0x6e, 0x7, 0x74, 0x69, 0x6d, 0x65, 0x6f, 0x75, 0x74, 0x1, 0x30, 0x5, 0x61, 0x73, 0x79, 0x6e, 0x63, 0x5, 0x66, 0x61, 0x6c, 0x73, 0x65, 0xb, 0x65, 0x6e, 0x76, 0x69, 0x72, 0x6f, 0x6e, 0x6d, 0x65, 0x6e, 0x74, 0x3, 0x70, 0x72, 0x6f, 0x4, 0x70, 0x61, 0x74, 0x68, 0x30, 0x27, 0x6f, 0x72, 0x67, 0x2e, 0x61, 0x70, 0x61, 0x63, 0x68, 0x65, 0x2e, 0x64, 0x75, 0x62, 0x62, 0x6f, 0x2e, 0x44, 0x75, 0x62, 0x62, 0x6f, 0x44, 0x65, 0x6d, 0x6f, 0x50, 0x72, 0x6f, 0x76, 0x69, 0x64, 0x65, 0x72, 0x2e, 0x54, 0x65, 0x73, 0x74, 0x5a}) = err:write tcp 192.168.123.192:17947->192.168.123.192:20000: i/o timeout
github.com/apache/dubbo-getty.(*gettyTCPConn).send
        C:/Users/ruben/Desktop/dubbo-demo/vendor/github.com/apache/dubbo-getty/connection.go:329
github.com/apache/dubbo-getty.(*session).WritePkg
        C:/Users/ruben/Desktop/dubbo-demo/vendor/github.com/apache/dubbo-getty/session.go:408
dubbo.apache.org/dubbo-go/v3/remoting/getty.(*Client).transfer
        C:/Users/ruben/Desktop/dubbo-demo/vendor/dubbo.apache.org/dubbo-go/v3/remoting/getty/getty_client.go:269
dubbo.apache.org/dubbo-go/v3/remoting/getty.(*Client).Request
        C:/Users/ruben/Desktop/dubbo-demo/vendor/dubbo.apache.org/dubbo-go/v3/remoting/getty/getty_client.go:207
dubbo.apache.org/dubbo-go/v3/remoting.(*ExchangeClient).Request
        C:/Users/ruben/Desktop/dubbo-demo/vendor/dubbo.apache.org/dubbo-go/v3/remoting/exchange_client.go:131
dubbo.apache.org/dubbo-go/v3/protocol/dubbo.(*DubboInvoker).Invoke
        C:/Users/ruben/Desktop/dubbo-demo/vendor/dubbo.apache.org/dubbo-go/v3/protocol/dubbo/dubbo_invoker.go:153
dubbo.apache.org/dubbo-go/v3/filter/graceful_shutdown.(*consumerGracefulShutdownFilter).Invoke
        C:/Users/ruben/Desktop/dubbo-demo/vendor/dubbo.apache.org/dubbo-go/v3/filter/graceful_shutdown/consumer_filter.go:66
dubbo.apache.org/dubbo-go/v3/protocol/protocolwrapper.(*FilterInvoker).Invoke
        C:/Users/ruben/Desktop/dubbo-demo/vendor/dubbo.apache.org/dubbo-go/v3/protocol/protocolwrapper/protocol_filter_wrapper.go:127 
dubbo.apache.org/dubbo-go/v3/cluster/cluster/failover.(*failoverClusterInvoker).Invoke
        C:/Users/ruben/Desktop/dubbo-demo/vendor/dubbo.apache.org/dubbo-go/v3/cluster/cluster/failover/cluster_invoker.go:86
dubbo.apache.org/dubbo-go/v3/proxy.DefaultProxyImplementFunc.func1.1
        C:/Users/ruben/Desktop/dubbo-demo/vendor/dubbo.apache.org/dubbo-go/v3/proxy/proxy.go:202
main.main
        C:/Users/ruben/Desktop/dubbo-demo/cmd/client/client.go:35
runtime.main
        C:/Users/ruben/scoop/apps/go/current/src/runtime/proc.go:267
runtime.goexit
        C:/Users/ruben/scoop/apps/go/current/src/runtime/asm_amd64.s:1650
2024-01-09 20:41:56     WARN    proxy/proxy.go:212      [CallProxy] received rpc err: Failed to invoke the method SayHello in the service org.apache.dubbo.DubboDemoProvider.Test. Tried 0 times of the providers [dubbo://:@192.168.123.192:20000/?interface=org.apache.dubbo.DubboDemoProvider.Test&group=myAppGroup&version=myversion] (1/1)from the registry nacos://127.0.0.1:8848?nacos.access=&nacos.group=myGroup&nacos.namespaceId=&nacos.password=&nacos.secret=&nacos.timeout=5s&nacos.username=&registry=nacos&registry.group=myGroup&registry.label=true&registry.namespace=&registry.preferred=false&registry.role=0&registry.timeout=5s&registry.ttl=15m&registry.weight=0&registry.zone=&remote-client-name=dubbo.registries-nacos-127.0.0.1%3A8848&simplified=false on the consumer 192.168.123.192 using the dubbo version 3.0.4. Last error is write tcp 192.168.123.192:17947->192.168.123.192:20000: i/o timeout.: write tcp 192.168.123.192:17947->192.168.123.192:20000: i/o timeout
panic: write tcp 192.168.123.192:17947->192.168.123.192:20000: i/o timeout

goroutine 1 [running]:
main.main()
        C:/Users/ruben/Desktop/dubbo-demo/cmd/client/client.go:37 +0x25a

What you expected to happen:

The following configuration file shows that the request-timeout has been set to 1minute, which is valid.

However, a write timeout error always occurs after multiple requests,In fact, the request does not exceed 10s!!

I find that commenting out currentTime.Sub(t.wLastDeadline.Load()) > t.wTimeout.Load()>>2 can solve this problem.

image

How to reproduce it (as minimally and precisely as possible):

It can be reproduced by running the demo program。

https://github.com/rnben/dubbo-demo/blob/master/README.md

Anything else we need to know?:

dubbo:
  application:
    name: myApp # metadata: application=myApp; name=myApp
    module: opensource #metadata: module=opensource
    group: myAppGroup # no metadata record
    organization: dubbo # metadata: organization=dubbo
    owner: laurence # metadata: owner=laurence
    version: myversion # metadata: app.version=myversion
    environment: pro # metadata: environment=pro
  registries:
    nacosWithCustomGroup:
      protocol: nacos
      address: 127.0.0.1:8848
      group: myGroup # default is DEFAULT_GROUP
      registry-type: interface
#      namespace: 9fb00abb-278d-42fc-96bf-e0151601e4a1 # default is public
  consumer:
    request-timeout: 1m
    references:
      DubboDemoProvider:
        protocol: dubbo
        interface: org.apache.dubbo.DubboDemoProvider.Test
        retries: 0

All the other information is there:https://github.com/rnben/dubbo-demo

@AlexStocks
Copy link

Would you please give an example just using getty without dubbo-go to reproduce this problem?

@rnben
Copy link
Author

rnben commented Jan 17, 2024

Would you please give an example just using getty without dubbo-go to reproduce this problem?

I will try it, and I noticed that dubbo-go uses getty RPCClient to maintain multiple getty.Session, randomly selecting one for each request, which may be related to this. It is possible to obtain a session whose deadline is about to expire or has expired.

@rnben
Copy link
Author

rnben commented Jan 17, 2024

Would you please give an example just using getty without dubbo-go to reproduce this problem?

This may be the same problem: AlexStocks#14

@zhaoyunxing92
Copy link

把超时时间设置短点 request-timeout

@AlexStocks
Copy link

AlexStocks commented Mar 12, 2024

把超时时间设置短点 request-timeout

@rnben 不知道你的超时时间设置了多长?设置 3s 就足够了,不要太长,如 30s。

我们尝试修改下如下逻辑:

        // Optimization: update read deadline only if more than 25%
        // of the last read deadline exceeded.
        // See https://github.com/golang/go/issues/15133 for details.
        currentTime = time.Now()
        if currentTime.Sub(t.rLastDeadline.Load()) > t.rTimeout.Load()>>2 {
            if err = t.conn.SetReadDeadline(currentTime.Add(t.rTimeout.Load())); err != nil {
                // just a timeout error
                return 0, perrors.WithStack(err)
            }
            t.rLastDeadline.Store(currentTime)
        }

为:

        timeDuration := t.rTimeout.Load()>>2
        if timeDuration > 500e8 {
          timeDuration = 500e8
        }

        currentTime = time.Now()
        if currentTime.Sub(t.rLastDeadline.Load()) > timeDuration {
            if err = t.conn.SetReadDeadline(currentTime.Add(t.rTimeout.Load())); err != nil {
                // just a timeout error
                return 0, perrors.WithStack(err)
            }
            t.rLastDeadline.Store(currentTime)
        }

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

3 participants