?

Log in

об одном баге - Поклонник деепричастий [entries|archive|friends|userinfo]
Anatoly Vorobey

[ website | Website ]
[ userinfo | livejournal userinfo ]
[ archive | journal archive ]

Links
[Links:| English-language weblog ]

об одном баге [июн. 28, 2003|02:49 am]
Anatoly Vorobey


(заранее предупрежаю: очень долго и нудно. Просто я решил, уже начав, дописать до конца описание этого бага)

Вот над этим багом я и Брэд корпели последние 3-4 суток, только с перерывами на сон иногда. Как он меня [beep], это ж просто слов никаких нету. Я его назначаю на роль самого зло[beep]чего бага ЖЖ (до него чемпионом был вот этот).

Баг проявлялся только на "живых" данных, то есть у memcache, бегущего на серверах ЖЖ и принимающего реальные данные от livejournal.com . Вне "живой" инсталляции мы его так и не смогли воспроизвести (даже пытались записать весь TCP-траффик и проиграть его заново — ничего не вышло); в результате поиск бага состоял в основном в выискивании мест, где можно было бы добавить assert'ы, потом Брэд запускал версию с этими ассертами на живых данных под gdb, и когда она падала, получить backtrace от gdb и сразу выйти — остаться в дебаггере было невозможно, т.к. это подвесило бы весь сайт. Впрочем, дебаггер нам не слишком бы и помог, т.к. совершенно не было понятно, что от него требовать. Баг внешне проявлял себя тем, что сайт начинал работать медленно из-за того, что нарушалась целостность связанных списков внутри процесса memcache. В этих связанных списках хранятся, собственно, данные кэша, и это не совсем списки, это LRU (Least Recently Used) queues — список, в который новые данные входят с головы, старые освобождаются из хвоста, когда нужно освободить память для новых, но кроме того, каждый раз, когда какой-то кусок данных запрашивается клиентом, он двигается в голову своего списка. Всего есть полтора десятка таких LRU queues, по одной для каждого класса данных, где класс определяется размером (до 64 байт, до 128 байт, до 256 байт размером итп.). Так вот, в какой-то момент один из списков замыкался сам на себя и оказывался состоящим из одного элемента. Все остальные десятки тысяч элементов этого списка оказывались подвешенными в воздухе и просто висели там, пожирая память и не освобождаясь; а новые данные входили и уходили через "укороченный" список размером всего с один слот — неудивительно, что кэш переставал быть эффективным и сайт замедлялся.

Мы десять и двадцать раз прошли по всему коду в поисках места, где может происходить такой corruption списка, и ничего не нашли. В конце концов с помощью нескольких серий таких вот ассертов, как описано выше, мы проследили путь этого бага сквозь две подсистемы кода, т.е. изначально портилась совсем другая вещь, а то, что это проявлялось в списке, это было очень отдалённым сайд-эффектом порчи. Порча, как в конце концов после всех этих ужасных усилий мы обнаружили, заключалась в том, что иногда, очень редко, какой-то item данных освобождался два раза по ошибке. "Освобождался" у нас не значит, что на него вызывали free(), а значит, что он уходил в пул свободных кусков памяти под новые айтемы. Проблема в том, что из-за двойного освобождения в списке свободных кусков оказывался два раза подряд один и тот же указатель на один и тот же кусок памяти; и в результате подсистема memory management выдавала его два раза подряд под два разных новых айтема кэша. Эти два новых "разных" айтема (а на самом деле располагавшихся в результате в одной и той же памяти) заходили по очереди в голову списка LRU для их класса данных, как и полагается новым данным; в результате получалось, что указатель next второго из них указывал на первый, вошедший перед ним — т.е. сам на себя. Это и приводило к "закорачиванию" списка.

Двойное освобождение одного и того же айтема кэша происходило в результате ошибки в коде вывода данных по запросу клиента. Когда клиент просит у memcache какие-то данные кэша, в одном запросе он может указать сколько угодно ключей одновременно (и обычно указывает много — скажем, тексты всех записей для одной страницы ленты френдов). Но мы пишем ответ на такой запрос (как и любой ответ) в socket асинхронно, то и дело переключаясь на другие одновременные подсоединения (работая с сотнями подключений одновременно). Поэтому невозможно просто запомнить где-то, какие айтемы надо выдать наружу в ответ на запрос, и выдавать их асинхронно, потому что другие подключения могут эти же айтемы изменить или стереть. Самым простым было бы при запросе выделить достаточно памяти, динамически, и скопировать туда сразу все нужные данные, и писать в сокет из этого временного буфера, а потом его освободить. Но на деле это оказывается слишком большой тратой памяти: такой буфер часто может занимать мегабайт или больше, а при 600 одновременных подключениях... в общем, ясно. Я сделал это изначально по-другому: в структуре подключения сохраняется список указателей на все айтемы, которые нужно сейчас выдать в сокет, один за другим, и у всех этих айтемов увеличивается поле reference count, что означает, что другие функции не смогут их освободить (айтем не освобождается, пока его reference count не падает до нуля). После того, как айтем асинхронно записывается в сокет, его reference count уменьшают и переходят к следующему.

Да, но есть ещё случай, когда подключение заканчивается досрочно до того, как запись закончена (например, клиент прервал связь). Поэтому фунцкия закрытия подключения (close connection) смотрит, есть ли в структуре подключения незаписанные ещё пока указатели на айтемы, и если есть, вызывает item_remove() (функцию, понижающую reference count и освобождающую айтем, если он упал до нуля) для каждого из них.

Предположим, в кэше есть какой-то айтем, и его сейчас начали "печатать" наружу в сокет, и из-за этого повысили его reference count. Предположим теперь, что для него из-за бага случайно дважды вызывают item_remove() вместо одного раза. Это не значит ещё, что он по ошибке попадает дважды в список свободной памяти, потому что он пролинкован в списке LRU и в его поле атрибутов это обозначено — а этот факт сам по себе обеспечивает, что он остаётся в памяти. Есть как бы два вида "reference count", один из которых является просто присутствием в списке LRU, а другой используется кусками кода, которым нужно оставить айтем в памяти на короткое время даже если он выпадает из списка LRU (например, для того, чтобы закончить начатую операцию печатания в сокет) - и для этого второго вида используется поле reference count и функция item_remove(). Если айтем сидит в списке LRU, т.е. является активным, то ошибочное двойное его освобождение с точки зрения reference count ничему не повредит.

Но кроме кода печатания ответа клиенту, есть ещё одно место, использующее reference count — это код удаления айтема. Дело в том, что по команде delete айтем не сразу уходит из кэша, а остаётся в нём на 4 секунды: мы заинтересованы в том, чтобы после удаления несколько секунд не срабатывало внесение заново данных под тем же только что удалённым ключом (это решает некоторые race conditions со стороны клиента). Когда клиент подаёт серверу команду DELETE на какой-то ключ, данный айтем помечается соответсвующим образом (так что несмотря на тот факт, что он остался во всех списках, если клиент попробует его получить, сервер сделает вид, что его нет), и вносится в список данных на удаление, по которому проходят каждые несколько секунд и удаляют те айтемы, для которых нужные 4 секунды уже прошли. При внесении в отдельный список на удаление поле reference count айтема увеличивается, а когда он действительно удаляется из этого списка, по прошествии 4 секунд, его не только удаляют из списка LRU, но и вызывают item_remove(), чтобы снизить обратно эффект увеличенного reference count и окончательно убрать его из памяти.

Но предположим теперь, что, во-первых, есть баг в коде, к-й занимается выдачей данных наружу клиенту, и этот баг заставляет код иногда вызывать item_remove() дважды для какого-то айтема вместо одного раза: один раз, когда распечатка окончена, и другой; и предположим, что как раз в это время, в это очень короткое время, что этот айтем сидит в очереди на распечатку, другой клиент посылает, на него же, команду DELETE. Тогда этот айтем заносится в очередь на удаление и у него опять увеличивается refcount (равный теперь двум). Пока он сидит 4 секунды в этой очереди, заканчивается его распечатка и код по ошибке вызывает item_remove() два раза, понижая его refcount до 0 (вместо нужной единицы). Теперь, когда пройдут 4 секунды и его будут удалять, собственно освобождение из памяти произойдёт дважды: функцией item_unlink(), вынимающей его из LRU (она видит, что его refcount==0, значит, никто его не "ждёт" и можно освобождать) и фунцкией item_remove(), вызванной для понижения refcount, вызванного внесением в список на удаление. Теперь этот айтем попадает дважды в список свободных блоков, и оттуда уже всё пляшет.

Баг, из-за которого айтем освобождается два раза, тоже случается очень редко. Один раз item_remove() освобождается после того, как данный айтем закончили печатать. Но, как было объяснено выше, в случае непредвиденного закрытия сокета функция close_conn() должна освободить все айтемы, которые ещё не распечатаны, поэтому их список хранится в структуре подключения, вместе с полем ileft, обозначающим, сколько их ещё таких осталось. Проблема в том, что код распечатывания использует ileft в цикле, печатая сами айтемы, до тех пор, пока все они не распечатаны, но в конце этого цикла — и здесь заключён сам баг — по ошибке оставляет его граничным значением 1, а не 0. Для самого распечатывания это уже значения не имеет, оно закончено. Но если в этот самый момент, до того, как началось распечатывание других айтемов по другому запросу того же клиента, если в этот момент подключение закроется (по инициативе клиента или из-за сетевой проблемы какой-нибудь) — тогда функция close_conn() по ошибке подумает, что нужно освободить один айтем, и вызовет item_remove() для последнего из сохранённых указателей на айтемы, несмотря на то, что на самом деле он уже был распечатан в сокет и item_remove() для него уже вызывали. Вот этот баг и его исправление:


                     it = *(c->icurr);
                     item_remove(it);
-                    if (c->ileft <= 1) {
+                    c->ileft--;
+                    if (c->ileft <= 0) {
                         c->ipart = 3;
                         break;
                     } else {
-                        c->ileft--;
                         c->icurr++;
                     }



Это формат diff, т.е. строки, начинающиеся с минуса, удаляются, а вместо них ставятся строки, начинающиеся с плюса. Условие if(c->ileft <= 1) было правильным, т.к. оно выполняется только когда мы только что закончили печатать последний айтем (ileft было ==1), и теперь надо заканчивать эту команду, что и делает строка c->ipart=3 (она выставляет новое значение состояния для мини-машины состояний, управляющей этой командой); а если условие не проходит, нужно уменьшить ileft и подвинуть указатель icurr до следующего элемента, до указателя на следующий айтем из списка. Но ошибка в том, что если условие проходит, ileft остаётся единицей; исправляется она тем, что ileft уменьшается заранее, ещё до проверки, а потом сравнивается с нулём, а не единицей.

Таким образом, этот баг проявляется только в случае, если одновременно один клиент запросил данные по какому-то количеству ключей, и практически одновременно другой клиент сделал команду DELETE на последний ключ из списка ключей первого клиента, и, кроме того, первый клиент сразу после получения ответа на свой запрос прервал своё подключение. Неудивительно, что он проявлялся только на "живых" данных (т.е. при огромном потоке "живых" запросов)!

Уф.

Как. я. рад. что. мы. его. нашли.
СсылкаОтветить

Comments:
[User Picture]From: dich
2003-06-27 05:03 pm

В memories. Имхо пост года :)
(Ответить) (Thread)
[User Picture]From: avva
2003-06-27 05:05 pm

Re:

Смеётесь, да? ;)
(Ответить) (Parent) (Thread)
[User Picture]From: dich
2003-06-27 05:09 pm

Восхищаемся.
(Ответить) (Parent) (Thread)
[User Picture]From: passing
2003-06-27 05:41 pm
А почему один и тот же refcount на сохранение в памяти и на удаление? Я, правда, не очень внимательно читал - мог и пропустить чего..каюсь...
(Ответить) (Thread)
[User Picture]From: avva
2003-06-27 05:44 pm

Re:

"удаление" тут значит на самом деле "обязан сохранить в памяти 4 секунды, а только потом удалить". В течение обычной работы легко может случиться так, что в эти 4 секунды данный айтем сам по себе уйдёт (напр. будет удалён, чтобы освободить память под новые данные), а в случае удаления нам как раз нужны его 4 секунды гарантированно продержать, поэтому увеличивается refcount. Именно для сохранения в памяти.
(Ответить) (Parent) (Thread)
From: ex_makaroff405
2003-06-27 06:09 pm
freezer, неужели это ты?... ;)
(Ответить) (Parent) (Thread)
[User Picture]From: avva
2003-06-27 06:09 pm

Re:

Он, он ;)
(Ответить) (Parent) (Thread)
[User Picture]From: passing
2003-06-27 07:25 pm

Re:

хмм..а вы кто?
(Ответить) (Parent) (Thread)
[User Picture]From: vzaliva
2003-06-27 06:52 pm

next bug

Дело в том, что по команде delete айтем не сразу уходит из кэша, а остаётся в нём на 4 секунды: мы заинтересованы в том, чтобы после удаления несколько секунд не срабатывало внесение заново данных под тем же только что удалённым ключом (это решает некоторые race conditions со стороны клиента).

Вот это звучит очень подозрительно. Может оказаться что ваш следующий "самый злой" баг будет связан с этим.

(Ответить) (Thread)
[User Picture]From: avva
2003-06-27 06:58 pm

Re: next bug

Я немного упростил описание. На самом деле мы хорошо понимаем, как это работает и зачем это нужно, так что сомневаюсь, что следующий баг будет из-за этого.
(Ответить) (Parent) (Thread)
From: (Anonymous)
2003-06-28 01:49 pm

Re: next bug (грабли с утяжеленной рукояткой)

будет, будет. такие вещи на времянке делать *НЕЛЬЗЯ* - просто потому, что времянка всегда где-нибудь да пролетит. например, на перегруженной системе, или если высокоприоритетные задачи сьедят ресурсы, или само ядро (скажем, под резкое повышение сетевого траффика) и т.д. Видели. А если у Вас не пролетит, так у тех, кто решит Ваш memcache попробовать. введите поколения, что ли (я на код не смотрел, совет из общих соображений)

и заодно еще пара соображений.

отчего Вы сделали на TCP? если Вы на той же машине, что и клиент, то Вам дополнительная нагрузка из-за сетевых протокольных стеков только мешает, - лучше бы сделать порт в адресном пространстве Юникса. Если это невозможно, или Вы разносите клиента и кэш по разным машинам - хотя бы UDP.

обычно такие вещи (и вещи много хуже) отлаживают по дампу (core file для пользовательского процесса). отладка на живой задаче в 90% случаях - лишняя трата времени. и очень часто недоступна, либо так меняет характеристики системы (времянку), что не имеет смысла.

кроме того, циклический буфер в памяти для лога всяческих событий и внутренних действий программы - это гигиена.

и ошибки такие должны бы ловиться задолго до перехода в продукцию: при управлении ресурсами (аллокации/освобождении) стоит *всегда* иметь внутренние проверки (integrity checks) и по возможности посильную помощь для отладки. скажем, в аллокаторе памяти в ядре Plan 9 (которым Вы планировали поинтересоваться) при каждой аллокации записывали адрес точки (инструкции), откуда пришел запрос, и сохраняли его в спрятанном заголовке аллокированного кусочка памяти.
т.е. двойне освобождение должно ловиться сразу при попытке второго освобождения.

и последнее: посмотрите здесь (http://www.cs.rice.edu/~druschel/publications/index.html) (кстати, не пропустите там Flash)
(Ответить) (Parent) (Thread)
[User Picture]From: avva
2003-06-28 02:58 pm

Re: next bug (грабли с утяжеленной рукояткой)

отчего Вы сделали на TCP? если Вы на той же машине, что и клиент,

Нет, не на той же машине. Клиент не один, их штук 600, по сорок процессов на одну машину (примерно).

обычно такие вещи (и вещи много хуже) отлаживают по дампу (core file для пользовательского процесса)

Спасибо, я знаю ;)
В данном случае это не помогало, увы.

кроме того, циклический буфер в памяти для лога всяческих событий и внутренних действий программы - это гигиена.

Тоже не помогает: баг проявлялся при такой нагрузке на сервер, при которой такой лог-буфер был бы такого размера и сложности, что его безполезно было бы анализировать.

т.е. двойне освобождение должно ловиться сразу при попытке второго освобождения.

Да, вот это верно. Это наш недосмотр. Мы старались экономить память любой ценой и поэтому не делали никаких контрольных блоков для кусков памяти.
(Ответить) (Parent) (Thread)
[User Picture]From: bugabuga
2003-06-28 12:04 am
То бишь когда я делаю edit entry запись исчезает на 4 секунды полностью, а потом появляется в обновлённом варианте? :)
(Ответить) (Thread)
[User Picture]From: avva
2003-06-28 03:55 am
Нет, delete не для таких случаев. При редактировании записи её текст просто мгновенно обновляется в кэше.
(Ответить) (Parent) (Thread)
[User Picture]From: stas
2003-06-28 12:23 am
А нельзя было у блока хранить битик, занят он или свободен? Или это сложно слишком?
(Ответить) (Thread)
[User Picture]From: avva
2003-06-29 03:31 pm
Изначально этот битик и был, но тогда не было refcount'ов и поэтому он "быть занятым" означало то же самое, что "сидеть в LRU"... потом программа прошла через несколько очень срочных изменений и смысл этого битика изменился на именно "сидеть в LRU". Это не было недосмотром, всё так и задумывалось, но добавить больше полезных битиков просто руки не дошли. Это ведь всё делалось и делается в очень ограниченное время, и в соответствии со срочными заказами, обусловленными качеством работы livejournal.com ;)
(Ответить) (Parent) (Thread)
[User Picture]From: evilalex
2003-06-28 01:35 am
Молодцы!
Блин! Нифига се баги... Не то что мои... :)))
(Ответить) (Thread)
[User Picture]From: alexcohn
2003-07-01 09:07 am

разбор полетов

Урок, ПМСМ, состоит в том, что опасно разделять операцию item_remove(it) и операцию c->ileft--. То есть я бы сделал функцию item_remove_for_conn():
void item_remove_for_conn(conn *c) {
    item_remove(*(c->icurr));
    c->ileft--;
    c->icurr++;
}
например, в функции conn_close() есть следующий текст:
    if (c->ileft) {
        for (; c->ileft > 0; c->ileft--,c->icurr++) {
            item_remove(*(c->icurr));
        }
    }
мне кажется, что чище было бы:
    while (c->ileft) {
        item_remove_for_conn(c);
    }
Кстати, Толя, нет может ли быть проблемы с тем, что в сегодняшнем варианте цикла с->ileft тоже останавливается на единице?
(Ответить) (Parent) (Thread)
[User Picture]From: avva
2003-07-01 09:58 pm

Re: разбор полетов

Почему останавливается на единице? На нуле.
Последняя декрементация происходит в самом конце цикла.

Спасибо за замечания насчёт функции, наверное, ты прав.
(Ответить) (Parent) (Thread)
[User Picture]From: alexcohn
2003-07-01 11:37 pm

Re: разбор полетов

sorry, я сам себя запутал с этим циклом.
(Ответить) (Parent) (Thread)
[User Picture]From: quirrc
2003-06-28 04:38 am
а почему не получилось с записью траффика? т.к. там привязка к физическому времени?
(Ответить) (Thread)
[User Picture]From: avva
2003-06-28 04:40 am

Re:

Во-первых, да, но даже после того, как мы исправили привязку ко времени в протоколе, не получилось... видимо, надо было более тщательно проигрывать, а действительно тщательно это сделать очень нелегко.
(Ответить) (Parent) (Thread)
[User Picture]From: msh
2003-06-28 03:42 pm
Вообще, бороться задержками с race conditions - это обычно плохая идея. Лично я считаю, что заданные отрезки времени в программе могут появляться только в двух случаях a) timed protocol (ну типа, железка ждет единицу в течении 1 микросекунды) и b) timeouts и sanity check (за 10 секунд не ответили - считаем что кранты)

А для борьбы с двойным освобождением я использовал ownership (ну надо было чужой код оживить) - это когда код держит ownership над объектом и обязан объект или прибить или ownership передать, при этом уничтожать объект может только тот, у кого ownership.

(Ответить) (Thread)
[User Picture]From: avva
2003-06-28 03:49 pm

Re:

ownership - это хорошая идея, да.

Насчёт заданных отрезков времени: "4 секунды" это временная константа. В принципе клиент сам будет говорить: "удалите такой-то ключ, и не пускайте новые данные с этим ключом в течение N секунд".

DELETE key timeout

Это тривиально сделать (нигде ничего под константу не подгоняется, естественно), просто руки не дошли.
(Ответить) (Parent) (Thread)
[User Picture]From: 109
2003-06-29 02:27 am
ownership - это из области design patterns. а тут - суровые сибирские мужики херачат на голых плюсах прямо из командной строки.

я понимаю, что сейчас на меня опять накинутся с иррелевантными криками типа "у тебя free account, жри что дают", но из того, каким образом авва излагал проблему, мне лично понятно, что design patterns тут и не пахнет.
(Ответить) (Parent) (Thread)
[User Picture]From: avva
2003-06-29 03:13 am

Re:

Я не буду флеймить сегодня, у меня сил нет ;) да мне и не свойственны никогда аргументы типа "у тебя free account, жри что дают".

Не было никаких design patterns в данном случае, да. Был просто design. Повторю ещё раз на всякий случай, что код свободно доступен и вполне прозрачен.
(Ответить) (Parent) (Thread)
[User Picture]From: 109
2003-06-29 05:52 am
мне и не свойственны никогда аргументы типа "у тебя free account, жри что дают"

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

Не было никаких design patterns в данном случае, да.

но так же не бывает, чтобы в данном случае не было, а в другом было. design practices are usually company-wide.

код свободно доступен и вполне прозрачен

да речь-то не об этом...
(Ответить) (Parent) (Thread)
[User Picture]From: msh
2003-06-29 03:55 am
Я на тебя наброшусь с вполне релевантными криками

Welcome to the real world, kid!

Существует два вида программирования - индустриальное и "дворец пионеров". Понятно, что в индустриальном программировании этот код бы не существовал - он не прошел бы design review и никто бы не стал имплементировать код, пока для него нет средств тестирования.

Проблема в том, что это все замечательно, но многие проекты не могут себе позволить - слишком долго и дорого, а цена ошибки мала. Поэтому "дворец пионеров" имеет право на существования, причем лично я по объему напрограммированного гораздо больше участвовал именно в таких проектах. то как пионер, то как пионервожатый, то как уборщица за пионерами.
(Ответить) (Parent) (Thread)
[User Picture]From: 109
2003-06-29 04:15 am
а почему дворец пионеров не может использовть design patterns? (хер с ним с тестированием и хер с ним с design review).

и это... я знаю же, как оно в real world. у нас самих такое творится... сказал бы что, но non-disclosure agreement. несмотря на наличие design review.
(Ответить) (Parent) (Thread)
[User Picture]From: msh
2003-06-29 04:34 am
Да ну потому что в реальном мире программисты не гении, brain the size of a planet, и вполне могут что-то проглядеть в дизайне. Например, паттерн. Для этого дизайн и описывают сначала на бумажке, а потом ревьювят
(Ответить) (Parent) (Thread)
[User Picture]From: 109
2003-06-29 06:09 am
так надо дизайнить паттернами, а не искать их там после дизайна. вот ты сказал волшебное слово "ownership". это во время дизайна должно происходить, а не после.
(Ответить) (Parent) (Thread)