为什么在写作之前睡觉会减慢随后的写作速度？

huangapple
go评论133阅读模式
英文:

Why does sleeping before a write slow down the subsequent write?

问题

我在写入文件（或套接字）时偶尔遇到性能下降的情况，并且在调试过程中，我使用了一个小的测试工具来重现这个问题。我发现一个奇怪的行为，即在写入之间的睡眠时间越长，写入本身所需的时间就越长。我在Go和Python中都复现了这个测试工具，并且在我的Mac和Linux机器上都看到了类似的结果。

关键的困惑在于，在这两种情况下的计时代码看起来是这样的：

  1. sleep(x)
  2. startTime = now()
  3. write(msg)
  4. endTime = now()
  5. writeTime = endTime - startTime

尽管睡眠时间根本没有包含在计时中，但writeTime随着sleep的增加而显著变长！

Python代码：

  1. import time
  3. f = open("/dev/null", "w")
  5. msg = "0" * 1024
  7. for sleepMicros in [0, 1, 10, 100, 1000]:
  8.     totalSendTime = 0
  9.     cntOver10us = 0
  10.     for _ in range(10000):
  11.         time.sleep(sleepMicros / 1000 / 1000)
  12.         startSendTime = time.time()
  13.         f.write(msg)
  14.         sentTime = time.time()
  16.         timeInSend = sentTime - startSendTime
  17.         totalSendTime += timeInSend
  18.         if timeInSend > 10 / 1000 / 1000:
  19.             cntOver10us += 1
  21.     print(f"sleep: {sleepMicros}us\tTotal time in send: {totalSendTime * 1000}ms\tCount over 10us: {cntOver10us}")

Go代码：

  1. package main
  3. import (
  4. 	"fmt"
  5. 	"os"
  6. 	"time"
  7. )
  9. func main() {
  10. 	f, _ := os.Create("/dev/null")
  12. 	msg := make([]byte, 1024)
  14. 	for _, sleepMicros := range []time.Duration{0, 1, 10, 100, 1000} {
  15.         totalSendTime := time.Duration(0)
  16.         cntOver10us := 0
  17. 		sleepDuration := sleepMicros * time.Microsecond
  18. 		for i := 0; i < 10000; i++ {
  19. 			time.Sleep(sleepDuration)
  20. 			startSendTime := time.Now()
  21. 			_, err := f.Write(msg)
  22. 			sentTime := time.Now()
  24. 			if err != nil {
  25. 				fmt.Println("SendMessage got error", err)
  26. 			}
  27. 			timeInSend := sentTime.Sub(startSendTime)
  28. 			totalSendTime += timeInSend
  29. 			if timeInSend > 10*time.Microsecond {
  30. 				cntOver10us++
  31. 			}
  32. 		}
  33. 		fmt.Println("sleep:", sleepDuration, "\tTotal time in send:", totalSendTime, "\tCount over 10us:", cntOver10us)
  34. 	}
  35. }

结果：

Python：

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

Go：

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

我最好的猜测是这是调度器的某种副作用，但我很想了解发生了什么。为什么在写入之间睡眠1毫秒会导致在调用time.Now()之间花费的总时间增加20倍，并且“慢”（>10微秒）写入的数量增加了200倍？

英文:

I'm seeing occasionally slow performance in writing to a file (or socket) and in debugging, I ended up with a small test harness to reproduce it. I'm seeing strange behavior whereby the longer I sleep in between writes, the longer the write itself takes. I reproduced the test harness in both Go and Python and see similar results in both. I also see similar results on both my mac and linux machines.

The key confusion is that the timing code in both cases looks like

  1. sleep(x)
  2. startTime = now()
  3. write(msg)
  4. endTime = now()
  5. writeTime = endTime - startTime

where writeTime gets significantly longer as the sleep increases, despite the sleep not being included in the timing at all!

Python:

  1. import time
  3. f = open(&quot;/dev/null&quot;, &quot;w&quot;)
  5. msg = &quot;0&quot; * 1024
  8. for sleepMicros in [0, 1, 10, 100, 1000]:
  9.     totalSendTime = 0
  10.     cntOver10us = 0
  11.     for _ in range(10000):
  12.         time.sleep(sleepMicros / 1000 / 1000)
  13.         startSendTime = time.time()
  14.         f.write(msg)
  15.         sentTime = time.time()
  17.         timeInSend = sentTime - startSendTime
  18.         totalSendTime += timeInSend
  19.         if timeInSend &gt; 10 / 1000 / 1000:
  20.             cntOver10us += 1
  22.     print(f&quot;sleep: {sleepMicros}us\tTotal time in send: {totalSendTime * 1000}ms\tCount over 10us: {cntOver10us}&quot;)

Go:

  1. package main
  3. import (
  4. 	&quot;fmt&quot;
  5. 	&quot;os&quot;
  6. 	&quot;time&quot;
  7. )
  9. func main() {
  10. 	f, _ := os.Create(&quot;/dev/null&quot;)
  12. 	msg := make([]byte, 1024)
  14. 	for _, sleepMicros := range []time.Duration{0, 1, 10, 100, 1000} {
  15.         totalSendTime := time.Duration(0)
  16.         cntOver10us := 0
  17. 		sleepDuration := sleepMicros * time.Microsecond
  18. 		for i := 0; i &lt; 10000; i++ {
  19. 			time.Sleep(sleepDuration)
  20. 			startSendTime := time.Now()
  21. 			_, err := f.Write(msg)
  22. 			sentTime := time.Now()
  24. 			if err != nil {
  25. 				fmt.Println(&quot;SendMessage got error&quot;, err)
  26. 			}
  27. 			timeInSend := sentTime.Sub(startSendTime)
  28. 			totalSendTime += timeInSend
  29. 			if timeInSend &gt; 10*time.Microsecond {
  30. 				cntOver10us++
  31. 			}
  32. 		}
  33. 		fmt.Println(&quot;sleep:&quot;, sleepDuration, &quot;\tTotal time in send:&quot;, totalSendTime, &quot;\tCount over 10us:&quot;, cntOver10us)
  34. 	}
  35. }

Results:

Python:

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

Go:

  1. (venv) % go run write_to_devnull_mini.go
  2. sleep: 0s 	Total time in send: 5.724469ms 	Count over 10us: 0
  3. sleep: 1&#181;s 	Total time in send: 6.404582ms 	Count over 10us: 1
  4. sleep: 10&#181;s 	Total time in send: 4.346918ms 	Count over 10us: 0
  5. sleep: 100&#181;s 	Total time in send: 10.909356ms 	Count over 10us: 8
  6. sleep: 1ms 	Total time in send: 112.627213ms 	Count over 10us: 1307

My best guess is that this is some artifact of the scheduler, but would love to understand what's happening. How does sleeping for 1ms in between writes cause the total time spent between calls to time.Now() to go up by 20x, and the number of "slow" (>10us) writes to increase 200-fold?

答案1

得分: 1

等一下 - 这看起来有点可疑：

  1. totalSendTime := time.Duration(0)
  2. cntOver10us := 0
  3. for _, sleepMicros := range []time.Duration{0, 1, 10, 100, 1000} {
  4.     sleepDuration := sleepMicros * time.Microsecond
  5.     for i := 0; i < 10000; i++ {
  6.         ...
  7.     }
  8.     fmt.Println("sleep:", sleepDuration, "\tTotal time in send:", totalSendTime, "\tCount over 10us:", cntOver10us)
  9. }

你真的不想在每次迭代中重置 totalSendTime 和 cntOver10us 吗？否则，无论你睡眠多长时间，totalSendTime 和 cntOver10us 都会继续增加。

你可以这样修改代码：

  1. for _, sleepMicros := range []time.Duration{0, 1, 10, 100, 1000} {
  2.     totalSendTime := time.Duration(0)
  3.     cntOver10us := 0
  4.     sleepDuration := sleepMicros * time.Microsecond
  5.     for i := 0; i < 10000; i++ {
  6.         ...
  7.     }
  8.     fmt.Println("sleep:", sleepDuration, "\tTotal time in send:", totalSendTime, "\tCount over 10us:", cntOver10us)
  9. }

否则，由于你从未重置它，每个外部循环的 totalSendTime 只会增加。

英文:

Wait - this looks suspicious:

  1. totalSendTime := time.Duration(0)
  2. cntOver10us := 0
  3. for _, sleepMicros := range []time.Duration{0, 1, 10, 100, 1000} {
  4.     sleepDuration := sleepMicros * time.Microsecond
  5.     for i := 0; i &lt; 10000; i++ {
  6.         ...
  7.     }
  8.     fmt.Println(&quot;sleep:&quot;, sleepDuration, &quot;\tTotal time in send:&quot;, totalSendTime, &quot;\tCount over 10us:&quot;, cntOver10us)
  9. }

Don't you really want to reset totalSendTime and cntOver10us on each iteration? Otherwise, totalSleep and cntOver10us is going to keep going up no matter how long you sleep.

  1. for _, sleepMicros := range []time.Duration{0, 1, 10, 100, 1000} {
  2.     totalSendTime := time.Duration(0)
  3.     cntOver10us := 0
  4.     sleepDuration := sleepMicros * time.Microsecond
  5.     for i := 0; i &lt; 10000; i++ {
  6.         ...
  7.     }
  8.     fmt.Println(&quot;sleep:&quot;, sleepDuration, &quot;\tTotal time in send:&quot;, totalSendTime, &quot;\tCount over 10us:&quot;, cntOver10us)
  9. }

Otherwise, your totalSendTime for each outer loop is only going to go up since you never seem to reset it

答案2

得分: 1

你忽略了一些细节，比如核心数量、调度器以及来自其他进程的加载。

可能是频繁的睡眠导致了你的动态优先级降低。
这与用户设置的nice值不同。
预测你的进程每秒只使用几个周期，
所以可以用一个具有更紧迫截止时间的高优先级进程来抢占cPython字节码解释器。

但也可能是频繁的长时间睡眠导致
其他进程污染了缓存，导致你遭受更多的缓存未命中。
或者，类似地，你缺乏亲和性并且不断被重新调度
在不同的核心上。
如果你想调查这个问题，可以对缓存进行仪器化，或查看ps报告的PSR。

一个简单的查看方法是

  1. import resource
  2. ...
  3. r = resource.getrusage(resource.RUSAGE_SELF)

并注意自愿和r.ru_nivcsw非自愿
上下文切换的增量模式。
还要验证r.ru_minflt是否保持不变。

嗯，想起来了，由于L3缓存未命中而导致的缓慢
应该会显示为getrusage()报告的非常数用户和系统模式增量。

英文:

You omitted details like core count, scheduler, and loading from other processes.

It could be that frequent sleeping is reducing your dynamic priority.
That's different from the user-set nice value.
Your process is predicted to use only a few cycles per second,
so it's OK to pre-empt the cPython bytecode interpreter
with a higher priority process that has a tighter deadline.

But it could also be that frequent long sleeps are allowing
other processes to dirty the cache so you suffer more cache misses.
Or, similarly, you lack affinity and keep getting rescheduled
on different cores.
Instrument the cache, or look at PSR reported by ps
if you want to investigate that.

A simple thing to look at would be

  1. import resource
  2. ...
  3. r = resource.getrusage(resource.RUSAGE_SELF)

and note patterns in how voluntary and r.ru_nivcsw involuntary
context switches increment.
Also, verify that r.ru_minflt remains constant.

Hmmm, come to think of it, slowness due to L3 cache miss
should show up as non-constant user and sys mode deltas
reported by getrusage().

huangapple
  • 本文由 发表于 2022年8月4日 08:20:07
  • 转载请务必保留本文链接：https://go.coder-hub.com/73229112.html
  • go
  • performance
  • python
  • scheduler
匿名

发表评论

匿名网友

:?: :razz: :sad: :evil: :!: :smile: :oops: :grin: :eek: :shock: :???: :cool: :lol: :mad: :twisted: :roll: :wink: :idea: :arrow: :neutral: :cry: :mrgreen:

确定