为何写入前的休眠会导致后续写入操作变慢？

问题现象 #

向文件（或套接字）写入时发现反常现象：两次写入之间的休眠时间越长，写入操作本身的耗时就越久。分别用Go和Python实现测试用例，在Mac和Linux机器上均得到一致结果。

核心计时逻辑如下：

sleep(x)
startTime = now()
write(msg)
endTime = now()
writeTime = endTime - startTime

尽管休眠时间未被计入计时，但sleep时长增加时，writeTime显著变长。

测试代码 #

Python 实现 #

import time

f = open("/dev/null", "w")

msg = "0" * 1024


for sleepMicros in [0, 1, 10, 100, 1000]:
    totalSendTime = 0
    cntOver10us = 0
    for _ in range(10000):
        time.sleep(sleepMicros / 1000 / 1000)
        startSendTime = time.time()
        f.write(msg)
        sentTime = time.time()

        timeInSend = sentTime - startSendTime
        totalSendTime += timeInSend
        if timeInSend > 10 / 1000 / 1000:
            cntOver10us += 1

    print(f"sleep: {sleepMicros}us\tTotal time in send: {totalSendTime * 1000}ms\tCount over 10us: {cntOver10us}")

Go 实现 #

package main

import (
    "fmt"
    "os"
    "time"
)

func main() {
    f, _ := os.Create("/dev/null")

    msg := make([]byte, 1024)

    for _, sleepMicros := range []time.Duration{0, 1, 10, 100, 1000} {
        totalSendTime := time.Duration(0)
        cntOver10us := 0
        sleepDuration := sleepMicros * time.Microsecond
        for i := 0; i < 10000; i++ {
            time.Sleep(sleepDuration)
            startSendTime := time.Now()
            _, err := f.Write(msg)
            sentTime := time.Now()

            if err != nil {
                fmt.Println("SendMessage got error", err)
            }
            timeInSend := sentTime.Sub(startSendTime)
            totalSendTime += timeInSend
            if timeInSend > 10*time.Microsecond {
                cntOver10us++
            }
        }
        fmt.Println("sleep:", sleepDuration, "\tTotal time in send:", totalSendTime, "\tCount over 10us:", cntOver10us)
    }
}

测试结果 #

Python 运行结果 #

(venv) % python write_to_devnull_mini.py
sleep: 0us  Total time in send: 2.109527587890625ms Count over 10us: 0
sleep: 1us  Total time in send: 1.9390583038330078ms    Count over 10us: 0
sleep: 10us Total time in send: 1.9574165344238281ms    Count over 10us: 0
sleep: 100us    Total time in send: 5.476236343383789ms Count over 10us: 9
sleep: 1000us   Total time in send: 50.98319053649902ms Count over 10us: 1179

Go 运行结果 #

(venv) % go run write_to_devnull_mini.go
sleep: 0s   Total time in send: 5.724469ms  Count over 10us: 0
sleep: 1µs  Total time in send: 6.404582ms  Count over 10us: 1
sleep: 10µs     Total time in send: 4.346918ms  Count over 10us: 0
sleep: 100µs    Total time in send: 10.909356ms     Count over 10us: 8
sleep: 1ms  Total time in send: 112.627213ms    Count over 10us: 1307

原因解析 #

这本质是操作系统调度器与内核态资源调度共同作用的结果：

• 进程调度延迟：调用sleep时，进程会被移出CPU运行队列进入休眠。休眠时间越长，进程越可能被调度器放到低优先级队列，或CPU已切换到其他任务。休眠结束后，进程需要等待调度器重新分配CPU时间片，这个等待时间会被计入后续write的计时窗口——从startTime = now()到实际执行write内核操作之间，进程可能还在等待被调度上CPU。
• 内核态上下文与资源冷启动：即使写入/dev/null，write仍需从用户态切换到内核态。进程长时间休眠后，内核中与该进程相关的资源（如文件描述符缓存、线程上下文）可能被换出或需要重新初始化，增加内核处理耗时。
• 调度器唤醒机制差异：短休眠（0_{10us）时，进程可能只是进入轻量级休眠，调度器会快速唤醒并重新调度，几乎无额外延迟。但休眠时长达到100us}1ms时，操作系统会判定为较长休眠，会把CPU让给其他任务，进程需等待下一个调度周期才能获得CPU，这个等待时间远大于写入本身耗时，最终被统计到writeTime中。

简言之，你统计的writeTime实际包含了进程被调度唤醒的等待时间，而非单纯的写入操作耗时。休眠时间越长，调度等待的概率和时长越高，最终导致统计的写入耗时显著增加。

内容的提问来源于stack exchange，提问作者aslvrstn