Golang中Goroutine访问方法因日志记录被优化的问题探讨

Golang中Goroutine访问方法因日志记录被优化的问题探讨 我遇到了代码中的一些奇怪行为。我在四台不同的机器上进行了测试，包括两台Manjaro系统（4.20/5.0内核）和两台VPS（Debian9/4.15内核，Ubuntu 16.04lts/4.4内核）。在四台机器中有三台上，这段代码按预期运行。然而在第四台机器（Debian）上，一个负责收集和推送指标的goroutine似乎从未工作过。所有机器上都使用相同的Go版本（1.11.5）。

以下是指标任务的相关部分和调用它的处理程序：

### 指标任务

type MetricsTask struct {
    running     bool
    ticker      *time.Ticker

    counters map[string]float64
    gauges   map[string]float64

    counterBuf chan metricsAction
    gaugeBuf   chan metricsAction
}


func New() *MetricsTask {
// 初始化映射、通道、定时器
}

type metricsAction struct {
    name string
    val  float64
}

// 从其他goroutine调用此函数来增加指定名称的计数器
func (m *MetricsTask) CounterIncrease(name string, val float64) {
	m.counterBuf <- metricsAction{name: name, val: val}
}

func (m *MetricsTask) loop() {
    for m.running {
		select {
		case item := <-m.counterBuf:
            // 将测量值推送到指定名称
			m.ensureCounter(item.name)
			m.counters[item.name] += item.val
		case <-m.ticker.C:
            // 推送指标
            // ...
		}
	}
}


#### 处理程序

// 尝试插入指标，在一台机器上静默失败
func handler() {

    // 这个日志条目以某种方式修复了指标任务，没有它CounterIncrease不会被调用或者被调用时参数为空
    logrus.Debug("插入指标")
    metrics.CounterIncrease("my_counter", 1)

}

从日志中我看到指标任务已经启动等等，但方法’CounterIncrease’从未被调用。然后我做的唯一更改是在调用该方法之前添加日志行，不知何故它现在工作了。这是为什么？ 当尝试使用Goland和delve进行远程调试时，似乎’CounterIncrease’被调用了，但参数为空，但这可能只是向用户显示的内容？但最奇怪的部分是为什么这在我四台机器中的三台上都能工作？

编辑：使用日志和不使用日志编译了几次，似乎总是按照描述的方式修复/破坏代码。


更多关于Golang中Goroutine访问方法因日志记录被优化的问题探讨的实战教程也可以访问 https://www.itying.com/category-94-b0.html

2 回复

这看起来像是一个竞态条件。插入日志行会使函数稍微变慢。但代码不完整，例如处理程序是如何被调用的？所以很难判断到底发生了什么。

更多关于Golang中Goroutine访问方法因日志记录被优化的问题探讨的实战系列教程也可以访问 https://www.itying.com/category-94-b0.html


这是一个典型的并发执行时序问题，很可能是由于goroutine调度和通道操作的交互导致的。问题出现在CounterIncrease方法中的通道发送操作可能会在没有接收者准备好的情况下阻塞。

问题分析

在你的代码中，CounterIncrease方法向缓冲通道发送数据：

func (m *MetricsTask) CounterIncrease(name string, val float64) {
    m.counterBuf <- metricsAction{name: name, val: val}
}

如果counterBuf通道已满或者接收goroutine(loop方法)尚未开始运行，这个发送操作会阻塞。添加日志语句改变了程序的执行时序，使得loopgoroutine有更多时间在CounterIncrease被调用前开始运行。

解决方案

方案1：使用带缓冲的通道和select超时

func (m *MetricsTask) CounterIncrease(name string, val float64) {
    select {
    case m.counterBuf <- metricsAction{name: name, val: val}:
        // 正常发送
    case <-time.After(100 * time.Millisecond):
        // 超时处理，避免永久阻塞
        logrus.Warnf("指标通道阻塞，丢弃指标: %s", name)
    }
}

方案2：使用非阻塞发送

func (m *MetricsTask) CounterIncrease(name string, val float64) {
    select {
    case m.counterBuf <- metricsAction{name: name, val: val}:
        // 发送成功
    default:
        // 通道已满，处理背压
        logrus.Warnf("指标通道已满，丢弃指标: %s", name)
    }
}

方案3：确保MetricsTask正确初始化

func New() *MetricsTask {
    m := &MetricsTask{
        running:    true,
        ticker:     time.NewTicker(30 * time.Second),
        counters:   make(map[string]float64),
        gauges:     make(map[string]float64),
        counterBuf: make(chan metricsAction, 100), // 足够的缓冲区
        gaugeBuf:   make(chan metricsAction, 100),
    }
    
    // 立即启动处理循环
    go m.loop()
    
    return m
}

方案4：添加启动同步

type MetricsTask struct {
    running     bool
    ticker      *time.Ticker
    ready       chan struct{} // 新增：用于同步启动
    
    counters map[string]float64
    gauges   map[string]float64
    
    counterBuf chan metricsAction
    gaugeBuf   chan metricsAction
}

func New() *MetricsTask {
    m := &MetricsTask{
        running:    true,
        ticker:     time.NewTicker(30 * time.Second),
        ready:      make(chan struct{}),
        counters:   make(map[string]float64),
        gauges:     make(map[string]float64),
        counterBuf: make(chan metricsAction, 100),
        gaugeBuf:   make(chan metricsAction, 100),
    }
    
    go m.loop()
    <-m.ready // 等待loop goroutine启动完成
    
    return m
}

func (m *MetricsTask) loop() {
    close(m.ready) // 通知已启动
    
    for m.running {
        select {
        case item := <-m.counterBuf:
            m.ensureCounter(item.name)
            m.counters[item.name] += item.val
        case <-m.ticker.C:
            // 推送指标
        }
    }
}

根本原因

不同机器上的行为差异是由于：

  • goroutine调度器的非确定性
  • 不同系统上的CPU核心数量和负载差异
  • 内核调度策略的细微差别

添加日志语句增加了执行时间，改变了goroutine的调度顺序，使得loopgoroutine有机会在CounterIncrease被调用前开始运行。

推荐使用方案3或方案4，它们通过适当的缓冲和启动同步来确保可靠性，而不依赖执行时序。

回到顶部