avva: (Default)
[personal profile] avva
(интересно будет скорее всего только программистам)

Пару недель назад я починил баг на работе в одной внутренней библиотеке. Этот баг проявлялся так: долгоживущие сервера, пользовавшиеся этой библиотекой определенным способом, загадочным и случайным образом падали примерно раз в неделю (не все одновременно, а каждый сервер отдельно падал примерно с такой частотой). Найти и починить баг оказалось очень тяжело, потому что к моменту падения следов никаких почти не оставалось. Сам по себе баг тривиален - многопоточный код недостаточно дисциплинированно охранял доступ к глобальному ресурсу, который я назову X. У X есть мьютекс, который надо получить перед тем, как его трогать. Два потока делали следующее:

thread 1: get-mutex-for-X change1-X release-mutex-for-X
thread 2: change2-X

Код, который меняет X, в двух потоках был разный, поэтому я обозначил его change1 и change2, но он трогал одну и ту же часть X, и второй поток банально не охранял свой доступ мьютексом. Изредка, очень изредка, эти два потока выполняли эти куски кода одновременно на разных ядрах. Отыскать это все быстро мешало несколько осложняющих обстоятельств:

- кроме этих двух мест, есть еще десятки мест, которые меняют X, правильно охраняя замену мьютексом, но ни один из них не может конфликтовать с "thread 2"
- сам конфликт между thread 1 и thread 2 не приводил к немедленному падению, а коррумпировал внутренние структуры X, что обычно приводило к падению с загадочной и невнятной ошибкой спустя несколько секунд. К тому времени обычно thread 1 и thread 2 давно уже ушли из этих частей кода и никак не проявлялись в stack trace. Обычно там проявлялись другие места, которые ждали mutex-for-X в момент падения, просто по случайности.
- тот факт, что thread 2 не пользовался мьютексом, не был очевиден из его кода - неважно почему, долго объяснять. Казалось бы, этот код полностью лежал, вместе с еще кучей всего, внутри мьютекса X, но на самом деле он освобождал мьютекс как раз перед change2, и потом брал его заново, и это было неочевидно при чтении кода. Т.е. thread 2 выглядел, если быть точнее, так - троеточие передает "много всякой всячины":
thread 2: get-mutex-for-X ... release-mutex-for-X change2-X get-mutex-for-X ... release-mutex-for-X

Во многих ситуациях такое временное освобождение мьютекса как раз правильное поведение - если бы change2-X не меняло X, а делало какие-то совершенное другие вещи, и притом не очень быстро, то как раз это правильно. Но в данном случае это ошибка.

После того, как я нашел, почему это происходит, я исправил второй кусок кода, убрав неверное освобождение мьютекса, и все стало выглядеть так:

thread 1: get-mutex-for-X change1-X release-mutex-for-X
thread 2: get-mutex-for-X ... change2-X ... release-mutex-for-X

Падений больше не было. Вскоре я уехал в отпуск.

Во время моего отпуска, который еще не закончился, выяснилось следующее. Кусок кода из "thread 2" меняет X и одновременно меняет другой глобальный ресурс Y, который защищен своим собственным мьютексом. Изменение Y происходит внутри "change2-X" с помощью вызова какой-то функции Y, и работа с мьютексом полностью спрятана внутри этой функции и незаметна при чтении кода thread 2. Тем не менее, эта работа происходит, и если ее учесть, thread 2 выглядит так:

thread 2: get-mutex-for-X ... get-mutex-for-Y ... release-mutex-for-Y change2-X ... release-mutex-for-X

Одно из десятков других мест, которые могут менять X и охраняют это мьютексом, происходит внутри кода, связанного с ресурсом Y, и находящегося глубоко внутри цепочки кода, охраняемой мьютексом для Y. Этот код, выходит, выглядит так:

thread 3: get-mutex-for-Y ... get-mutex-for-X change3-X release-mutex-for-X ... release-mutex-for-Y

Интересно, что изменения change2-X и change3-X никак не конфликтуют друг с другом - они меняют разные места X. Но из-за того, что thread 2 и thread 3 получают два мьютекса для X и Y в разном порядке, получается возможность взаимной блокировки (deadlock). Один поток получил мьютекс для X, и еще до того, как он попытался получить мьютекс для Y, второй поток получил его - и все, они зависают, пытаясь отобрать друг у друга те мьютексы, что у них есть. До того, как я исправил код thread 2, блокировки быть не могло, но теперь она возможна.

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

Коллега, который разобрался в этой мешанине и нашел мою ошибку, исправил код thread 2 следующим образом. Он вернул освобождение мьютекса-X перед основной работой этого кода, и вставил эксплицитное ожидание этого мьютекса снова - но только после того, как вся работа с Y закончена. Так что выполнение thread 2 имеет теперь такой вид:

thread 2: get-mutex-for-X ... release-mutex-for-X get-mutex-for-Y ... release-mutex-for-Y get-mutex-for-X change2-X release-mutex-for-X get-mutex-for-X ... release-mutex-for-X.

На данный момент ни о каких новых проблемах с этим кодом не известно.

Date: 2010-08-20 01:50 am (UTC)
From: [identity profile] creaturen2.livejournal.com
По нашей профессии тоже можно снимать фильм наподобие "Доктора Хауса".

Date: 2010-08-20 01:57 am (UTC)
From: [identity profile] itman.livejournal.com
Это будет совершенно не гламурно. И потом, никто не хочет быть программистом, все хотят быть врачами.

Date: 2010-08-20 03:17 am (UTC)
From: [identity profile] http://users.livejournal.com/_navi_/
There's a reason movies never portray hacking realistically. (http://www.smbc-comics.com/index.php?db=comics&id=1898#comic)

(no subject)

From: [identity profile] p-a-s-h-a.livejournal.com - Date: 2010-08-20 10:14 am (UTC) - Expand

Date: 2010-08-21 04:47 am (UTC)
From: (Anonymous)
Среди врачей ass like House - редкость, среди программистов - норма.

Date: 2010-08-20 01:56 am (UTC)
From: [identity profile] kot-begemot.livejournal.com
Когда-то давным-давно был такой дивный инструмент для статического анализа многопоточного кода - locklint. Отлавливал такие ситуации довольно хорошо.
Решение коллеги, кстати, не идеально. Я бы, наверное, попытался разделить изменение X и Y по времени, более того, сделал бы доступ к полям X и Y исключительно через аксессоры/мутаторы, в которых бы и брал нужные мютексы.
Помимо всего прочего, это могло бы увеличить эффективность за счёт более высокой ганулярности сериализаций.

Date: 2010-08-20 05:07 am (UTC)
From: [identity profile] iratus.livejournal.com
Почему был? Он и сейчас прекрасно есть. Но работает только под Солярисом.
Для Линуксов есть Helgrind

(no subject)

From: [identity profile] netp-npokon.livejournal.com - Date: 2010-08-20 07:24 am (UTC) - Expand

(no subject)

From: [identity profile] alexott.livejournal.com - Date: 2010-08-20 08:47 am (UTC) - Expand

(no subject)

From: [identity profile] kot-begemot.livejournal.com - Date: 2010-08-20 10:41 am (UTC) - Expand

(no subject)

From: [identity profile] iratus.livejournal.com - Date: 2010-08-20 04:32 pm (UTC) - Expand
From: [identity profile] larisaka.livejournal.com
Фраза "Падений больше не было. Вскоре я уехал в отпуск." как-то выпадает из стиля записи, вам не кажется? какая-то литературная. Программисты могут огорчиться.
From: [identity profile] pilpilon.livejournal.com
С чего бы? Для программистов это thriller story, такая фраза там очень уместна.
From: [identity profile] racoonbear.livejournal.com
Вы не понимаете - это особый кайф. Представьте, вы сделали всё, что от вас требовал долг, заведомо зная что что-то может случиться (потому что вменяемый опытный специалист понимает, что что-то в большой системе может случиться всегда). И вот сидит он на песочке, или на лежаке, и думает с кайфом - "а может там всё накрылось медным тазом? через недель узнаю.." - и с кайфом переворачивается на другой бок.

Date: 2010-08-20 02:11 am (UTC)
From: [identity profile] itman.livejournal.com
Во многих ситуациях такое временное освобождение мьютекса как раз правильное поведение - если бы change2-X не меняло X, а делало какие-то совершенное другие вещи, и притом не очень быстро, то как раз это правильно. Но в данном случае это ошибка.

Кстати, ИМХО, это очень часто ошибка. Потому что код до первого освобождения мьютекса, обычно проверяет какое-то важное предусловие для последующего изменения. И, если это предусловие не проверяется повторно после "финального взятия" мьютекса, случаются чудеса.

Date: 2010-08-20 03:01 am (UTC)
From: [identity profile] raindog-2.livejournal.com
По совпадению, я как раз только что прослушал tech talk насчет STM в Closure (http://www.infoq.com/presentations/Value-Identity-State-Rich-Hickey). Твою историю можно запускать как страшилку перед рекламой Clojure & friends. "Раньше я пользовался Мьютексом, и страдал изжогой, а теперь перешел на persistent data structures / managed references, и мои волосы опять стали пушистыми" :)

Date: 2010-08-20 04:13 am (UTC)
From: [identity profile] cema.livejournal.com
Ну да, только не перешел.

Date: 2010-08-20 07:06 am (UTC)
From: [identity profile] migmit.vox.com (from livejournal.com)
Да уж. STM рулит и бибикает.

Date: 2010-08-20 03:23 am (UTC)
From: [identity profile] once-for-all.livejournal.com
Multithreading 101 С одной стороны - rookie mistake; с другой - the bitch to debug, тем более в чужом коде..

Из любпытство - насколько необходим общий mutex для всего Х? Была ли возможность заменить на, скажем, атомик переменные, или скажем все изменения такого рода посылаются в background thread? Если бы вы начинали делать новый дизайн.

Date: 2010-08-20 05:08 am (UTC)
From: [identity profile] iratus.livejournal.com
Это далеко не rookie mistake.

(no subject)

From: [identity profile] once-for-all.livejournal.com - Date: 2010-08-20 06:38 am (UTC) - Expand

Date: 2010-08-20 08:10 am (UTC)
From: [identity profile] avva.livejournal.com
Еще немного подробностей, в которые я не хотел вдаваться в самой записи:

- X - это Python, который подключен к C++ через SWIG
- mutex-for-X - это глобальный замок Питона (так называемый GIL), который всегда держится, когда исполняется любой питонный код или вызываются процедуры Python API из C++

Поэтому как раз эту часть дизайна изменить невозможно.

- причина, по которой трудно понять, что thread 2 не держит мьютекс: доступ к GIL регулируется специальными макросами или функциями в Python API. Этих макросов/функций есть три разные версии, а вдобавок SWIG делает возможным непрозрачное и нелокальное их использование. SWIG может, например, на основе одной глобальной директивы добавить обертку этими макросами всех функций в модуле. Когда читаешь код самой функции, не видишь, что на самом деле у нее еще будут такие добавки.

(no subject)

From: [identity profile] kot-begemot.livejournal.com - Date: 2010-08-20 10:45 am (UTC) - Expand

(no subject)

From: [identity profile] netp-npokon.livejournal.com - Date: 2010-08-20 11:02 am (UTC) - Expand

Date: 2010-08-20 04:15 am (UTC)
From: [identity profile] cema.livejournal.com
А почему разные треды берут мьютексы в разном порядке? Непорядок.

Date: 2010-08-20 04:27 am (UTC)
From: [identity profile] rezkiy.livejournal.com
мне как-то Арун Кишан рассказывал, как он автоматизировал процесс поиска таких ошибок без собственно поиска дедлоков. Ясно дело, что если дедлокнуло, то дампы говорят сами за себя. Но иногда дедлокает редко, и есть риск шипнуть с багом.

(no subject)

From: [personal profile] lxe - Date: 2010-08-20 06:17 am (UTC) - Expand

(no subject)

From: [identity profile] rezkiy.livejournal.com - Date: 2010-08-20 06:46 am (UTC) - Expand

(no subject)

From: [identity profile] rezkiy.livejournal.com - Date: 2010-08-20 06:49 am (UTC) - Expand

(no subject)

From: [identity profile] cema.livejournal.com - Date: 2010-08-20 03:03 pm (UTC) - Expand

(no subject)

From: [identity profile] tejblum.livejournal.com - Date: 2010-08-20 06:51 am (UTC) - Expand

(no subject)

From: [identity profile] rezkiy.livejournal.com - Date: 2010-08-20 07:11 am (UTC) - Expand

(no subject)

From: [identity profile] avva.livejournal.com - Date: 2010-08-20 08:15 am (UTC) - Expand

(no subject)

From: [identity profile] cema.livejournal.com - Date: 2010-08-20 03:00 pm (UTC) - Expand

Date: 2010-08-20 05:31 am (UTC)
stas: (Don't panic!)
From: [personal profile] stas
Вот поэтому threads are evil.

Date: 2010-08-20 06:15 am (UTC)
lxe: (Default)
From: [personal profile] lxe
Не, зло - это блокировки. А рулят атомарные операции.

(no subject)

From: [identity profile] once-for-all.livejournal.com - Date: 2010-08-20 06:39 am (UTC) - Expand

(no subject)

From: [identity profile] rezkiy.livejournal.com - Date: 2010-08-20 06:54 am (UTC) - Expand

Date: 2010-08-20 06:59 am (UTC)
From: [identity profile] netp-npokon.livejournal.com
А вы не пробовали использовать ThreadSanitizer для поиска не защищенных мьютексом доступов? Если нет, то это, по-видимому, наша недоработка :)

Date: 2010-08-20 08:11 am (UTC)
From: [identity profile] avva.livejournal.com
А ThreadSanitizer мог бы помочь в этом случае, учитывая эти обстоятельства? Если да, то это по-видимому моя недоработка, что я не попробовал :)

(no subject)

From: [identity profile] netp-npokon.livejournal.com - Date: 2010-08-20 08:45 am (UTC) - Expand

(no subject)

From: [identity profile] netp-npokon.livejournal.com - Date: 2010-08-20 08:50 am (UTC) - Expand

(no subject)

From: [identity profile] avva.livejournal.com - Date: 2010-08-20 02:06 pm (UTC) - Expand
(deleted comment)

Date: 2010-08-20 05:38 pm (UTC)
From: [identity profile] avva.livejournal.com
- смотрел на stack traces всех потоков в момент падения
- читал исходники выглядевших интересно потоков
- недоумевал
- добавлял много debug prints куда надо и не надо, перезапускал, ждал падения (около 2-х часов т.к. я запускал много копий)
- смотрел на stack traces, читал исходники, недоумевал
- читал информацию в интернете и внутренних рассылках про то, что означает невнятная ошибка в момент падения
- добавлял еще debug prints, убирал некоторые вызовы X, подозревая их, перезапускал
- смотрел на stack traces, читал исходники, недоумевал
- повторить предыдущие два пункта несколько раз

Через какое-то время мне СИЛЬНО ПОВЕЗЛО и "thread 2" еще не успел уйти из своего кода к моменту падения через несколько секунд - так сложилось, что он все еще ждал мьютекса X. Я до этого этот код в stack traces не видел, заинтересовался, начал читать, понял, что ничего не понимаю. Пошел читать документацию SWIG, который плохо знаю, разобрался, сформировал подозрение, проверил, ну дальше уже легко.

Если бы не было этого "сильно повезло", следующим этапом было бы построить debug build питона, распечатывающий все, что возможно, о внутренних структурах, и искать тот момент, когда происходит коррупция, а не падение (я понимал уже, что это два разных момента). Правда, не уверен, что на это меня бы в тот день хватило.

(no subject)

From: [identity profile] status-constr.livejournal.com - Date: 2010-08-20 06:02 pm (UTC) - Expand

(no subject)

From: [identity profile] al-zatv.livejournal.com - Date: 2010-08-20 09:07 pm (UTC) - Expand

(no subject)

From: [identity profile] avva.livejournal.com - Date: 2010-08-20 09:14 pm (UTC) - Expand

Date: 2010-08-20 11:34 am (UTC)
From: [identity profile] jasno.livejournal.com
до чего же типичная и знакомая ситуация:) с этим малтитредингом всегда так - убрал race - добавил deadlock, и наоборот. и race, конечно, ужасно фигово ищется.

Date: 2010-08-20 03:02 pm (UTC)
From: [identity profile] dmarck.livejournal.com
Hmm, а зачем в последнем core flow вот эта часть:

change2-X release-mutex-for-X get-mutex-for-X

?

Я упускаю что-то очевидное?

Date: 2010-08-20 05:28 pm (UTC)
From: [identity profile] avva.livejournal.com
Это не друг за другом в исходнике, а в функциях разного уровня. Внешняя функция делает

release
do stuff
get

внутренняя где-то внутри do stuff делает

do some stuff
get
do more stuff
release

Если посмотреть на то, что происходит с мьютексом, то выходит теоретически ненужная последовательность release get, но это незначительная плата за правильные абстракции.
Edited Date: 2010-08-20 05:28 pm (UTC)

Date: 2010-08-20 07:42 pm (UTC)
From: [identity profile] dimrub.livejournal.com
У вас есть билд с tsan?

Date: 2010-08-20 07:47 pm (UTC)
From: [identity profile] avva.livejournal.com
Нет - см. выше, думаю, что это для нас нерелевантно, т.к. все происходило при координации C++ с питоном, а питон и его API и SWIG не инструментированы для тсана.

(no subject)

From: [identity profile] dimrub.livejournal.com - Date: 2010-08-20 10:56 pm (UTC) - Expand

(no subject)

From: [identity profile] netp-npokon.livejournal.com - Date: 2010-08-21 05:32 am (UTC) - Expand
From: [identity profile] inmbt0001.livejournal.com
Меня в такой ситуации больше всего расстраивает то, что некоторые бинарники невозможно собрать в debug режиме, как раз недавно пытался собрать нечто, чьи объектники занимали более 5 гигов. Приходится отлаживаться старым добрым printf.

Интересно, что за библиотека это была....

December 2025

S M T W T F S
  123 4 56
78 9 10 11 1213
1415 1617181920
21 22 23 24 2526 27
28293031   

Most Popular Tags

Style Credit

Expand Cut Tags

No cut tags
Page generated Dec. 29th, 2025 02:59 am
Powered by Dreamwidth Studios