Трассировка планировщика в Go: где горутины теряют время

Сервис на Go отдаёт 40k RPS, CPU держится на 60%, память стабильна, а p99 латентности регулярно прыгает с 15 до 200 мс без видимой причины. GC не при делах — паузы стабильно ниже миллисекунды. Профиль CPU показывает равномерную нагрузку без горячих точек. Проблема не в том, что горутины медленно считают, а в том, что они ждут: очереди в планировщике, захваченные P без работы, тысячи горутин на нескольких логических процессорах. Это видно только через трассировку планировщика — runtime/trace и GODEBUG=schedtrace. Разбираем на Go 1.22+, где формат трассировки уже стабилизировался и появился новый trace-viewer.

Речь только про диагностику латентности через планировщик. GC-паузы, аллокации и сетевые таймауты — отдельные темы, здесь их не трогаем.

Как планировщик Go создаёт задержки

Модель G-P-M: горутины (G) исполняются на логических процессорах (P), которые привязаны к потокам ОС (M). Число P задаётся GOMAXPROCS и по умолчанию равно числу ядер. Горутина не выполняется сама по себе — её должен подхватить свободный P. Если готовых к исполнению горутин больше, чем P, лишние стоят в очереди.

Задержка возникает в трёх местах:

• Локальная очередь run queue переполнена. У каждого P своя очередь на 256 горутин. Когда она заполняется, горутины уходят в глобальную очередь под глобальный мьютекс — это точка сериализации.
• Горутина проснулась, но P занят. Между «готова к исполнению» и «начала исполняться» проходит время. Под нагрузкой это десятки микросекунд, при перегрузке — миллисекунды.
• Syscall блокирует M. Когда горутина уходит в блокирующий системный вызов, M отвязывается от P, а планировщик ищет или создаёт новый M для этого P. Массовые syscall-ы (запись логов в файл, обращения к диску) плодят потоки ОС.

Компонент sysmon — фоновый поток без P — раз в некоторый интервал проверяет застрявшие горутины и вытесняет те, что заняли P дольше 10 мс. Это предотвращает голодание, но само вытеснение тоже стоит времени.

Профиль CPU отвечает на вопрос «где горутины жгут такты». Трассировка планировщика отвечает на другой: «где горутины ничего не делают, хотя работа есть». Для плавающей латентности нужен второй ответ.

Быстрый замер: GODEBUG=schedtrace

Прежде чем собирать полную трассировку, оцените ситуацию дёшево. Переменная окружения GODEBUG=schedtrace=1000 заставляет рантайм каждые 1000 мс печатать в stderr сводку по планировщику:

GODEBUG=schedtrace=1000,scheddetail=1 ./your-service

Строка вывода выглядит примерно так:

SCHED 1000ms: gomaxprocs=8 idleprocs=0 threads=23 spinningthreads=1 idlethreads=4 runqueue=142 [12 8 15 9 11 7 14 10]

Что читать в этой строке:

• idleprocs=0 — ни одного свободного P. Все процессоры заняты, а в очередях всё равно горутины. Признак нехватки CPU или слишком мелкой нарезки работы.
• runqueue=142 — 142 горутины в глобальной очереди ждут. Ненулевое стабильное значение под нагрузкой — прямой источник задержки.
• Числа в скобках — длина локальной очереди каждого P. Если у одних P очереди по 15, а у других по 7 — работа распределена неравномерно, work-stealing не успевает.
• threads=23 при gomaxprocs=8 — 23 потока ОС. Много потоков означает частые блокирующие syscall-ы.

Если runqueue и локальные очереди стабильно около нуля, а латентность всё равно плавает — планировщик ни при чём, копайте в GC, сеть или блокировки. Если очереди растут — переходите к полной трассировке.

Полная трассировка: runtime/trace

Пакет runtime/trace пишет детальный лог всех событий планировщика: старт и остановка горутин, syscall-ы, блокировки на каналах и мьютексах, события GC. Включить можно через HTTP-эндпоинт net/http/pprof или программно.

Снять трассировку с работающего сервиса

Если импортирован net/http/pprof, эндпоинт уже поднят. Снимаем 5 секунд под нагрузкой:

curl -o trace.out "http://localhost:6060/debug/pprof/trace?seconds=5"

Снимайте именно в момент всплеска латентности. Трассировка на пике нагрузки и трассировка на холостом ходу — это два разных файла, и второй бесполезен.

Открыть трассировку

go tool trace trace.out

Команда поднимает локальный веб-сервер и открывает браузер. Ключевые разделы для латентности:

• Scheduler latency profile — распределение времени между «горутина готова» и «горутина начала исполняться». Это прямой ответ на вопрос про очереди.
• Goroutine analysis — по каждому типу горутин разбивка времени: сколько исполнялась, сколько ждала планировщик, сколько висела в syscall, сколько блокировалась на каналах и мьютексах.
• View trace — временная шкала с дорожками по каждому P. Видно, когда P простаивали, а когда были забиты.

Замеры до и после: пример с пулом воркеров

Условия замера важнее самих цифр, поэтому фиксируем: 8 логических ядер, нагрузка 10k RPS через vegeta, каждый запрос порождает CPU-bound задачу на ~2 мс. Ниже — не универсальные числа, а иллюстрация подхода; на вашем железе они будут другими, поэтому меряйте сами.

Проблема. Обработчик на каждый запрос запускал по три коротких горутины через go func(). При 10k RPS это 30k новых горутин в секунду. В Scheduler latency profile хвост распределения уходил в десятки миллисекунд, runqueue в schedtrace стабильно держался за сотню.

Решение. Ограниченный пул воркеров вместо неограниченного порождения горутин. Число воркеров привязано к GOMAXPROCS, а не к числу запросов:

package worker

import (
	"context"
	"runtime"
	"sync"
)

// Task — единица работы, которую исполняет воркер.
type Task func()

// Pool — пул воркеров фиксированного размера.
type Pool struct {
	tasks chan Task
	wg    sync.WaitGroup
}

// NewPool создаёт пул с числом воркеров по числу логических процессоров.
func NewPool(ctx context.Context, queueSize int) *Pool {
	workers := runtime.GOMAXPROCS(0)
	p := &Pool{
		tasks: make(chan Task, queueSize),
	}
	for i := 0; i < workers; i++ {
		p.wg.Add(1)
		go p.worker(ctx)
	}
	return p
}

func (p *Pool) worker(ctx context.Context) {
	defer p.wg.Done()
	for {
		select {
		case <-ctx.Done():
			return
		case task, ok := <-p.tasks:
			if !ok {
				return
			}
			task() // исполняем задачу синхронно в рамках воркера
		}
	}
}

// Submit кладёт задачу в очередь; блокируется, если очередь заполнена.
func (p *Pool) Submit(task Task) {
	p.tasks <- task
}

Смысл не в самом пуле, а в том, что число одновременно готовых к исполнению горутин теперь ограничено и предсказуемо. Планировщику не приходится тасовать десятки тысяч сущностей — он работает с несколькими воркерами, которые разбирают буферизованный канал.

Цифры в таблице — форма результата, а не гарантия. Ваш выигрыш зависит от того, была ли реальной проблемой именно перегрузка планировщика, или всё упиралось, например, в один мьютекс.

Где этот подход ломается

• Задачи с блокирующими syscall-ами. Если воркеры ходят в сеть или на диск, привязка их числа к GOMAXPROCS ошибочна: пока горутина в syscall, её P свободен и мог бы взять другую работу. Для I/O-bound нагрузки пул должен быть больше числа ядер, и его размер подбирается замером, а не формулой.
• Overhead трассировки. runtime/trace под нагрузкой добавляет заметный оверхед и раздувает файл. Пятисекундная трассировка занятого сервиса — это сотни мегабайт. Не оставляйте эндпоинт открытым для длительного сбора и не снимайте трассировку постоянно.
• GOMAXPROCS в контейнере. В Kubernetes с лимитом CPU рантайм по умолчанию видит все ядра узла, а не выделенную квоту. Планировщик создаёт лишние P, cgroup-троттлинг режет реальное время исполнения — и вы ловите задержки, которых нет на голом железе. Решается пакетом go.uber.org/automaxprocs либо явной установкой GOMAXPROCS под лимит.
• Буферизованный канал маскирует, а не решает. Большой queueSize в пуле не убирает перегрузку — он превращает всплеск нагрузки в рост латентности вместо отказа. Иногда честнее отклонять запрос при полной очереди, чем копить его.

Что делать дальше

Начните с дешёвого: включите GODEBUG=schedtrace=1000 на стенде под нагрузкой и посмотрите на runqueue и idleprocs. Если очереди пустые — планировщик не ваша проблема, идите профилировать GC и блокировки. Если растут — снимите runtime/trace ровно в момент всплеска и откройте Scheduler latency profile. Проверьте GOMAXPROCS в проде: в контейнере это почти всегда первый источник неожиданных задержек. И держите под наблюдением число потоков ОС — их резкий рост под нагрузкой всегда указывает на массовые блокирующие вызовы.