Skip to content

runtime: time.Sleep() wakes up too early #48214

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
Closed
YoshikiShibata opened this issue Sep 6, 2021 · 6 comments
Closed

runtime: time.Sleep() wakes up too early #48214

YoshikiShibata opened this issue Sep 6, 2021 · 6 comments
Labels
FrozenDueToAge

Comments

@YoshikiShibata
Copy link

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

$ go version
go version devel go1.18-04d8d24960 Fri Sep 3 19:56:09 2021 +0000 darwin/arm64

Does this issue reproduce with the latest release?

N/A

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

go env Output
$ go env
GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/yoshiki.shibata/Library/Caches/go-build"
GOENV="/Users/yoshiki.shibata/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/yoshiki.shibata/gocode/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/yoshiki.shibata/gocode"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/yoshiki.shibata/tools/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/yoshiki.shibata/tools/go/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="devel go1.18-04d8d24960 Fri Sep 3 19:56:09 2021 +0000"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/yoshiki.shibata/deletemes/go/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 -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/5y/6k1nfy3n0sn9h4g61bp36wv40000gp/T/go-build3264075978=/tmp/go-build -gno-record-gcc-switches -fno-common"
GOROOT/bin/go version: go version devel go1.18-04d8d24960 Fri Sep 3 19:56:09 2021 +0000 darwin/arm64
GOROOT/bin/go tool compile -V: compile version devel go1.18-04d8d24960 Fri Sep 3 19:56:09 2021 +0000
uname -v: Darwin Kernel Version 20.6.0: Wed Jun 23 00:26:27 PDT 2021; root:xnu-7195.141.2~5/RELEASE_ARM64_T8101
ProductName:	macOS
ProductVersion:	11.5.2
BuildVersion:	20G95
lldb --version: lldb-1205.0.28.2
Apple Swift version 5.4.2 (swiftlang-1205.0.28.2 clang-1205.0.19.57)

What did you do?

I ran the following program on my MacBook Pro M1

https://play.golang.org/p/foEoaXu4HHu

What did you expect to see?

No value under 100ms

What did you see instead?

 % go build -o a.out sleep.go
 % ./a.out
       0 value : 102.258000
       0 value : 102.261000
       0 value : 102.354000
       0 value : 102.211000
       0 value : 102.382000
       0 value : 102.205000
       0 value : 102.372000
       0 value : 102.223000
      44 value : 101.707000
      44 value : 101.706000
      44 value : 101.730000
      44 value : 101.724000
      44 value : 101.729000
      44 value : 101.731000
      44 value : 101.734000
      44 value : 101.731000
      71 value : 101.050000
      71 value : 100.053000
      71 value : 101.126000
      71 value : 101.120000
      71 value : 100.093000
      71 value : 101.142000
      71 value : 100.095000
      71 value : 101.147000
      73 value : 101.075000
      73 value : 101.115000
      78 value : 100.167000
      78 value : 100.153000
      78 value : 100.165000
      78 value : 100.174000
      78 value : 100.194000
     311 value : 100.111000
     311 value : 100.140000
     311 value : 100.149000
     311 value : 100.154000
     311 value : 100.157000
     359 value : 100.120000
     373 value : 100.069000
     373 value : 100.115000
     373 value : 100.121000
     373 value : 100.125000
     373 value : 100.130000
     386 value : 100.115000
     404 value : 100.063000
     404 value : 100.090000
     404 value : 100.082000
     404 value : 100.067000
     404 value : 100.096000
     570 value : 100.056000
     797 value : 100.065000
     797 value : 100.062000
     797 value : 100.067000
     797 value : 100.071000
     797 value : 100.070000
     829 value : 100.048000
    1091 value : 100.062000
    1296 value : 100.027000
    1296 value : 100.045000
    1296 value : 100.046000
    1296 value : 100.047000
    1296 value : 100.048000
    1296 value : 100.050000
    1296 value : 100.049000
    1733 value : 100.043000
    2104 value : 100.042000
    3189 value : 100.048000
    3302 value : 100.012000
    3302 value : 100.043000
    3974 value : 100.043000
    4092 value : 100.037000
    4454 value : 100.024000
    5685 value : 100.045000
    6115 value : 100.009000
    6115 value : 100.024000
    6115 value : 100.026000
    6742 value : 100.011000
    6742 value : 100.033000
    7384 value : 100.044000
    8813 value : 100.016000
    8813 value : 100.032000
    8813 value : 100.036000
   11729 value : 100.027000
   12706 value : 100.014000
   12706 value : 100.035000
   12780 value : 100.029000
   12816 value : 100.023000
   12816 value : 100.018000
   12863 value : 100.019000
   12957 value : 100.006000
   12957 value : 100.023000
   13711 value : 100.012000
   13762 value : 100.006000
   13762 value : 100.008000
   13762 value : 100.012000
   14615 value : 100.009000
   17859 value : 100.010000
   18226 value : 100.010000
value : 39.840000
   19980 value : 39.840000
value : 39.865000
   19980 value : 39.865000
value : 39.871000
   19980 value : 39.871000
value : 39.874000
   19980 value : 39.874000
value : 39.875000
   19980 value : 39.875000
value : 39.876000
   19980 value : 39.876000
value : 39.878000
   19980 value : 39.878000
value : 39.879000
   19980 value : 39.879000
value : 100.000000
value : 100.000000
value : 99.971000
value : 99.993000
value : 99.985000
value : 99.997000
value : 99.990000
value : 99.988000
value : 35.781000
  173510 value : 35.781000
value : 35.823000
value : 35.900000
  173510 value : 35.900000
value : 35.976000
  173510 value : 35.823000
value : 35.990000
  173510 value : 35.990000
value : 35.983000
  173510 value : 35.983000
value : 36.004000
  173510 value : 35.976000
  173510 value : 36.004000
value : 35.982000
  173510 value : 35.982000
value : 48.469000
value : 48.472000
value : 48.487000
value : 48.509000
value : 48.490000
value : 48.522000
value : 48.520000
value : 48.518000
^C
@YoshikiShibata YoshikiShibata changed the title time: time.Sleep() wakes up too early tip version: time: time.Sleep() wakes up too early Sep 6, 2021
@YoshikiShibata YoshikiShibata changed the title tip version: time: time.Sleep() wakes up too early tip version: time.Sleep() wakes up too early Sep 6, 2021
@seankhliao
Copy link
Member

Does this happen with 1.17?

@seankhliao seankhliao changed the title tip version: time.Sleep() wakes up too early runtime: time.Sleep() wakes up too early Sep 6, 2021
@YoshikiShibata
Copy link
Author

I will try it with 1.17

@YoshikiShibata
Copy link
Author

@seankhliao It happened with 1.17

% go version
go version go1.17 darwin/arm64
% go build -o a1_17.out sleep.go 
% go version a1_17.out 
a1_17.out: go1.17
% ./a1_17.out 
       0 value : 104.385000
       0 value : 104.423000
       0 value : 104.401000
       0 value : 104.340000
       0 value : 104.480000
       0 value : 104.364000
       0 value : 104.477000
       0 value : 104.504000
       3 value : 101.556000
       3 value : 101.551000
       3 value : 101.579000
       3 value : 101.556000
       3 value : 101.556000
       3 value : 101.557000
       3 value : 101.578000
       3 value : 101.554000
       5 value : 101.527000
       5 value : 101.526000
       5 value : 101.528000
       5 value : 101.539000
       5 value : 101.541000
       5 value : 101.541000
       5 value : 101.541000
       5 value : 101.542000
      11 value : 101.158000
      11 value : 101.169000
      11 value : 101.178000
      11 value : 101.168000
      11 value : 101.162000
      11 value : 101.172000
      11 value : 101.175000
      11 value : 101.167000
      12 value : 100.992000
      12 value : 101.003000
      12 value : 101.002000
      12 value : 101.001000
      12 value : 101.006000
      12 value : 101.004000
      12 value : 101.004000
      12 value : 101.003000
      15 value : 100.817000
      15 value : 100.817000
      15 value : 100.823000
      15 value : 100.824000
      15 value : 100.824000
      15 value : 100.825000
      15 value : 100.826000
      15 value : 100.827000
      22 value : 100.076000
      22 value : 100.073000
      22 value : 100.078000
      22 value : 100.079000
      22 value : 100.079000
      22 value : 100.081000
      22 value : 100.081000
      22 value : 100.092000
     116 value : 100.064000
     136 value : 100.055000
     136 value : 100.059000
     136 value : 100.090000
     163 value : 100.086000
     197 value : 100.032000
     197 value : 100.036000
     197 value : 100.039000
     197 value : 100.039000
     197 value : 100.040000
     197 value : 100.031000
     197 value : 100.042000
     197 value : 100.048000
     287 value : 100.028000
     445 value : 100.024000
     445 value : 100.031000
     445 value : 100.041000
     445 value : 100.024000
     455 value : 100.017000
     455 value : 100.029000
     455 value : 100.031000
     455 value : 100.040000
     545 value : 100.019000
     611 value : 100.012000
     663 value : 100.032000
    1353 value : 100.014000
    1417 value : 100.030000
    1648 value : 100.010000
    1648 value : 100.017000
    1678 value : 100.026000
    1678 value : 100.007000
    1678 value : 100.022000
    1678 value : 100.020000
    1748 value : 100.015000
    1748 value : 100.014000
    1748 value : 100.021000
    1784 value : 100.017000
    2267 value : 100.010000
    2267 value : 100.017000
    2267 value : 100.021000
    2513 value : 100.010000
    4456 value : 100.012000
    4545 value : 100.007000
    4774 value : 100.016000
value : 99.956000
    5179 value : 99.956000
value : 99.962000
    5185 value : 100.004000
value : 99.986000
    5194 value : 99.986000
value : 99.999000
    5194 value : 99.999000
value : 99.972000
    5236 value : 99.972000
value : 99.974000
    5236 value : 99.974000
value : 99.993000
    5251 value : 100.007000
value : 99.978000
    5252 value : 99.978000
value : 99.992000
    5493 value : 100.009000
    5722 value : 100.005000
    5722 value : 100.002000
   13190 value : 100.008000
   16617 value : 100.003000
   21407 value : 100.002000
   28527 value : 100.003000
   44612 value : 100.002000
   55977 value : 100.002000
   56046 value : 100.001000
value : 99.845000
value : 99.795000
value : 99.917000
value : 99.944000
   87189 value : 99.944000
   87189 value : 99.795000
value : 99.974000
value : 99.861000
   87189 value : 99.845000
   87189 value : 99.917000
value : 99.925000
   87189 value : 99.925000
value : 99.778000
   87189 value : 99.778000
   87189 value : 99.861000
value : 99.952000
value : 99.877000
value : 99.891000
value : 100.000000
value : 99.939000
value : 99.978000
value : 99.963000
value : 99.915000
value : 99.938000
value : 99.909000
value : 99.908000
   87193 value : 99.908000
   87193 value : 99.915000
value : 99.892000
value : 99.909000
value : 99.907000
   87193 value : 99.907000
   87193 value : 99.938000
value : 99.919000
value : 99.812000
value : 99.823000
value : 99.845000
   87195 value : 99.823000
value : 99.849000
value : 99.833000
value : 99.812000
   87195 value : 99.812000
   87195 value : 99.812000
value : 99.852000
   87195 value : 99.852000
value : 99.835000
   87195 value : 99.835000
value : 99.936000
value : 99.977000
value : 99.979000
value : 99.965000
value : 99.981000
value : 99.983000
value : 99.981000
value : 99.980000
value : 99.893000
value : 99.804000
value : 99.819000
   87199 value : 99.819000
value : 99.817000
value : 99.919000
value : 99.816000
value : 99.914000
value : 99.813000
   87199 value : 99.813000
value : 99.904000
value : 99.920000
value : 99.913000
value : 99.935000
value : 99.942000
value : 99.941000
value : 99.943000
value : 99.903000
value : 99.997000
value : 99.997000
value : 99.985000
value : 99.998000
value : 99.855000
value : 99.852000
value : 99.874000
value : 99.856000
value : 99.846000
value : 99.852000
value : 99.856000
value : 99.852000
value : 99.831000
value : 99.847000
value : 99.839000
value : 99.851000
value : 99.836000
value : 99.854000
value : 99.854000
value : 99.855000
value : 99.909000
value : 99.934000
value : 99.929000
value : 99.929000
value : 99.928000
value : 99.935000
value : 99.931000
value : 99.938000
value : 99.921000
value : 99.937000
value : 99.924000
value : 99.924000
value : 99.925000
value : 99.926000
value : 99.926000
value : 99.919000
value : 99.907000
value : 99.916000
value : 99.925000
value : 99.912000
value : 99.916000
value : 99.920000
value : 99.928000
value : 99.929000
value : 99.964000
value : 99.976000
value : 99.974000
value : 99.978000
value : 99.976000
value : 99.979000
value : 99.978000
value : 99.978000
value : 99.967000
value : 99.990000
value : 99.999000
value : 99.968000
value : 99.990000
value : 99.979000
value : 99.990000
value : 99.990000
value : 99.998000
value : 100.000000
value : 100.000000
value : 52.693000
  137390 value : 52.693000
value : 52.839000
value : 52.814000
  137388 value : 52.839000
value : 52.868000
  137390 value : 52.868000
value : 52.852000
  137390 value : 52.852000
value : 52.866000
value : 52.765000
  137390 value : 52.765000
  137390 value : 52.866000
  137390 value : 52.814000
value : 52.879000
  137390 value : 52.879000

@davecheney
Copy link
Contributor

I wonder if this is a montonic time vs wall clock time issue. Could you do an experiments for me:

Change the code to use time.Since rather than computing the difference between two Unix nano values.

Ref: https://pkg.go.dev/time#hdr-Monotonic_Clocks

@YoshikiShibata
Copy link
Author

@davecheney I will try again with the following program:
https://play.golang.org/p/cc6aj8RUPxf

@YoshikiShibata
Copy link
Author

@davecheney You are right. The problem was how to measure the duration. With time.Since, the output of the program is:

--snip--
   27716 value : 100.001500
   30463 value : 100.001542
   33770 value : 100.003167
   37496 value : 100.002750
   43148 value : 100.001666
   56605 value : 100.001833
   60132 value : 100.001166
   60254 value : 100.002333
   86963 value : 100.002375
  109972 value : 100.002250
  219979 value : 100.000750
  411978 value : 100.002833

I close this issue

@golang golang locked and limited conversation to collaborators Sep 7, 2022
@julieqiu julieqiu removed this from Go Security Sep 8, 2022
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
@davecheney @YoshikiShibata @gopherbot @seankhliao