Golang中Timer异常行为问题排查

Golang中Timer异常行为问题排查

请帮忙查看一个定时器问题，谢谢。

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

问题描述：

在 win10 下测试正常，在 win10 的 Linux 子系统下也正常，在 centos7 服务器上出现异常。问题是除了按照指定时间执行外，还会在前几秒执行一次，并且时间不固定。

代码

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())
 }

}

日志：

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


更多关于Golang中Timer异常行为问题排查的实战教程也可以访问 https://www.itying.com/category-94-b0.html

4 回复

谢谢

更多关于Golang中Timer异常行为问题排查的实战系列教程也可以访问 https://www.itying.com/category-94-b0.html


看起来你的算法在挂钟和单调钟之间存在冲突。持续时间是使用挂钟计算的，而定时器持续时间（如果存在）使用的是单调钟。挂钟似乎存在偏差，而且偏差可能很大。

time包

单调钟

liuzhuangbb:

在 Windows 10 下测试正常，在 Windows 10 的 Linux 子系统下测试正常，但在 CentOS 7 服务器上出现异常。

看起来在 CentOS 7.3 下计时器有点不准确，导致它在午夜前一点点就触发了，然后代码又将计时器重置为在午夜再次触发。

CentOS 7.3 运行的是内核 3.10.0，该内核最初于 2013 年 6 月发布。我猜在那个内核版本中 Linux 计时器有点问题，但现在已经修复了。

如果你想添加一个变通方案，只需检查小时数是否为 23，如果是，就再循环一次。

这是一个典型的Timer在并发环境下被误用的问题。问题出在CreatLogger函数中Timer没有被正确重置，导致goroutine竞争条件。

关键问题分析：

  1. log.Println和fileloger.Println使用了不同的logger，导致日志输出到不同位置
  2. Timer在循环中没有被正确管理，可能触发多次

修复后的代码示例：

package main

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

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

func initLogger() error {
    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)
    if err != nil {
        return err
    }
    fileLogger = log.New(logFile, "", log.LUTC)
    return nil
}

func CreatLogger() {
    // 初始化日志
    if err := initLogger(); err != nil {
        log.Printf("Failed to init logger: %v", err)
        return
    }
    
    for {
        now := time.Now()
        // 计算到第二天0点的时间
        next := now.Add(24 * time.Hour)
        next = time.Date(next.Year(), next.Month(), next.Day(), 0, 0, 0, 0, next.Location())
        
        timer := time.NewTimer(next.Sub(now))
        
        // 等待定时器触发
        <-timer.C
        
        // 使用同一个logger输出
        log.Printf("Creating new log file at %v", time.Now())
        
        // 关闭旧文件
        if logFile != nil {
            logFile.Close()
        }
        
        // 重新初始化logger
        if err := initLogger(); err != nil {
            log.Printf("Failed to reinit logger: %v", err)
            timer.Stop()
            return
        }
        
        // 停止定时器（虽然已经触发，但显式停止是好的实践）
        timer.Stop()
    }
}

func searchHandler(w http.ResponseWriter, r *http.Request) {
    body, _ := ioutil.ReadAll(r.Body)
    fileLogger.Println(string(body))
    w.Write([]byte(strconv.Itoa(runtime.NumGoroutine())))
}

func main() {
    runtime.GOMAXPROCS(runtime.NumCPU())
    
    // 确保日志目录存在
    os.MkdirAll("./logs", 0755)
    
    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())
    }
}

主要修改点：

  1. 统一使用log.Printf进行控制台日志输出，避免混合使用log.Println和fileLogger.Println
  2. 在每次循环中创建新的Timer，避免重用已触发的Timer
  3. 添加错误处理，防止initLogger失败导致panic
  4. 确保日志目录存在
  5. 显式停止Timer（虽然已经触发）

问题根源：原始代码中Timer可能在goroutine调度时被意外触发，特别是在系统负载变化时。修复后的代码确保每个循环周期都创建新的Timer，避免了Timer状态的不确定性。

回到顶部