{"action":"created","issue":{"url":"https://api.github.com/repos/golang/go/issues/17696","repository_url":"https://api.github.com/repos/golang/go","labels_url":"https://api.github.com/repos/golang/go/issues/17696/labels{/name}","comments_url":"https://api.github.com/repos/golang/go/issues/17696/comments","events_url":"https://api.github.com/repos/golang/go/issues/17696/events","html_url":"https://github.com/golang/go/issues/17696","id":186369400,"number":17696,"title":"time: time.Sleep and time.NewTimer: Fix duration parameter error","user":{"login":"johnrs","id":5679210,"avatar_url":"https://avatars.githubusercontent.com/u/5679210?v=3","gravatar_id":"","url":"https://api.github.com/users/johnrs","html_url":"https://github.com/johnrs","followers_url":"https://api.github.com/users/johnrs/followers","following_url":"https://api.github.com/users/johnrs/following{/other_user}","gists_url":"https://api.github.com/users/johnrs/gists{/gist_id}","starred_url":"https://api.github.com/users/johnrs/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/johnrs/subscriptions","organizations_url":"https://api.github.com/users/johnrs/orgs","repos_url":"https://api.github.com/users/johnrs/repos","events_url":"https://api.github.com/users/johnrs/events{/privacy}","received_events_url":"https://api.github.com/users/johnrs/received_events","type":"User","site_admin":false},"labels":[{"id":199753992,"url":"https://api.github.com/repos/golang/go/labels/OS-Windows","name":"OS-Windows","color":"ededed","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":{"url":"https://api.github.com/repos/golang/go/milestones/42","html_url":"https://github.com/golang/go/milestones/Go1.8Maybe","labels_url":"https://api.github.com/repos/golang/go/milestones/42/labels","id":1748849,"number":42,"title":"Go1.8Maybe","description":"","creator":{"login":"bradfitz","id":2621,"avatar_url":"https://avatars.githubusercontent.com/u/2621?v=3","gravatar_id":"","url":"https://api.github.com/users/bradfitz","html_url":"https://github.com/bradfitz","followers_url":"https://api.github.com/users/bradfitz/followers","following_url":"https://api.github.com/users/bradfitz/following{/other_user}","gists_url":"https://api.github.com/users/bradfitz/gists{/gist_id}","starred_url":"https://api.github.com/users/bradfitz/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bradfitz/subscriptions","organizations_url":"https://api.github.com/users/bradfitz/orgs","repos_url":"https://api.github.com/users/bradfitz/repos","events_url":"https://api.github.com/users/bradfitz/events{/privacy}","received_events_url":"https://api.github.com/users/bradfitz/received_events","type":"User","site_admin":false},"open_issues":81,"closed_issues":126,"state":"open","created_at":"2016-05-04T23:40:26Z","updated_at":"2016-10-31T20:47:37Z","due_on":"2017-01-31T00:00:00Z","closed_at":null},"comments":5,"created_at":"2016-10-31T19:04:54Z","updated_at":"2016-10-31T20:55:14Z","closed_at":null,"body":"### What version of Go are you using (`go version`)?\r\ngo version go1.7.3 windows/amd64\r\n\r\n### What operating system and processor architecture are you using (`go env`)?\r\nset GOARCH=amd64\r\nset GOHOSTARCH=amd64\r\nset GOHOSTOS=windows\r\nset GOOS=windows\r\n\r\n### What did you do?\r\nI wrote a test which is basically a loop consisting of two things: Some busy work for about 500us and a call to time.Sleep(1 * time.Millisecond).\r\n\r\nHere's a link to the test program: https://play.golang.org/p/VYGvIbTPo3\r\n\r\nIt can't run on the playground, so you will have to grab it and run it yourself.\r\n\r\n### What did you expect to see?\r\n```\r\n  work(~500us) + time.Sleep(1ms): 1.500000ms    ... or slightly more\r\n  work(~500us) + time.After(1ms): 1.500000ms    ... or slightly more\r\n```\r\n\r\n### What did you see instead?\r\n```\r\n  work(~500us) + time.Sleep(1ms): 1.030103ms\r\n  work(~500us) + time.After(1ms): 1.110111ms\r\n```\r\n\r\n### Discussion\r\nI believe that there are errors in the doc's for time.Sleep and time.NewTimer.  They both make similar statements regarding the duration.\r\n\r\n`Sleep pauses the current goroutine for at least the duration d.`\r\n\r\n`NewTimer creates a new Timer that will send the current time on its channel after at least duration d.`\r\n\r\nIf these are correct, then the test loops should take ~1.5ms or longer per pass.  But they don't.\r\n\r\nI believe that `at least the duration d` was an attempt to convey that overhead might result in a longer duration than requested.  But there are two other factors which might result in a shortened duration, sometime **MUCH** shorter.  These factors are the resolution and phase of the time source used for these functions.\r\n\r\nIn Windows, the resolution is normally 1ms for Go programs.  I'll refer to this value as r, short for resolution.  I'm not sure what it is on other platforms.  If you run the test program it will measure and display it.  Please let me know what you find.\r\n\r\nI believe that in general the duration can be as short as d-r (rather than d).  How short simply depends on what the phase of the time source when you use it.  Thus if you ask for a 100ms delay you will end up with something between 99 and 100 (plus overhead).  Thus as you use smaller values of d (approaching r) the problem gets worse.  By itself, this isn't too bad.  But now the other shoe drops.\r\n\r\nIn the specific case that you ask for a delay of r (or anything between 1 and r), then the delay  can be anything between 0 and r.  Actually, for a reason I don't quite understand, the lowest delay I've actually seen is about 50us, not 0.    Even so, that is 20 times less than the 1ms requested.  This was drastic enough to break some of my code.  I changed d from 1ms to 2ms.  The resulting delay is between 1 and 2ms (plus overhead).\r\n\r\nCan this cause a problem?  Generally, in a loop only the first pass is affected, because the loop gets in phase with the timing source.  So this might or might not be bad for you.  If it is, put a sleep 1ms call just before the loop.\r\n\r\nBut imagine that you are using time.After to set up a timeout, but it occurs too quickly.  Perhaps 20 times too quickly.  This can cause intermittent, non-deterministic, bogus timeouts, even on a single-threaded program.  Ouch!  This is what bit me.\r\n\r\nAnother gotcha:  Using d of 10ms now, but Go Windows switches r from 1ms to 15.6ms.  Instead of a delay of 9 - 10ms you now get 0 - 15.6ms.\r\n\r\n### Possible Solutions\r\nThe really bad case when d is between 1 and r could be detected causing d to be changed to r+1.  Tacky, in my opinion.  Alternatively, vet could look for this case.\r\n\r\nMost programming languages I've worked in allow this to happen, but they don't document it incorrectly.  This seems like the best solution to me.  Simply fix the doc's to reflect reality.\r\n\r\nPerhaps a paragraph at the top describing what the \"resolution of the time source\" means, what it is for some typical platforms, and an example of a simple routine to determine what yours is.  Maybe even a system call to retrieve it.\r\n\r\nThen, change the current time.Sleep description from\r\n\r\n`\r\nSleep pauses the current goroutine for at least the duration d. A negative or zero duration causes Sleep to return immediately.\r\n`\r\n\r\nto something like\r\n\r\n`\r\nSleep pauses the current goroutine for at least the duration d - 1.  A duration less than or equal to the time source resolution can cause Sleep to return quickly.  A negative or zero duration causes Sleep to return immediately.\r\n`\r\n\r\nAnd similar for time.NewTimer's description.\r\n"},"comment":{"url":"https://api.github.com/repos/golang/go/issues/comments/257417943","html_url":"https://github.com/golang/go/issues/17696#issuecomment-257417943","issue_url":"https://api.github.com/repos/golang/go/issues/17696","id":257417943,"user":{"login":"johnrs","id":5679210,"avatar_url":"https://avatars.githubusercontent.com/u/5679210?v=3","gravatar_id":"","url":"https://api.github.com/users/johnrs","html_url":"https://github.com/johnrs","followers_url":"https://api.github.com/users/johnrs/followers","following_url":"https://api.github.com/users/johnrs/following{/other_user}","gists_url":"https://api.github.com/users/johnrs/gists{/gist_id}","starred_url":"https://api.github.com/users/johnrs/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/johnrs/subscriptions","organizations_url":"https://api.github.com/users/johnrs/orgs","repos_url":"https://api.github.com/users/johnrs/repos","events_url":"https://api.github.com/users/johnrs/events{/privacy}","received_events_url":"https://api.github.com/users/johnrs/received_events","type":"User","site_admin":false},"created_at":"2016-10-31T20:55:14Z","updated_at":"2016-10-31T20:55:14Z","body":"Wow!  I was thinking that perhaps the Linux time source would be good to 1us.  48ns!\r\n\r\nI see what you mean about the resulting durations being a bit (about 25%) too long.  That makes no sense at all to me.  It makes me wonder if there is a math error somewhere (using 4 instead of 5, or vice versa).  Perhaps it is worth creating an issue for this.  25% is too much to ignore."}}
{"actor":{"display_login":"johnrs"}}