Anatoly Vorobey (avva) wrote,
Anatoly Vorobey
avva

Category:

об одном баге



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

Вот над этим багом я и Брэд корпели последние 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 на последний ключ из списка ключей первого клиента, и, кроме того, первый клиент сразу после получения ответа на свой запрос прервал своё подключение. Неудивительно, что он проявлялся только на "живых" данных (т.е. при огромном потоке "живых" запросов)!

Уф.

Как. я. рад. что. мы. его. нашли.
Subscribe
  • Post a new comment

    Error

    default userpic

    Your IP address will be recorded 

    When you submit the form an invisible reCAPTCHA check will be performed.
    You must follow the Privacy Policy and Google Terms of use.
  • 31 comments