time: After delay 10s occasionally

[sisyphsu]

Version: go version go1.8.3 darwin/amd64
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/sulin/workspace/go"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/j0/z8rksv5911g9kwyfffq5y1rr0000gn/T/go-build131871117=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

When i use time.After for some short sleep, mostly 10ms~100ms.
I found the timer didn't expire at the expected time, but delay 10 seconds. this was occasionally, like 1/1000, but it really ruin my application.

The code is blow:

for !s._close {
    p := newProtocol()
    s.Lock()
    delay := s.fec.onSend(p)
    s.Unlock()
    startTime := time.Now().UnixNano()
    select {
    case <-time.After(delay):
        LOGGER.TraceF("normal %v: %v", delay, time.Duration(time.Now().UnixNano()-startTime))
    case <-s.signal:
        LOGGER.TraceF("break %v: %v", delay, time.Duration(time.Now().UnixNano()-startTime))
    }
}

Most log didn't delay much, like 10ms->12ms, I could accept it.

2017-09-03 16:18:18.094617288 [TRACE] normal 7.953537ms: 9.151017ms
2017-09-03 16:18:18.145271958 [TRACE] normal 8.877516ms: 10.193023ms
2017-09-03 16:18:18.220673023 [TRACE] normal 19.940444ms: 22.052824ms
2017-09-03 16:19:12.85975685  [TRACE] normal 10.94034ms: 13.224514ms
2017-09-03 16:19:12.885154309 [TRACE] normal 21.935108ms: 25.278368ms

But sometimes, the timer will delay very much, like 10ms->10s.

2017-09-03 16:18:52.915667148 [TRACE] normal 10.974347ms: 9.162969872s
2017-09-03 16:18:57.783207779 [TRACE] normal 21.896961ms: 4.867348206s

[davecheney]

Hello, Please try the following. 1. upgrade to Go 1.9 2. startTime := time.Now(); endTIme := time.Since(startTime) And check the results. If the problem please occurs, please post a _complete_ runnable example that shows the problem, or at least is a runnable representation of what you are seeing.

…

On Sun, Sep 3, 2017 at 6:44 PM, lin ***@***.***> wrote: Version: go version go1.8.3 darwin/amd64 GOARCH="amd64" GOBIN="" GOEXE="" GOHOSTARCH="amd64" GOHOSTOS="darwin" GOOS="darwin" GOPATH="/Users/sulin/workspace/go" GORACE="" GOROOT="/usr/local/go" GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64" GCCGO="gccgo" CC="clang" GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/j0/ z8rksv5911g9kwyfffq5y1rr0000gn/T/go-build131871117=/tmp/go-build -gno-record-gcc-switches -fno-common" CXX="clang++" CGO_ENABLED="1" PKG_CONFIG="pkg-config" CGO_CFLAGS="-g -O2" CGO_CPPFLAGS="" CGO_CXXFLAGS="-g -O2" CGO_FFLAGS="-g -O2" CGO_LDFLAGS="-g -O2" When i use time.After for some short sleep, mostly 10ms~100ms. I found the timer didn't expire at the expected time, but delay 10 seconds. this was occasionally, like 1/1000, but it really ruin my application. The code is blow: for !s._close { p := newProtocol() s.Lock() delay := s.fec.onSend(p) s.Unlock() startTime := time.Now().UnixNano() select { case <-time.After(delay): LOGGER.TraceF("normal %v: %v", delay, time.Duration(time.Now().UnixNano()-startTime)) case <-s.signal: LOGGER.TraceF("break %v: %v", delay, time.Duration(time.Now().UnixNano()-startTime)) } } Most log didn't delay much, like 10ms->12ms, I could accept id. 2017-09-03 16:18:18.094617288 [TRACE] normal 7.953537ms: 9.151017ms 2017-09-03 16:18:18.145271958 [TRACE] normal 8.877516ms: 10.193023ms 2017-09-03 16:18:18.220673023 [TRACE] normal 19.940444ms: 22.052824ms 2017-09-03 16:19:12.85975685 [TRACE] normal 10.94034ms: 13.224514ms 2017-09-03 16:19:12.885154309 [TRACE] normal 21.935108ms: 25.278368ms But sometimes, the timer will delay very much, like 10ms->10s. 2017-09-03 16:18:52.915667148 [TRACE] normal 10.974347ms: 9.162969872s 2017-09-03 16:18:57.783207779 [TRACE] normal 21.896961ms: 4.867348206s — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#21746>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAcA-pjHwBRZSZyw22wxTow0vzHmYVlks5semb2gaJpZM4PLIHs> .

[sisyphsu]

@davecheney OK, thanks.

[cznic]

FTR: time.After(x) semantics are such that the receive from the returned channel occurs not before x, ie. any time later on non-RT OSes and not much more can be guaranteed.

Additionally to what @davecheney wrote, it could be helpful to know also the value received from the channel, to distinguish if the delay is on the send or receive side.

[sisyphsu]

After upgrade Go to 1.9, this issue didn't appear anymore, and I can't find the reason...

I will keep watching my log, should I close this issue temporary?

[ianlancetaylor]

If you can't recreate the problem with 1.9, let's close the issue. Thanks.