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

Jump to bottom

time.After Sometimes Skips #34889

Closed
ossie-git opened this issue Oct 14, 2019 · 6 comments
Closed

time.After Sometimes Skips #34889

ossie-git opened this issue Oct 14, 2019 · 6 comments
Labels
FrozenDueToAge

Comments

@ossie-git
Copy link

What version of Go are you using (go version)?

$ go version
go version go1.13.1 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/ubuntu/.cache/go-build"
GOENV="/home/ubuntu/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/ubuntu/go_files"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/ubuntu/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/ubuntu/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build604759310=/tmp/go-build -gno-record-gcc-switches"

What did you do?

From my understanding, time.After is equivalent to running a goroutine that sleeps for the given time period and then writes the time to the channel. It also takes care of channel cleanup for you. So I would expect something like this:

<-time.After(time.Second)

to behave similarly to the following code snippet (+ automatically close the channel for you):

go func() {
    for {
        c1 <-time.After(time.Second)
    }
}()

however, from my experimentation, this is not the case. In my sample https://play.golang.org/p/FasIldsACpD, it would produce the same # for both runs but if I try this on any environment (I ran this on both Linux + Mac), I would run into discrepancies. These changes were more noticeable if I ran this on a multi-CPU system and if I ran it for a longer period of time. Running it for 600 seconds would result in something like this on a multi-CPU system:

$ go run /tmp/test.go
Using goroutine:  432467
Using time.After: 430642

Even if I set the interval to 1 second (replace time.Millisecond with time.Second), I would still run into discrepancies. After running it for a minute, I got

Using goroutine:  59
Using time.After: 55

What did you expect to see?

They should both be the same or a difference of one at most

What did you see instead?

See above
@go101
Copy link

go101 commented Oct 14, 2019 •
edited

If you change the channel c1 to a buffered one, you will find the difference will be even much larger.

There might be some imperfections in the runtime implementation, but your use of time.After is not recommended. There will be more and more goroutines hanging for ever. We should use it like https://play.golang.org/p/ljRAQnREgLk

@go101
Copy link

go101 commented Oct 14, 2019 •
edited

Ah, there is a mistake in my description in the last comment. There will be not more and more goroutines hanging for ever.

@go101
Copy link

go101 commented Oct 14, 2019 •
edited

I think the difference is normal. For the select-block loop goroutine has a little more initialization overhead than the other loop at each step.

@ianlancetaylor
Copy link
Contributor

You are in effect measuring the overhead of the select statement. There is no particular reason to expect the counts in your program to be equal; the simple goroutine is going to loop around faster, so it's more likely to be ready before the time.After in the select statement. It's not all that much faster, so the counts aren't all that different. Also, time.After uses a buffered channel but the simple goroutine uses an unbuffered channel.

I'm going to close this issue because it is not a bug. If you want to discuss it, I encourage you to use a forum rather than the issue tracker. See https://golang.org/wiki/Questions.

@ossie-git
Copy link
Author

Okay. But I think you might have missed the second part that I mentioned. Even if I set the time.After and the goroutine timeouts to be 1 second instead of 1 millisecond (in which case the select overhead should be negligible), I still get different results which I think is unexpected. So something like this - https://play.golang.org/p/DVXB8LFJRln - sometimes results in:

Using goroutine:  9
Using time.After: 7

which I think any makes the use of time.After unreliable

@ianlancetaylor
Copy link
Contributor

If you want to discuss this, I encourage you to use a forum rather than the issue tracker. See https://golang.org/wiki/Questions.

The select overhead does not become negligible merely by extending the timeout, because both loops will start at roughly the same instant in time.

@golang golang locked and limited conversation to collaborators Oct 14, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@ianlancetaylor @gopherbot @go101 @ossie-git