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

runtime: differing timer behavior in goroutines between Go 1.14 and 1.15 #41606

Closed
wangao1236 opened this issue Sep 24, 2020 · 13 comments
Closed

runtime: differing timer behavior in goroutines between Go 1.14 and 1.15 #41606

wangao1236 opened this issue Sep 24, 2020 · 13 comments

Comments

@wangao1236
Copy link

@wangao1236 wangao1236 commented Sep 24, 2020

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

$ go version
go version go1.15.2 darwin/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="/Users/wangao/Library/Caches/go-build"
GOENV="/Users/wangao/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/wangao/go/pkg/mod"
GONOPROXY="tkestack.io,tkestack.com,helm.sh,go.etcd.io,k8s.io,go.uber.org,git.code.oa.com"
GONOSUMDB="tkestack.io,tkestack.com,helm.sh,go.etcd.io,k8s.io,go.uber.org,git.code.oa.com"
GOOS="darwin"
GOPATH="/Users/wangao/go"
GOPRIVATE="tkestack.io,tkestack.com,helm.sh,go.etcd.io,k8s.io,go.uber.org,git.code.oa.com"
GOPROXY="https://goproxy.cn,https://mirrors.aliyun.com/goproxy/,direct"
GOROOT="/usr/local/go-1.15"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go-1.15/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/wangao/go/mod/test/golang-test/go.mod"
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/w4/cx24m_2d5y3gkrwt1kpf495h0000gn/T/go-build322658631=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I used a package called "k8s.io/apimachinery v0.18.2", the package has a function called wait.Until, it is a polling function, that can set the interval. The script is as follows:

package main

import (
	"fmt"
	"k8s.io/apimachinery/pkg/util/wait"
	"runtime/debug"
	"time"
)

func main() {
	fun1 := func() {
		fmt.Printf("%+v=>start test1: %+v\n", time.Now(), string(debug.Stack()))
	}
	go func() {
		go wait.Until(fun1, 1*time.Minute, wait.NeverStop)
	}()
	select {}
}

What did you expect to see?

I want the polling function to run every one minute. Running logs under version 1.14.1 is as follows:

2020-09-24 18:04:39.185988 +0800 CST m=+0.002008136=>start test1: goroutine 21 [running]:
runtime/debug.Stack(0xbfd339adcb15f3a0, 0x1ea448, 0x14f8d60)
	/usr/local/go-1.14/src/runtime/debug/stack.go:24 +0x9d
main.main.func1()
	/Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:29 +0x5c
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x12e3d48)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:155 +0x5f
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x12e3d48, 0x132db60, 0xc00009ac30, 0xc0000b0001, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:156 +0xa3
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x12e3d48, 0xdf8475800, 0x0, 0x1, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:133 +0xe2
k8s.io/apimachinery/pkg/util/wait.Until(0x12e3d48, 0xdf8475800, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:90 +0x4d
created by main.main.func2
	/Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:32 +0x5a

2020-09-24 18:05:39.189541 +0800 CST m=+60.003761493=>start test1: goroutine 21 [running]:
runtime/debug.Stack(0xbfd339bccb4c2a88, 0xdf880bd55, 0x14f8d60)
	/usr/local/go-1.14/src/runtime/debug/stack.go:24 +0x9d
main.main.func1()
	/Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:29 +0x5c
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x12e3d48)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:155 +0x5f
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x12e3d48, 0x132db60, 0xc00009ac30, 0xc0000b0001, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:156 +0xa3
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x12e3d48, 0xdf8475800, 0x0, 0x1, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:133 +0xe2
k8s.io/apimachinery/pkg/util/wait.Until(0x12e3d48, 0xdf8475800, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:90 +0x4d
created by main.main.func2
	/Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:32 +0x5a

2020-09-24 18:06:39.192031 +0800 CST m=+120.004451138=>start test1: goroutine 21 [running]:
runtime/debug.Stack(0xbfd339cbcb722918, 0x1bf0d29b42, 0x14f8d60)
	/usr/local/go-1.14/src/runtime/debug/stack.go:24 +0x9d
main.main.func1()
	/Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:29 +0x5c
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x12e3d48)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:155 +0x5f
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x12e3d48, 0x132db60, 0xc00009ac30, 0xc0000b0001, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:156 +0xa3
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x12e3d48, 0xdf8475800, 0x0, 0x1, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:133 +0xe2
k8s.io/apimachinery/pkg/util/wait.Until(0x12e3d48, 0xdf8475800, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:90 +0x4d
created by main.main.func2
	/Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:32 +0x5a

2020-09-24 18:07:39.194212 +0800 CST m=+180.004832819=>start test1: goroutine 21 [running]:
runtime/debug.Stack(0xbfd339dacb9370a0, 0x29e91fc633, 0x14f8d60)
	/usr/local/go-1.14/src/runtime/debug/stack.go:24 +0x9d
main.main.func1()
	/Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:29 +0x5c
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x12e3d48)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:155 +0x5f
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x12e3d48, 0x132db60, 0xc00009ac30, 0xc0000b0001, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:156 +0xa3
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x12e3d48, 0xdf8475800, 0x0, 0x1, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:133 +0xe2
k8s.io/apimachinery/pkg/util/wait.Until(0x12e3d48, 0xdf8475800, 0xc00008e0c0)
	/Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:90 +0x4d
created by main.main.func2
	/Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:32 +0x5a

What did you see instead?

But in the new version, when the program starts, the polling function executes twice in a row, then every other minute. The first round was executed one more time. Running logs under version 1.15.2 is as follows:

2020-09-24 17:59:20.025211 +0800 CST m=+0.002176999=>start test1: goroutine 21 [running]:
runtime/debug.Stack(0xbfd3395e0180b078, 0x2137e7, 0x1328880)
  /usr/local/go-1.15/src/runtime/debug/stack.go:24 +0x9f
main.main.func1()
  /Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:29 +0x59
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x11edb20)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:155 +0x5f
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x11edb20, 0x1217c00, 0xc00009ac00, 0xc0000b0001, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:156 +0xad
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x11edb20, 0xdf8475800, 0x0, 0x1, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:133 +0xe5
k8s.io/apimachinery/pkg/util/wait.Until(0x11edb20, 0xdf8475800, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:90 +0x4d
created by main.main.func2
  /Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:32 +0x5a

2020-09-24 17:59:20.025443 +0800 CST m=+0.002408991=>start test1: goroutine 21 [running]:
runtime/debug.Stack(0xbfd3395e01843ab8, 0x24c21f, 0x1328880)
  /usr/local/go-1.15/src/runtime/debug/stack.go:24 +0x9f
main.main.func1()
  /Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:29 +0x59
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x11edb20)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:155 +0x5f
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x11edb20, 0x1217c00, 0xc00009ac00, 0xc0000b0001, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:156 +0xad
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x11edb20, 0xdf8475800, 0x0, 0x1, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:133 +0xe5
k8s.io/apimachinery/pkg/util/wait.Until(0x11edb20, 0xdf8475800, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:90 +0x4d
created by main.main.func2
  /Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:32 +0x5a

2020-09-24 18:00:20.029864 +0800 CST m=+60.005029982=>start test1: goroutine 21 [running]:
runtime/debug.Stack(0xbfd3396d01c7b040, 0xdf894185e, 0x1328880)
  /usr/local/go-1.15/src/runtime/debug/stack.go:24 +0x9f
main.main.func1()
  /Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:29 +0x59
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x11edb20)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:155 +0x5f
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x11edb20, 0x1217c00, 0xc00009ac00, 0xc0000b0001, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:156 +0xad
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x11edb20, 0xdf8475800, 0x0, 0x1, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:133 +0xe5
k8s.io/apimachinery/pkg/util/wait.Until(0x11edb20, 0xdf8475800, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:90 +0x4d
created by main.main.func2
  /Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:32 +0x5a

2020-09-24 18:01:20.032505 +0800 CST m=+120.005871217=>start test1: goroutine 21 [running]:
runtime/debug.Stack(0xbfd3397c01effca8, 0x1bf0e84671, 0x1328880)
  /usr/local/go-1.15/src/runtime/debug/stack.go:24 +0x9f
main.main.func1()
  /Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:29 +0x59
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x11edb20)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:155 +0x5f
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x11edb20, 0x1217c00, 0xc00009ac00, 0xc0000b0001, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:156 +0xad
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x11edb20, 0xdf8475800, 0x0, 0x1, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:133 +0xe5
k8s.io/apimachinery/pkg/util/wait.Until(0x11edb20, 0xdf8475800, 0xc00008e0c0)
  /Users/wangao/go/pkg/mod/k8s.io/apimachinery@v0.18.2/pkg/util/wait/wait.go:90 +0x4d
created by main.main.func2
  /Users/wangao/go/mod/test/golang-test/syntax/k8s/wail.go:32 +0x5a
@wangao1236
Copy link
Author

@wangao1236 wangao1236 commented Sep 24, 2020

@mdlayher
Copy link
Member

@mdlayher mdlayher commented Sep 24, 2020

This is not the Kubernetes repository, closing.

@mdlayher mdlayher closed this Sep 24, 2020
@ALTree
Copy link
Member

@ALTree ALTree commented Sep 24, 2020

It looks like OP is reporting a difference in behaviour between two Go versions (1.14 and 1.15), though.

@mdlayher mdlayher changed the title abnormal numbers of a polling function's running in a Goroutine runtime: differing timer behavior in goroutines between Go 1.14 and 1.15 Sep 24, 2020
@mdlayher
Copy link
Member

@mdlayher mdlayher commented Sep 24, 2020

Apologies, I misread the post. Will reopen.

@wangao1236
Copy link
Author

@wangao1236 wangao1236 commented Sep 24, 2020

Apologies, I misread the post. Will reopen.

Never mind, thanks for checking the issue.

@prattmic
Copy link
Member

@prattmic prattmic commented Sep 24, 2020

It seems like this was fixed between k8s.io/apimachinery v0.18.2 and v0.19.2 (latest version). It reproduces for me on v0.18.2, but not v0.19.2.

@prattmic
Copy link
Member

@prattmic prattmic commented Sep 24, 2020

Probably kubernetes/apimachinery@49ae5f6, which completely changed the internal implementation.

It is possible that something changed between 1.14 and 1.15 that changed the behavior of resetOrReuseTimer (in the old code). Though stopping timers is sufficiently tricky that it is not immediately obvious to me whether that code was correct or not.

@seankhliao
Copy link
Contributor

@seankhliao seankhliao commented Sep 24, 2020

Testing it, it looks like it might be a race condition somewhere, it reliably reproduces on go1.15.2 and it occasionally happens on go1.14.1

k8s.io/apimachinery v0.19.2 does indeed look like it fixed it

@wangao1236
Copy link
Author

@wangao1236 wangao1236 commented Sep 24, 2020

I tried this version, k8s.io/apimachinery v0.19.2 with go1.15.2, and it worked.

However, it is strange that go1.15.2 can reproduce this problem stably, while go1.14.1 does not ?

I will continue to read the code in k8s.io/apimachinery v0.19.2. thank you for your reply~

@seankhliao @prattmic

@evanphx
Copy link
Contributor

@evanphx evanphx commented Sep 24, 2020

@wangao1236 please please do not tag random people in assignment, it's extremely rude.

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Sep 24, 2020

The Go timer support was rewritten in Go 1.15. If there was a race condition in the old Kubernetes code, as suggested by the fact that the problem sometimes occurred with 1.14, then it is not surprising that the behavior changed between Go 1.14 and 1.15.

It sounds to me like everything is working fine with current Kubernetes code, and it sounds like there may have been a problem with the old Kubernetes code, so there doesn't seem to be a reason to keep this issue open. Happy to hear otherwise.

@wangao1236
Copy link
Author

@wangao1236 wangao1236 commented Sep 25, 2020

@wangao1236 please please do not tag random people in assignment, it's extremely rude.

@wangao1236 please please do not tag random people in assignment, it's extremely rude.

Sorry

@wangao1236
Copy link
Author

@wangao1236 wangao1236 commented Sep 25, 2020

Perhaps the difference between k8s.io/apimachinery v0.18.2 and k8s.io/apimachinery 0.19.2 is here:

// v0.18.2
func NewJitteredBackoffManager(duration time.Duration, jitter float64, c clock.Clock) BackoffManager {
	return &jitteredBackoffManagerImpl{
		clock:        c,
		duration:     duration,
		jitter:       jitter,
		backoffTimer: c.NewTimer(0),
	}
}

// v0.19.2
func NewJitteredBackoffManager(duration time.Duration, jitter float64, c clock.Clock) BackoffManager {
	return &jitteredBackoffManagerImpl{
		clock:        c,
		duration:     duration,
		jitter:       jitter,
		backoffTimer: nil,
	}
}

I think the problem is k8s. Thank you for everyone's help. I will close this issue.

@wangao1236 wangao1236 closed this Sep 25, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
7 participants