Timer abnormal action

[liuzhuangbb]

Please help to see a timer problem, thank you.

go version go1.15.2 linux/amd64
CentOS Linux release 7.3.1611 (Core)

Problem Description:

The test is normal under win10, normal under Linux subsystem of win10, and abnormal on centos7 server. The problem is that in addition to executing according to the specified time, it is executed once in the previous few seconds, and the time is not fixed.

code

package main

import (
 "io/ioutil"
 "log"
 "net/http"
 "os"
 "runtime"
 "strconv"
 "time"
)

var fileloger *log.Logger
var logFile *os.File

func initLogger() {
 file := "./logs/" + time.Now().Format("20060102") + ".log"
 var err error
 logFile, err = os.OpenFile(file, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0766)
 //defer logFile.Close()
 if err != nil {
  panic(err)
 }
 fileloger = log.New(logFile, "", log.LUTC) // 将文件设置为loger作为输出
 return
}

func CreatLogger() {
 initLogger()
 for {
  now := time.Now()                                
  next := now.Add(time.Hour * 24)               
  next = time.Date(next.Year(), next.Month(), next.Day(), 0, 0, 0, 0, next.Location()) 
  t := time.NewTimer(next.Sub(now))         
  <-t.C
  log.Println(time.Now(), "create file")
  logFile.Close()
  t.Stop()
 
  initLogger()
 }
}

func searchHandler(w http.ResponseWriter, r *http.Request) {
 fileloger.Println(string(body))
 w.Write([]byte(strconv.Itoa(runtime.NumGoroutine())))
}

func main() {
 runtime.GOMAXPROCS(runtime.NumCPU())
 go CreatLogger()
 http.HandleFunc("/search", searchHandler)
 log.Println("Server start listen on port:", 18080)
 err := http.ListenAndServe(":18080", nil)
 if err != nil {
  log.Fatal("ListenAndServe: ", err.Error())
 }

}

logs ：

2020/10/09 14:48:52 Server start listen on port: 18080

2020/10/09 23:59:57 2020-10-09 23:59:57.197181062 +0800 CST m=+33067.952413287 create file

2020/10/10 00:00:00 2020-10-10 00:00:00.00015083 +0800 CST m=+33070.755383073 create file

2020/10/10 23:59:52 2020-10-10 23:59:52.519040092 +0800 CST m=+119470.755332920 create file

2020/10/11 00:00:00 2020-10-11 00:00:00.000123355 +0800 CST m=+119478.236416191 create file

2020/10/11 23:59:58 2020-10-11 23:59:58.635823011 +0800 CST m=+205878.236415904 create file

2020/10/12 00:00:00 2020-10-12 00:00:00.000176828 +0800 CST m=+205879.600769738 create file

[petrus]

It looks like your algorithms have a conflict between wall and monotonic clocks. The duration is calculated using the wall clock and the timer duration uses the monotonic clock, if it exists. The wall clock appears to be a off, it could be off by a lot.

Package time

Monotonic Clocks

[ncw (Nick Craig-Wood)]

@liuzhuangbb

The test is normal under win10, normal under Linux subsystem of win10, and abnormal on centos7 server.

It looks like the timer is a little inaccurate under Centos 7.3 so it fires a little bit before midnight then the code resets the timer to fire at midnight again.

Centos 7.3 is running kernel 3.10.0 which was initially released in June 2013. My guess is that the Linux timers were a bit off in that kernel but they’ve been fixed now.

If you want to add a workaround, just check to see if the hour is 23 and if it is, go round again.

[liuzhuangbb]

Thanks