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.

Sign up for GitHub

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

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
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@wangao1236
Copy link

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

/assign @evanphx @bmizerany @uggedal @benburkert

@mdlayher
Copy link
Member

This is not the Kubernetes repository, closing.

@ALTree
Copy link
Member

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

Apologies, I misread the post. Will reopen.

@mdlayher mdlayher reopened this Sep 24, 2020
@ALTree ALTree added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 24, 2020
@wangao1236
Copy link
Author

Apologies, I misread the post. Will reopen.

Never mind, thanks for checking the issue.

@prattmic
Copy link
Member

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

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
Member

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

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 commented Sep 24, 2020

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

@ianlancetaylor
Copy link
Contributor

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.

@ianlancetaylor ianlancetaylor added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Sep 24, 2020
@wangao1236
Copy link
Author

@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

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.

@golang golang locked and limited conversation to collaborators Sep 25, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
8 participants
@evanphx @prattmic @mdlayher @ianlancetaylor @ALTree @gopherbot @seankhliao @wangao1236