Какой-то странный баг в Go с часами в рутинах

92d74958ce0054e3229230d0e2519b67

Прилетела ко мне задача померять минимальное, максимальное и среднее время исполнения запросов. Делал, делал и не мог понять, почему на 48 ядерной машине, запросы исполняются за 100 мс при нагрузке в 50к/сек.

В итоге я выяснил причину и не могу понять. Толи лыжи не едут, толи реально баг в Go cо снятием времени.

Короче к телу

func TestSingle(t *testing.T) {
	count := 100000

	at := time.Now()
  
	for n := 0; n < count; n++ {
		for i := 0; i < 1000; i++ {
		}
	}

	durAll := time.Since(at)
	durOne := durAll / time.Duration(count)

	log.Println("Single: all ", durAll, " one ", durOne.String())
}

func TestParallel(t *testing.T) {
	count := 100000

	wg := sync.WaitGroup{}
	wg.Add(count)

	dura := atomic.Int64{}

	for n := 0; n < count; n++ {
		go func() {
			defer wg.Done()
          
			at := time.Now()
          
			for i := 0; i < 1000; i++ {
			}

			dura.Add(int64(time.Since(at)))
		}()
	}

	wg.Wait()

	durAll := time.Duration(dura.Load())
	durOne := durAll / time.Duration(count)

	log.Println("Parallel: all ", durAll, " one ", durOne.String())
}

Итог:

=== RUN   TestSingle
2024/10/30 23:27:14 Single: all  13.9972ms  one  139ns
--- PASS: TestSingle (0.01s)
=== RUN   TestParallel
2024/10/30 23:27:14 Parallel: all  65.9173ms  one  659ns
--- PASS: TestParallel (0.02s)
PASS


Это версия 2. Первая была не корректна и уважаемый @runetfreedom в личку сообщил инфу о погрешности часов. Я это учел (хоть и забыл) и решил переделать тесты. Да и тесты в первой были не корректные.
К нашим баранам. В переписке было сказано, что часы имеют погрешность и не всегда из-за БЫСТРОГО исполнения можно точно узнать время ТОЧНО. Ок. Подумал я и решил увеличить счетчик i с 1000 до 1000 0000 что бы эту погрешность уменьшить.

Итог

=== RUN   TestSingle
2024/10/30 23:14:49 Single: all  12.4822524s  one  124.822µs
--- PASS: TestSingle (12.48s)
=== RUN   TestParallel
2024/10/30 23:14:52 Parallel: all  1m5.7762707s  one  657.762µs
--- PASS: TestParallel (2.77s)
PASS

Кто знает тонкости Go, расскажите в чем подвох со снятием времени в рутинах? Сталкивались ли вы с таким багом?

go version go1.23.1 windows/amd64
goos: windows
goarch: amd64
pkg: ad-dmp/app/rest/route/audience
cpu: 12th Gen Intel® Core i7–1255U

© Habrahabr.ru