Спящая красавица - как один из старейших багов EVE был найден и исправлен :: Дев блог :: EVE-ONLINE

Иногда история о баге получается такой интригующей, что ты просто обязан её записать. Если у вас технический склад ума или вам просто любопытно узнать реалии разработки EVE Online – присоединяйтесь. Мы окунёмся в технические глубины исходного кода EVE Online в моих воспоминаниях о том, как один из старейших дефектов в игре был найден и исправлен.

Мы всегда работаем над тем, чтобы улучшить EVE Online и наш исходный код. Я надеюсь, что вы получите удовольствие от рассказа о том, что из себя представляет эта работа.

Как это всё началось

Не так давно CCP karkur попросила меня помочь ей в работе над исправлением проблемы с окном управления дронами, когда оно переставало обновляться после того, как дроны были отозваны. Её расследование не выявило никаких багов в коде связанных с дронами или пользовательским интерфейсом. На протяжении нескольких часов она смогла воспроизвести баг с дронами всего три раза – каждый раз добавляя ещё больше логирования там, где, как казалось, находилась проблема. Во время последней попытки стало ясно, что проблема была в той строчке кода, где мы меньше всего ожидали её найти – окно управления дронами начинало обновляться, потом засыпало и никогда не просыпалось. Казалось, что тасклеты просто, в случайный момент, не выходили из сна.

Оригинальный баг было довольно сложно воспроизвести, но CCP karkur написала скрипт, который генерировал 500,000 тасклетов, которые должны просто спать определённое время. Потом скрипт искал те из них, которые никогда не заканчивали своё исполнение. Скрипт помог надёжно воспроизводить это расстройство сна. Скрипт указал на тасклет, который не просыпался, и после дальнейшего анализа стало ясно, что этот тасклет не был ни запланирован, ни блокирован – он был в каком-то лимбе.

Немного деталей

Тасклеты (см. Stackless Python для информации) запускаются внутри метода PyScheduler::Run посредством вызова метода PyStackless_RunWatchdogEx. Этот метод принимает таймаут в качестве аргумента и запускает любые тасклеты из расписания до тех пор, пока переданное время не прошло. Когда тасклет создаётся, он вносится в расписание и будет запущен во время вызова PyScheduler::Run. Когда тасклет спит, он вызывает Synchro::SleepWallclock, реализация которого представляет собой создание канала и выполнения метода receive этого канала. Эта логика блокирует канал до тех пор, пока кто-то не пошлёт какие-либо данные на этот канал. Объект Synchro содержит кучу (heap) слиперов. Слипер – это простой объект, который содержит канал и время до пробуждения тасклета. Метод Synchro::Tick извлекает слипер с вершины кучи и отправляет значение по определённому каналу. Это, в свою очередь, разблокирует тасклет и заносит его в расписание.

Первой моей идеей было то, что, возможно, присутствует баг в реализации кучи. Это наш собственный код, он старый и для него нет юнит тестов. Я думал над тем, чтобы написать пару тестов или вообще найти замену существующему коду, когда понял, что симптомы просто не соответствуют ситуации, когда тасклет никогда не извлекается из кучи. Если бы дело было в этом, то тасклет вечно оставался бы заблокированным. Кстати, у меня до сих пор в to-do добавить тесты к этому коду.

Моей следующей идеей было посмотреть в документацию PyStackless_RunWatchdogEx. Эта функция может вернуть тасклет, который нельзя ни убить, ни перенести в расписание. Это оказалось тупиковой идеей – такое может случится только при работе в упреждающем режиме (preemptive mode), когда тасклет может быть прерван.

Покажи мне код

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

PyObject* Synchro::SleepWallclock(int ms, const int64_t &due;)
{
    Sleeper sl;
    sl.channel = PyChannel_New(NULL);
    if (!sl.channel)
        return 0;
    PyChannel_SetPreference(sl.channel, 0); //просто чтобы работало во время пробуждения
    sl.due = due;

    mWallclockSleepers.Insert(sl);
     
    // Усни и проснись! *(отправитель разблокирует канал)
    PyObject *ret = PyChannel_Receive(sl.channel);

    if (!ret) {
        //нас убили, давайте поищем нас в очереди чтобы высвободить ресурсы
        RemoveSleeper( mWallclockSleepers, sl );
    }
    return ret;
}

Функция SleepWallclock создаёт канал, добавляет его в слипер, помещает слипер в кучу и вызывает метод receive канала. Метод receive возвращает результат после того, как Synchro::Tick вызывает метод send для этого канала. Вызов send разблокирует канал и, в последующем, добавляет его в расписание. Также, тасклет может быть уничтожен, в этом случае метод receive возвращает nullptr. Давайте взглянем на фрагмент года из Synchro::Tick:

//собрать слиперы для пробуждения
std::vector sleepers;
while (mWallclockSleepers.size()) {
    if (mWallclockSleepers.front().due > now)
        break;
    sleepers.push_back(mWallclockSleepers.Shift());
}
if (sleepers.size()) {
    Be::Time nnow = BeOS->GetActualTime();
    for(unsigned int i = 0; i < sleepers.size(); i++) {
        Sleeper &s;= sleepers[i];
        if (PyChannel_GetBalance(s.channel)) {
            int res = PyChannel_Send(s.channel, Py_None);
            if (res)
                PyOS->PyError();
        }
        Py_DECREF(s.channel);
    }
}

Всё это выглядит корректно – канал нельзя вытащить из-под тасклета до тех пор, пока не произошёл вызов метода Send. А что происходит если убить тасклет?

void Synchro::RemoveSleeper( Heap &sleepers;, Sleeper &sl;)
{
    SleeperIt it;
    for( it = sleepers.begin(); it != sleepers.end(); ++it )
    {
        if( it->channel == sl.channel )
        {
            break;
        }
    }

    if( it != sleepers.end() )
    {
        //Ок, нас нашли. Пора нас удалить.
        sleepers.Remove( it );
        Py_DECREF( sl.channel );
    }
}

Снова всё выглядит нормально – тасклет убирается из кучи и канал освобождается. Обратите внимание, что если тасклета нет в куче, то это не ошибка – он может проснутся и быть добавлен в расписание и, в тот же самый момент, быть убитым. Но в этом случае канал будет освобождён.

Давайте всё же проанализируем это немного дальше. Имейте ввиду, что Py_DECREF освобождает память если количество ссылок равно нулю. Вызов PyChannel_New внутри SleepWallclock возвращает объект типа PyChannelObject. Новых ссылок не добавляется, так что объект канала удаляется в тике, когда вызывается Py_DECREF. Это кажется вполне нормальным ведь после вызова receive в SleepWallclock ссылок на канал больше нет. Не считая...

Внутри функции RemoveSleeper, которая вызывается после уничтожения тасклета, мы сравниваем каналы. На самом деле, на этом месте мы сравниваем тасклеты, но т.к. между каналом и тасклетом у нас всегда связь один к одному, и мы всё равно вынуждены следить за каналами чтобы пробуждать тасклеты, то мы просто используем для сравнения каналы. Я добавил ссылку на тасклет внутри слипера и получил возможность проверить, что этот тасклет действительно есть, и вдруг, о чудо, когда CCP karkur запустила скрипт, я увидел несоответствие – судя по данным из канала тасклет был в куче, но он не совпадал с тасклетом из слипера.

Эврика

Когда канал удаляется, память, которую он занимал, высвобождается и становится доступна для повторного использования. Из этого следует, что тасклет, который засыпает в тот же тик, что и тасклет, который уничтожается в тот же самый момент, когда он собирался проснуться могут получить один и тот же указатель на канал. В этом случае RemoveSleeper удалит неправильный тасклет (тот, который только вызвал SleepWallclock) из кучи и убьёт его канал. Этот тасклет не будет занесён в расписание и не будет заблокированным.

Исправить очень просто – переместить вызовы Py_DECREF внутрь SleepWallclock. Это гарантирует, что каналы не будут уничтожены раньше положенного срока. Это, по моему мнению, даже лучше ведь весь учёт ссылок будет сконцентрирован в одной функции.

Никогда не предполагай

Еве уже почти 14 лет и она видела много битв за свою жизнь. Можно сказать, что код был тщательно проверен в бою. В тоже время, хоть это и не значит, что скрытые баги не прячутся внутри, но найти баг в такой фундаментальной функции было, мягко говоря, удивительно. Я думаю, что мы никогда не сможем утверждать, что любая часть нашего исходного кода на 100% корректна. CCP karkur и другие потратили существенное количество времени выслеживая эту ошибку, так что мы были достаточно уверены в более высокоуровневом коде. Именно это позволило мне начать это исследование на основе предположения, что метод Sleep был сломан, и быть достаточно упрямым чтобы воспроизвести этот редкий сценарий.

У нас есть основание полагать, что и несколько других багов это лишь симптомы одной и той же основной проблемы. Например, овервью не обновляется, не обновляются полоски щитов, брони и структуры. Эти баги было почти нереально воспроизвести, но несмотря на это, они периодически давали о себе знать. Особенно после массовых тестов или больших битв на Транквилити.

-CCP Snorlax

Перевод © Garret