В конце прошлой недели убил почти два часа чтобы найти и исправить баг в многопоточном коде. В мною написанном и, как казалось, протестированном и отлаженном коде.
Код делал относительно несложную штуку: формировал очередь запросов, поступающих из разных рабочих нитей и ждущих разрешения на выполнение. Какие-то из этих запросов могли быть запущены в параллель, какие-то должны были ждать завершения ранее начатых запросов, какие-то должны были уходить в конец очереди при появлении более приоритетных запросов.
Но, как оказалось, не всегда это выполнялось правильно. Даже не смотря на наличие тестов 🙁
Особо доставили два момента:
Во-первых, обнаружение бага. Чистая случайность. Делал очередной прогон приложения со включенными отладочными печатями и буквально краем глаза заметил что-то необычное в консоли. Там было несколько дампов с перечнем работающих и ждущих запросов. И в части этих дампов указывалось, что с какого-то момента в работу пошло вообще все, а очередь опустела, хотя часть запросов должна была бы все еще оставаться в очереди.
Во-вторых, осознание того, что я не помню последовательности запросов, которая привела к такой ситуации. Я их накидывал случайно, в разном порядке, с разными параметрами. И когда заметил подозрительные следы в отладочных печатях, то не смог вспомнить в каком именно порядке какие запросы выдавались.
Так что внезапно обнаружил себя в ситуации, когда баг явно есть, но как он возник решительно непонятно. Как и непонятно есть ли вообще возможность его воспроизвести (и во что все это выльется).
Пришлось чуть ли не в буквальном смысле "курить бамбук": смотреть в код, смотреть в получившиеся отладочные печати, опять смотреть в код, опять смотреть в отладочные печати, опять смотреть в код... Все время пытаясь понять "а вот если оно пошло вот по этой ветке, то...", периодически отвлекаясь на попытки подумать о том, а можно ли сделать тестовый прогон, который бы подтвердил или опроверг очередную гипотезу.
В какой-то момент мозг начал закипать. В общем-то, два часа на поиск бага в многопоточном коде -- это не много, но когда эти два часа ты можешь разве что листать код вперед назад и рисовать схемки на бумаге, то это долго 😉
Оказалось вот что: у меня был ассоциативный контейнер (std::map), содержимое которого защищалось мутексом. Но в одной из веток происходило следующее:
- захваченный мутекс отпускался чтобы дать другим нитям возможность обратиться к этому контейнеру;
- текущая нить (которая ранее владела мутексом) засыпала в ожидании некого события;
- когда это самое событие происходило, текущая нить просыпалась и вносила изменения в этот контейнер.
По недосмотру в коде не оказалось повторного захвата мутекса после того, как текущая нить дождалась своего события и проснулась. Поэтому обновление контейнера было уже не thread-safe 🥴
Поэтому получилось, как я полагаю, следующее: на ожидании своих событий заснуло две нити. Потом они проснулись практически одновременно одна за одной (вот такое вот счастливое для меня стечение обстоятельств) и сперва первая добавила свою информацию в этот контейнер, а потом и вторая. Причем, подозреваю, обновление контейнера происходило чуть ли не одновременно. Т.к. стечение обстоятельств было действительно счастливым, то изначально контейнер был пустым и сперва одна нить туда добавила свою информацию, а затем и вторая. При этом, как я подозреваю, вторая нить просто полностью перезаписала содержимое контейнера. Из-за чего в нем оказался один-единственный элемент, а не два. А уже это привело к нарушению всей последующей логики обработки очереди запросов и в работу ушли даже те запросы, которые должны были еще подождать.
В общем, целый ряд счастливых случайностей:
- сперва я очень удачно сгенерировал "правильную" последовательность запросов которая привела к тому, что две рабочие нити проснулись в одно время;
- затем повезло с тем, что при перезаписи std::map-а из разных потоков не образовался какой-то мусор из-за чего бы программа могла бы упасть с segmentation fault;
- и все это случилось когда в программе еще оставались отладочные печати, благодаря которым на консоль сбрасывались дампы с информацией о текущих запросах;
- ну и каким-то чудом в этих самых дампах я заметил то, что у ряда запросов статус оказался "в работе", а не "в ожидании".
Короче говоря, без везения в поиске багов в многопоточке не обойтись 😎
А в завершении хочется повторить то, что я уже неоднократно говорил (и буду делать это снова и снова): многопоточность -- это пот, боль и кровь. Посему если у вас есть возможность не писать многопоточный код, то не пишите его.
Сам я себя ни в коем случае специалистом по многопоточному программированию не считаю, мне тупо не хватает мозгов, чтобы моделировать все то многообразие сочетаний событий, которое может возникнуть в многопоточном коде. Я поэтому-то SObjectizer-ом и занимаюсь, чтобы свести работу с многопоточностью к минимуму. Поэтому в моем многопоточном коде баги были, есть и будут. Куда же без них 😉 Главное, чтобы они вовремя наружу вылазили, под присмотром 🤣
На правах саморекламы: изобретаю велосипеды для себя, могу изобретать и для вас.
