openlang

Зависший тест лучше читать по дампу, а не по print

Раньше при зависшем тесте рука сама тянулась расставить fmt.Println и запустить заново. Сейчас делаю иначе. Ставлю короткий таймаут, и когда он истекает, пакет testing паникует и печатает стеки всех горутин.

package hang

import "testing"

func TestHandoff(t *testing.T) {
	results := make(chan int)
	go func() {
		results <- 42 // nobody reads this
	}()
	done := make(chan struct{})
	<-done
}

go test -timeout 3s выдаёт panic: test timed out after 3s, список запущенных тестов и потом горутины по одной. У каждой в квадратных скобках причина ожидания и строка, на которой она стоит. Здесь две нужные видно сразу. Одна в [chan receive] на строке с <-done, другая в [chan send] на results <- 42, и под ней строка created by, то есть кто её запустил. Ещё там пишется, сколько каждая горутина уже ждёт, так что старую утечку легко отличить от свежей.

Не знаю, почему print так долго меня устраивал. Наверное, потому что таймаут по умолчанию десять минут, и до дампа просто никто не дожидался.

Разговор продолжается 9

Следуя доводам
  1. Ссылка на ответ

    Это Go-версия привычки читать дамп потоков до того, как добавлять логирование, и хорошо, что это кто-то записал. Мне в таких дампах больше всего помогает строка created by. Горутины пакета testing там тоже есть, testing.(*T).Run в chan receive и прочие, и выглядят они так же намертво, как ваши. Начинать стоит с тех, которые создала ваша собственная тестовая функция и под которыми стоит имя вашего файла.

  2. Ссылка на ответ

    Причина ожидания говорит, где находится каждая горутина, и её стоит прочитать до того, как строить теорию о том, почему. Дамп вашего теста даёт два наблюдения. Тестовая горутина ждёт приёма, в который никто никогда не отправит, а другая ждёт отправки, которую никто никогда не примет. Любого из двух хватило бы, чтобы объяснить зависание, так что дамп показывает два независимых дефекта в тесте из двенадцати строк, а не один дефект и его симптом.

  3. Ссылка на ответ

    Здесь важен порядок. Сначала дамп, потому что он ничего не стоит и показывает все горутины в один момент. Потом, если зависание вне тестов, тот же вид с живого процесса через net/http/pprof по адресу /debug/pprof/goroutine?debug=2, где стеки печатаются в той же форме, что и у падающей программы. Только после этого имеет смысл открывать трассировщик выполнения. Начинать с трассировщика на зависании - значит читать временные шкалы горутин, которые просто припаркованы.

  4. Ссылка на ответ

    Одна фраза в исходном сообщении неточна. Время ожидания в скобках есть не всегда. Оно печатается целыми минутами, так что меньше минуты не видно вовсе, а время начала ожидания рантайм отмечает только во время прохода сборки мусора. Ваш тест с -timeout 75s дал мне голое [chan send]. С вызовом runtime.GC() каждые несколько секунд внутри теста и -timeout 70s та же горутина вышла как [chan send, 1 minutes]. Так что с таймаутом в три секунды вы его не увидите никогда, а в тихом тесте можете не увидеть совсем.

  5. Ссылка на ответ

    Для теста стоит добавить один шаг до чтения. Когда горутин тысячи, дамп сверху вниз никто не читает, поэтому сначала посчитайте их по причине ожидания.

    go test -timeout 5s 2>&1 | grep -oE '^goroutine [0-9]+ \[[^],]+' \
      | cut -d'[' -f2 | sort | uniq -c | sort -rn

    Если 900 стоят в chan send и одна в chan receive, смотреть надо на эту одну и на того, кто должен был читать за остальные 900.

  6. Ссылка на ответ

    Мне нравится, что дамп говорит глаголами. "chan send" - это то, что горутина пытается сделать, и это уже намекает, кого она ждёт, а "зависла" ничего такого не сообщает.

  7. Ссылка на ответ

    Дамп говорит, где всё встало. Следующее зависание он дешевле не делает. Отправке в этом тесте нужен выход, select по ctx.Done() или канал с буфером под число результатов, а тест должен падать сам и с сообщением, а не полагаться на панику по таймауту. Эта паника к тому же убивает весь тестовый бинарник, так что ни один тест после зависшего в этом пакете не запускается. Сначала почините отправку, потом укорачивайте таймаут.

  8. Ссылка на ответ

    Таймаут всё же стоит оставить как страховку. Тест, который падает сам, ловит только то зависание, которое кто-то предвидел. Для непредвиденного по-прежнему нужны паника и дамп, так что лучше укоротить -timeout для пакета и заодно починить отправку, а не выбирать одно из двух.

Другие стороны того же вопроса

  1. Мой init поменял fill-column ровно в одном буфере

    (setq fill-column 72) годами лежал у меня в init, и только сейчас выяснилось, что M-q в свежем буфере по-прежнему переносит н…

    Ответы 8emacs-lisp
  2. SilentlyContinue как On Error Resume Next с другим написанием

    После унаследованных рабочих книг дошло дело до унаследованных скриптов PowerShell, и там нашёлся старый знакомый в новом пал…

    Ответы 0powershell
  3. Обновляемость значит, что раскладка хранилища останется навсегда

    Слышат «прокси» и думают, что проблема неизменяемости исчезла. Она переехала. Прокси хранит состояние и пересылает вызовы чер…

    Ответы 3solidity