linux - Golang Scheduler之谜: Linux vs Mac OS X

我在Go调度程序中遇到了一些神秘的行为，并且我对正在发生的事情非常好奇。要点是，除非在Linux上先进行runtime.Gosched()调用，否则log.Printf()不会按预期工作，但在OS X上这两种情况下均按预期工作。这是重现此行为的最小设置:
主goroutine sleep 1000毫秒(1毫秒)，每次 sleep 后将伪消息通过一个 channel 推送到另一个goroutine。第二个goroutine监听新消息，每收到一条消息，它就会工作10毫秒。因此，没有任何runtime.Gosched()调用，该程序将需要10秒钟才能运行。
当我在第二个goroutine中添加定期的runtime.Gosched()调用时，按预期，程序运行时间在Mac上缩减为1秒。但是，当我尝试在Ubuntu上运行同一程序时，仍然需要10秒钟。我确保在两种情况下都设置runtime.GOMAXPROCS(1)。
这真的很奇怪:如果我只是在runtime.Gosched()调用之前添加一条日志记录语句，那么该程序也会突然在预期的1秒内在Ubuntu上运行。

package main

import (
    "time"
    "log"
    "runtime"
)

func doWork(c chan int) {
    for {
        <-c

        // This outer loop will take ~10ms.
        for j := 0; j < 100 ; j++ {
            // The following block of CPU work takes ~100 microseconds
            for i := 0; i < 300000; i++ {
                _ = i * 17
            }
            // Somehow this print statement saves the day in Ubuntu
            log.Printf("donkey")
            runtime.Gosched()
        }
    }
}

func main() {
    runtime.GOMAXPROCS(1)
    c := make(chan int, 1000)
    go doWork(c)

    start := time.Now().UnixNano()
    for i := 0; i < 1000; i++ {
        time.Sleep(1 * time.Millisecond)

        // Queue up 10ms of work in the other goroutine, which will backlog
        // this goroutine without runtime.Gosched() calls.
        c <- 0
    }

    // Whole program should take about 1 second to run if the Gosched() calls
    // work, otherwise 10 seconds.
    log.Printf("Finished in %f seconds.", float64(time.Now().UnixNano() - start) / 1e9)
}

其他详细信息:我正在运行go1.10 darwin/amd64，并使用env GOOS=linux GOARCH=amd64 go build ...我尝试了一些简单的变体:

只需进行log.Printf()调用，而无需Gosched()

两次调用Gosched()

保留Gosched()调用，但将log.Printf()调用替换为虚拟函数调用

所有这些都比调用log.Printf()和Gosched()慢约10倍。
任何见解将不胜感激!这个示例当然是非常人为的，但是在编写Websocket广播服务器时出现了问题，导致性能大大下降。
编辑:在我的示例中，我摆脱了无关紧要的部分，使事情变得更加透明。我发现，没有print语句，runtime.Gosched()调用仍在运行，只是它们似乎延迟了固定的5ms，在下面的示例中，当程序应该完成时，导致总运行时间几乎恰好是5秒即时(并且在我的Mac上或在带有print语句的Ubuntu上也是如此)。

package main

import (
    "log"
    "runtime"
    "time"
)

func doWork() {
    for {
        // This print call makes the code run 20x faster
        log.Printf("donkey")

        // Without this line, the program never terminates (as expected). With this line
        // and the print call above it, the program takes <300ms as expected, dominated by
        // the sleep calls in the main goroutine. But without the print statement, it
        // takes almost exactly 5 seconds.
        runtime.Gosched()
    }
}

func main() {
    runtime.GOMAXPROCS(1)
    go doWork()

    start := time.Now().UnixNano()
    for i := 0; i < 1000; i++ {
        time.Sleep(10 * time.Microsecond)

        runtime.Gosched()
    }

    log.Printf("Finished in %f seconds.", float64(time.Now().UnixNano() - start) / 1e9)
}

最佳答案

在Ubuntu上，我无法在一秒钟而不是十秒钟内重现您的问题，

输出:

$ uname -srvm
Linux 4.13.0-37-generic #42-Ubuntu SMP Wed Mar 7 14:13:23 UTC 2018 x86_64
$ go version
go version devel +f1deee0e8c Mon Apr 2 20:18:14 2018 +0000 linux/amd64
$ go build rampatowl.go && time ./rampatowl
2018/04/02 16:52:04 Finished in 1.122870 seconds.
real    0m1.128s
user    0m1.116s
sys 0m0.012s
$

rampatowl.go:

package main

import (
    "log"
    "runtime"
    "time"
)

func doWork(c chan int) {
    for {
        <-c

        // This outer loop will take ~10ms.
        for j := 0; j < 100; j++ {
            // The following block of CPU work takes ~100 microseconds
            for i := 0; i < 300000; i++ {
                _ = i * 17
            }
            // Somehow this print statement saves the day in Ubuntu
            //log.Printf("donkey")
            runtime.Gosched()
        }
    }
}

func main() {
    runtime.GOMAXPROCS(1)
    c := make(chan int, 1000)
    go doWork(c)

    start := time.Now().UnixNano()
    for i := 0; i < 1000; i++ {
        time.Sleep(1 * time.Millisecond)

        // Queue up 10ms of work in the other goroutine, which will backlog
        // this goroutine without runtime.Gosched() calls.
        c <- 0
    }

    // Whole program should take about 1 second to run if the Gosched() calls
    // work, otherwise 10 seconds.
    log.Printf("Finished in %f seconds.", float64(time.Now().UnixNano()-start)/1e9)
}