1.16.3 update

README.md

@@ -1,11 +1,13 @@
 # sleeptest
-golang `time.Sleep()` test 
+golang `time.Sleep()` test
+
+IMPORTANT: NOTE: 1.16.3 seems to solve the issue outlined here. Feel free to continue to read if you have nothing better to do.
 
 ### TL;DR
 
 `time.Sleep(1 * time.Hour)` can sometimes sleep for longer than the 1 hour that is specified, although I generally see it between 3-5 minutes when it is behaving badly in my experience. Testing against go1.16.2 currently.
 
-macOS has a problem on both M1 and Intel. A Digital Ocean Linux droplet works perfectly fine. See description and data below. 
+macOS has a problem on both M1 and Intel. A Digital Ocean Linux droplet works perfectly fine. See description and data below.
 
 See https://github.com/golang/go/issues/44343 if you've stumbled upon this from some other place.
 
@@ -21,7 +23,7 @@ Please tell me if there are any bugs in this code that could be causing this iss
 
 This test is to help determine how `time.Sleep()` functions in Go in various scenarios.
 
-I wrote a Go program that called a shell script that executed multiple command line tools - each of which accessed the network. The shell script was executed serially using `exec.Command()`, in a loop 3x, being passed a different parameter each time. Once all of the calls completed, the Go program would execute one final shell script and then `time.Sleep(1 * time.Hour)` before continuing the endless for loop. 
+I wrote a Go program that called a shell script that executed multiple command line tools - each of which accessed the network. The shell script was executed serially using `exec.Command()`, in a loop 3x, being passed a different parameter each time. Once all of the calls completed, the Go program would execute one final shell script and then `time.Sleep(1 * time.Hour)` before continuing the endless for loop.
 
 The original shell script would gather data from AWS, format it, and then post it to a chat room, although the exact task didn't seem to influence the sleep timing issue since it was outside the scope of the sleep itself. I noticed that in the chat room the first few times this ran, the timestamps would be one hour later each time. If the script finished at 1:03 the next would would begin at 2:03, etc. However, after a few runs the times would increase to 3 minutes or more. One time I even saw a 9 minute discrepancy...lost time...mind you, the timestamps were very course, so I wrote the program here for more granularity and to distill the problem down.
 

main.py

@@ -0,0 +1,8 @@
+import time
+from datetime import datetime
+
+while 1:
+    print("ABOUT TO SLEEP: ", datetime.utcnow())
+    time.sleep(60*60)
+    print("AWAKE:          ", datetime.utcnow())
+    print("----------------")

results/digitalocean-screen.txt → results/digitalocean-screen-1-16-2-linux-amd64.txt

@@ -1,4 +1,4 @@
-FINAL RUN
+FINAL RUN go1.16.2 linux/amd64
 
 <<< GO SLEEPING... 2021-03-21 00:22:20.416241647 +0000 UTC
 =======================

results/intel-screen.txt → results/intel-screen-1-16-2-darwin-amd64.txt

@@ -1,4 +1,4 @@
-FINAL RUN
+FINAL RUN go1.16.2 darwin/amd64
 
 <<< GO SLEEPING... 2021-03-20 19:24:51.261283 +0000 UTC
 =======================

results/m1-screen.txt → results/m1-screen-1-16-2-darwin-arm64.txt

@@ -1,4 +1,4 @@
-FINAL RUN
+FINAL RUN go1.16.2 darwin/arm64
 
 <<< GO SLEEPING... 2021-03-20 20:26:17.240372 +0000 UTC
 =======================

results/m1-screen-1-16-3-darwin-amd64.txt

@@ -0,0 +1,29 @@
+ FINAL RUN go1.16.3 darwin/amd64
+
+ <<< GO SLEEPING... 2021-04-02 13:30:24.279499 +0000 UTC
+ =======================
+ zzz GO PREV SLEEP TIME: 59m59.992974s
+ zzz GO ALL SLEEP TIMES: [59m59.90839s 1h0m0.062829s 59m59.992974s]
+ >>> GO STARTING... 2021-04-02 14:30:24.272473 +0000 UTC
+ GO PROCESSING COMMAND 1 uptime
+  start uptime: Fri Apr 2 14:30:24 UTC 2021
+ 10:30  up 10 days,  1:07, 5 users, load averages: 2.08 2.13 1.99
+  sleeping for 4 seconds...
+  end uptime: Fri Apr 2 14:30:28 UTC 2021
+ GO PROCESSING COMMAND 2 uptime
+  start uptime: Fri Apr 2 14:30:28 UTC 2021
+ 10:30  up 10 days,  1:07, 5 users, load averages: 2.08 2.13 1.99
+  sleeping for 5 seconds...
+  end uptime: Fri Apr 2 14:30:33 UTC 2021
+ GO PROCESSING COMMAND 3 uptime
+  start uptime: Fri Apr 2 14:30:33 UTC 2021
+ 10:30  up 10 days,  1:07, 5 users, load averages: 1.92 2.10 1.97
+  sleeping for 4 seconds...
+  end uptime: Fri Apr 2 14:30:37 UTC 2021
+ GO PROCESSING ADDITIONAL COMMAND:  uptime
+  start uptime: Fri Apr 2 14:30:37 UTC 2021
+ 10:30  up 10 days,  1:08, 5 users, load averages: 1.76 2.06 1.96
+  sleeping for 6 seconds...
+  end uptime: Fri Apr 2 14:30:43 UTC 2021
+ GO PROCESSING TIME: 19.341813s
+ <<< GO SLEEPING... 2021-04-02 14:30:43.614286 +0000 UTC

results/m1-screen-1-16-3-darwin-arm64.txt

@@ -0,0 +1,29 @@
+ FINAL RUN go1.16.3 darwin/arm64
+
+ <<< GO SLEEPING... 2021-04-02 20:36:43.126732 +0000 UTC
+ =======================
+ zzz GO PREV SLEEP TIME: 2h21m22.47225s (computer was asleep)
+ zzz GO ALL SLEEP TIMES: [59m59.979776s 1h0m0.019405s 59m59.98669s 1h0m0.001715s 1h0m0.001987s 59m59.976767s 2h21m22.47225s]
+ >>> GO STARTING... 2021-04-02 22:58:05.598982 +0000 UTC
+ GO PROCESSING COMMAND 1 uptime
+  start uptime: Fri Apr 2 22:58:05 UTC 2021
+ 18:58  up 10 days,  9:35, 5 users, load averages: 2.22 2.85 2.81
+  sleeping for 4 seconds...
+  end uptime: Fri Apr 2 22:58:09 UTC 2021
+ GO PROCESSING COMMAND 2 uptime
+  start uptime: Fri Apr 2 22:58:09 UTC 2021
+ 18:58  up 10 days,  9:35, 5 users, load averages: 2.21 2.83 2.81
+  sleeping for 7 seconds...
+  end uptime: Fri Apr 2 22:58:16 UTC 2021
+ GO PROCESSING COMMAND 3 uptime
+  start uptime: Fri Apr 2 22:58:16 UTC 2021
+ 18:58  up 10 days,  9:35, 5 users, load averages: 2.24 2.82 2.80
+  sleeping for 5 seconds...
+  end uptime: Fri Apr 2 22:58:21 UTC 2021
+ GO PROCESSING ADDITIONAL COMMAND:  uptime
+  start uptime: Fri Apr 2 22:58:21 UTC 2021
+ 18:58  up 10 days,  9:35, 5 users, load averages: 2.22 2.81 2.80
+  sleeping for 7 seconds...
+  end uptime: Fri Apr 2 22:58:28 UTC 2021
+ GO PROCESSING TIME: 23.145532s
+ <<< GO SLEEPING... 2021-04-02 22:58:28.744514 +0000 UTC

results/m1-terminal.txt → results/m1-terminal-1-16-2-darwin-arm64.txt

@@ -1,4 +1,4 @@
-COMPLETE RUN
+COMPLETE RUN go1.16.2 darwin/arm64
 
 >>> GO STARTING... 2021-03-20 12:59:16.686704 +0000 UTC
 GO PROCESSING COMMAND 1 uptime