Замер до и после на боевой базе: как отличить ускорение от шума нагрузки

Приёмка оптимизации отвечает на два вопроса, и второй обычно не задают вовсе.

Первый: результат не изменился? На него отвечает сверка выхода. Второй: а ускорение вообще было? На него отвечает повторный замер, устроенный не так, как первый.

Обе половины отработаны на проекте оптимизации отчётности в крупной розничной сети. Платформа 8.3.17.1386, прод открыт только на чтение, внешние отчёты собирались и отлаживались на копии. И цифра, ради которой всё это писалось: одно из наших ускорений при перепроверке оказалось нулём.

Часть первая: замер, которому можно верить

Требования к процедуре

Начну с готового рецепта, а дальше покажу, откуда взялся каждый пункт.

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

Пункт про весь ряд самый недооценённый. Строчка “стало 23,0 против 26,5” выглядит как результат, а восемь чисел рядом показывают, что результата нет.

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

Наш первый замер был устроен привычно: три прогона, холодный отбрасываем, из оставшихся берём лучший. Логика за минимумом здравая - он ближе всего к цене операции на незанятом сервере, и посторонняя нагрузка его только портит.

На проде эта логика ломается ровно там, где кажется сильной. Минимум выбирает самый удачный момент из трёх, а удачный момент достаётся блокам случайно. Достался блоку после правки - вы отчитались об ускорении, которого не существует.

Так у нас и вышло на отчёте по складам одного бренда. Минимум дал минус тринадцать процентов. Медиана по тем же прогонам стояла на месте: 26 852 миллисекунды до правки против 26 516 после, разница чуть больше процента. Две метрики по одним и тем же данным расходились в разы, и мы взяли минимум - не потому, что он вернее, а потому, что так считали остальные отчёты, и сравнивать надо было одинаково.

Перепроверка чередованием, четыре круга подряд в одном окне, дала такие ряды:

• до правки: 25,1; 20,8; 23,5; 26,4 с
• после правки: 22,0; 22,4; 25,7; 24,4 с

Смотреть тут надо не на средние, а на перекрытие. Самый быстрый прогон вообще достался старому коду: 20,8 с, тогда как переписанный в лучшем случае дал 22,0 с. Ряды накрывают друг друга целиком, разброс держится в пределах пяти процентов в обе стороны. Устойчивого выигрыша нет.

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

Что показал разбор причины

Отсутствие эффекта полезнее самого факта, если понять, почему его нет.

Правки в том отчёте были грамотные: отбор поднят во временную таблицу и придвинут к источникам, срез цен перестал материализоваться целиком. Приёмы рабочие, разобраны у нас по восьми пунктам с замерами.

Мимо ушла главная стоимость. Время съедала виртуальная таблица остатков и оборотов с пустым началом периода: обороты считались от начала истории. Правки же трогали отборы по бренду и складам, а отбирать там нечего - склады подобраны так, что почти всё на них и есть товар нужного бренда. Дорогое место не тронули, дешёвые вылизали.

Отсюда правило, которое дороже самой методики замера: прежде чем принимать отсутствие эффекта за странность, посмотрите, куда уходит время. Обычно выясняется, что оптимизировали не то.

Итог по шести отчётам

Отчёт	До	После	Итог
Сводный складской	30,0 с	23,4 с	-22 %
Остатки по группам номенклатуры	20,2 с	14,1 с	-30 %
Показатели по неходовым позициям	~38 с	~26 с	-30 %
Склады одного бренда	~26,5 с	~23,0 с	эффекта нет
Возвраты	~6 с	-	выигрыша нет, оставлен оригинал
Кассовый X-отчёт	0,11 с	0,11 с	уже быстрый

Из шести: у трёх скорость выросла, один переписан корректно и остался при своей, два не трогали вовсе. Останься мы на первом замере, заказчик увидел бы четыре ускорения, и одно из них было бы выдумкой.

Отдельная строка про честность отчётности. Сводный складской имел два оптимизированных варианта: минус двадцать два процента без новых параметров и минус тридцать четыре, если добавить параметр со списком складов. Выкатили первый, потому что второй требовал от людей другого порядка запуска. Значит и в таблице стоит его число, меньшее из двух.

Чем мерить тяжёлый отчёт

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

Свести всё к одному прогону не выходит: наш собственный запрос от раза к разу показывал от 28 до 65 секунд. Идея замерить единожды, зато аккуратно, на живом проде не живёт.

Обходной путь - мерить не время, а работу. Число логических чтений и время процессора на запуск от посторонней нагрузки почти не зависят, поэтому им хватает и одного прогона:

-- логические чтения и CPU на запуск, накопленные с момента попадания плана в кэш;
-- фильтр по DB_ID() нужен, если на инстансе живёт не одна база
SELECT TOP 20
       qs.execution_count                                   AS zapuskov,
       qs.total_logical_reads / qs.execution_count          AS chteniy_na_zapusk,
       qs.total_worker_time  / qs.execution_count / 1000    AS cpu_ms_na_zapusk,
       qs.total_elapsed_time / qs.execution_count / 1000    AS ms_na_zapusk,
       SUBSTRING(st.text, (qs.statement_start_offset / 2) + 1,
                 ((CASE qs.statement_end_offset
                        WHEN -1 THEN DATALENGTH(st.text)
                        ELSE qs.statement_end_offset END
                   - qs.statement_start_offset) / 2) + 1)   AS tekst_zaprosa
FROM sys.dm_exec_query_stats AS qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) AS st
CROSS APPLY sys.dm_exec_plan_attributes(qs.plan_handle) AS pa
WHERE pa.attribute = 'dbid' AND CAST(pa.value AS int) = DB_ID()
ORDER BY qs.total_logical_reads / qs.execution_count DESC;

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

Когда счётчики выводят на тяжёлый пакетный запрос, часть работы по нему делается механически: обработка Оптимизатор временных таблиц находит место последнего использования каждой временной таблицы в пакете и расставляет УНИЧТОЖИТЬ сама - меньше мусора в tempdb, и повторный замер чище.

Часть вторая: доказать, что ничего не сломалось

Почему построчная сверка не работает на отчётах

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

На отчётах три вещи ломают её одну за другой.

Порядок строк никто не обещал. Сортировки в запросе нет - и строки лягут так, как их выдала СУБД, а выдача зависит от плана. Другой план, другой порядок: данные те же, файлы разные. Причём менять план и есть смысл оптимизации, так что построчная сверка ломается именно на тех правках, под которые её и завели.

Плавающая точка. Сложите те же числа в ином порядке - и последний разряд уедет.

Промежуточные округления. Стоит разложить расчёт по временным таблицам, как округление случается на другом шаге. Итог сходится, а промежуточные колонки нет.

Слепок из трёх частей

Сравнивать надо не файл, а повторяемый слепок. В нём три части: сколько строк, сумма по всем числовым ячейкам и SHA-256, снятый с канонически сериализованных строк, которые предварительно отсортированы как текст.

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

Толк в них другой. Покрасневший хеш говорит ровно “что-то не так” и ни слова о месте. Дальше смотрим два числа: разъехалось количество - значит поехала выборка; количество совпало при другой сумме - поехали значения. Хеш тут сигнализация, а эти двое наводят на место, и смотреть на них можно без всяких инструментов.

Как это выглядит на живом примере: тот самый отчёт по складам одного бренда дал 75 078 строк, ту же сумму числовых ячеек и SHA-256, начинающийся на 76F50C6E, - до и после, при полностью переписанном запросе. Скорости вариант не дал, вреда тоже, код стал понятнее, и в деплой он ушёл именно на этом основании.

Код снятия

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

// Снимает слепок результата: число строк, сумма числовых ячеек и SHA-256
// по нормализованным строкам. ЗначащихЗнаков - до скольких знаков после запятой
// округляем числа перед хешированием (для денег 2).
Функция СлепокТаблицы(Таблица, ЗначащихЗнаков = 2) Экспорт

    Колонки = Новый Массив;
    Для Каждого Колонка Из Таблица.Колонки Цикл
        // служебные поля расчёта в слепок не идут
        Если СтрНачинаетсяС(Колонка.Имя, "Служебное") Тогда
            Продолжить;
        КонецЕсли;
        Колонки.Добавить(Колонка.Имя);
    КонецЦикла;
    Колонки.Сортировать();   // фиксированный порядок колонок

    СтрокиДляХеша = Новый Массив;
    СуммаЧисел = 0;

    Для Каждого Строка Из Таблица Цикл
        Ячейки = Новый Массив;
        Для Каждого ИмяКолонки Из Колонки Цикл
            Значение = Строка[ИмяКолонки];
            Если ТипЗнч(Значение) = Тип("Число") Тогда
                Значение = Окр(Значение, ЗначащихЗнаков);
                СуммаЧисел = СуммаЧисел + Значение;
                Ячейки.Добавить(Формат(Значение, "ЧГ=0; ЧДЦ=" + ЗначащихЗнаков));
            ИначеЕсли Значение = Неопределено Или Значение = Null Тогда
                Ячейки.Добавить("");                       // пустые к одному виду
            ИначеЕсли ТипЗнч(Значение) = Тип("Дата") Тогда
                Ячейки.Добавить(Формат(Значение, "ДФ=yyyyMMddHHmmss"));
            Иначе
                Ячейки.Добавить(СокрЛП(Строка(Значение))); // хвостовые пробелы прочь
            КонецЕсли;
        КонецЦикла;
        СтрокиДляХеша.Добавить(СтрСоединить(Ячейки, Символы.Таб));
    КонецЦикла;

    // порядко-независимость: сортируем строки как строки, дубли НЕ схлопываем
    ТаблицаСортировки = Новый ТаблицаЗначений;
    ТаблицаСортировки.Колонки.Добавить("Ключ");
    Для Каждого Т Из СтрокиДляХеша Цикл
        ТаблицаСортировки.Добавить().Ключ = Т;
    КонецЦикла;
    ТаблицаСортировки.Сортировать("Ключ");

    Отсортированные = Новый Массив;
    Для Каждого С Из ТаблицаСортировки Цикл
        Отсортированные.Добавить(С.Ключ);
    КонецЦикла;

    Хеширование = Новый ХешированиеДанных(ХешФункция.SHA256);
    Хеширование.Добавить(СтрСоединить(Отсортированные, Символы.ПС));

    Результат = Новый Структура;
    Результат.Вставить("Строк", Таблица.Количество());
    Результат.Вставить("Сумма", СуммаЧисел);
    Результат.Вставить("Хеш",
        ПолучитьHexСтрокуИзДвоичныхДанных(Хеширование.ХешСумма));
    Возврат Результат;

КонецФункции

Два места здесь легко испортить.

Первое: дубли строк схлопывать нельзя. Соблазн прогнать массив через свёртку уникальных велик, сортировать потом дешевле. Но задваивание строк - самая дорогая ошибка оптимизации, и слепок, схлопывающий дубли, перестаёт её видеть.

Второе: ПолучитьHexСтрокуИзДвоичныхДанных тут не для красоты. ХешСумма отдаёт двоичные данные, и приведение их к строке через Строка() даст представление объекта, а не хеш.

Нормализация несёт всю конструкцию

Слово “канонически” в описании слепка главное. Нормализовать значит привести результат в такое состояние, из которого незначимые различия ушли раньше, чем за дело взялся хеш:

• числа округляются до значимой точности. В отчёте про деньги хватает копейки. Пятнадцатый знак не нужен никому, зато от перестановки слагаемых он гуляет, и хеш краснеет: к последнему разряду SHA-256 чувствителен предельно;
• промежуточные колонки выбрасываются. В слепке остаётся то, на что смотрит человек, а служебные поля расчёта живут снаружи;
• пустые значения приводятся к одному виду: пустая строка, Null и Неопределено дальше должны выглядеть одинаково;
• порядок колонок фиксируется;
• шапка вырезается. Время формирования, пользователь и номер версии меняются законно.

Выкиньте первые два пункта, и из трёх названных проблем слепок закроет одну. С порядком строк справляется хеш; плавающую точку и промежуточные округления гасит нормализация, которая прошла раньше него.

Мина в быстром способе

К независимости от порядка ведут две дороги. Либо сортировка всего набора до хеширования, либо свой хеш на каждую строку и свёртка коммутативной операцией.

Второй быстрее и имеет неприятное свойство. Свёртка через исключающее ИЛИ даёт ноль на любом чётном числе одинаковых строк, а значит задваивания, самой дорогой ошибки, она не видит. Тут и становится понятно, зачем в слепке первая часть: число строк прикрывает ровно эту дыру.

Сложение по модулю этим не болеет, так что свёртку можно оставить и на нём. Мы пошли через сортировку: медленнее, зато думать не надо.

Три случая, когда слепка мало

Колонка недетерминирована в самом отчёте. Встроенный отчёт на одних и тех же параметрах возвращал в одной колонке разные значения от прогона к прогону. Такому набору красный хеш обеспечен всегда, и нормализация бессильна: различие значимое, просто невоспроизводимое. Сверку там свели к колоночной - контрольная сумма на каждую колонку, а гуляющую колонку исключили явно и записали это в протокол приёмки.

Колонки поменялись местами. Колоночная сверка тут же нашла настоящий дефект в другом отчёте: значения двух числовых столбцов оказались переставлены. Ни общая сумма по числовым ячейкам, ни количество строк от такой перестановки не двигаются. Хеш бы покраснел, а адреса не дал. Суммы по колонкам указали на виноватую пару сразу.

Параметры выбираются сами. Ещё один отчёт разошёлся там, где до данных никто не дотрагивался. Виноват был не код, а сам замер: значение параметра добывалось вспомогательным запросом с ПЕРВЫЕ 1 и без сортировки, платформа в двух прогонах вернула разное, и отчёт добросовестно посчитал два разных сезона. Вывод короткий: пока вход не детерминирован, мерить эквивалентность бессмысленно.

Приём выбирается по тому, что может сломаться

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

Что меняем	Что может сломаться	Чем проверяем
Отчёт, выгрузка	состав и значения строк	слепок результата
Пересчёт итогов	сами итоги, их и меняем	сверка остатков с прямым расчётом по движениям
Чистка данных	учёт	оборотно-сальдовая до и после, до копейки
Операции с кластером	доступность соседей	проверка живости по всем базам

Пересчёт итогов слепку не по зубам в принципе: правка бьёт ровно по тому, что слепок и сравнивает. Проверка другая - взять регистр, сложить движения с начала и сверить полученный остаток с тем, что лежит в таблице итогов. Для пересчёта, который за 25 минут убрал итоги с 73,6 миллиона строк до 18,3, другого доказательства корректности не было вовсе.

Веб-выгрузка остатков шла на том же проекте отдельным треком и дала максимальный прирост скорости: на разных объёмах до 8,5 раза, а в замеренном вызове 192 секунды превратились в 59. Со слепком тут повезло: наружу уходит JSON, и он совпал байт в байт. Тонкость в дроблении - вызов идёт по одному складу, поэтому слепков ровно столько, сколько складов, и каждый живёт своей жизнью. Свести их в один по всем складам сразу значило бы утопить расхождение по единственному складу в общей сумме.

Вывод простой: про упавшую соседнюю базу хеш отчёта вам не скажет ни слова.

Красный слепок: порядок разбора

Первая реакция всегда “сломали”, и часто это неправда. Разбирать по возрастанию тяжести:

1. Строк стало другое число. Случай частый, он же и самый дорогой: соединение начало терять или задваивать. Разбирать весь запрос не нужно, смотрите то соединение, которое трогали руками. Типовая история - вложенный запрос переделали в соединение и забыли условие связи.
2. Количество то же, сумма не та. Поехали числовые колонки. Причина либо в изменившемся расчёте, либо в том, что старые строки подменились другими в равном количестве. Вторая реже, но путать эти две не надо. Вот тут построчное сравнение двух версий уместно: искать осталось в одной колонке.
3. Строки и сумма на месте, хеш красный. Разъехалось что-то нечисловое: текст, признак, последовательность колонок. Нередко выясняется, что выборка прежняя, а сбилась нормализация. Классика - у поля появился пробел на конце.
4. Всё сошлось, а пользователь видит другое. Слепок снят не с того, что лежит перед человеком. Проверьте, попала ли туда итоговая таблица целиком, вместе с расшифровками и группировками.

Гипотеза, которую отклонил замер

Заходили мы с убеждением, что дереференс к справочнику, вписанный прямо в условие, всегда проигрывает индексному полусоединению с временной таблицей. На двух отчётах приём подтвердился, и дальше мы понесли его как универсальный.

На отчёте по неходовым позициям правка первой версии сделала ровно обратное: отчёт стал медленнее. Отбор по виду номенклатуры почти ничего не отсекал, под него проходила без малого вся номенклатура, и соединение с этим гигантским списком вышло дороже дереференса. Выручил заход с другого конца: срез цен ограничили номенклатурой, у которой за день были движения. Движений за один день несопоставимо мало против целой базы, и минус тридцать процентов нашлись именно там.

На чековых отчётах выигрыша не случилось вовсе. Отбор по периоду платформа и сама уводит в условие Ссылка.Дата МЕЖДУ, так что предварительно отбирать документы ей незачем.

Отсюда и граница: на узком отборе полусоединение помогает, на широком мешает. Насколько отбор узок, по тексту запроса не понять - это видно только из замера на боевых объёмах.

Чего это стоит

Разговор неполон без цены.

Время. Эталон, прогон правки, повторный слепок, разбор расхождения - в сумме это тянет на вторую такую же правку.

Стенд. Под эталон нужна копия прода, и непременно свежая. Отсюда диск, часы на восстановление и постоянная оглядка на дату копии: снятый на устаревшей базе эталон “до” не значит ничего.

Ночные окна. Тяжёлое выполняется монопольно, и приёмка встаёт сразу за ним, в это же окно. Про то, как эти окна репетируются, у нас есть отдельный разбор.

Прогоны. Их восемь, а не три, и на тяжёлом отчёте разница считается уже не минутами.

Люди. Про неизменность данных слепок скажет и промолчит о том, способен ли пользователь работать. Прогон под настоящими ролями остаётся на человеке.

Платят же при этом за оптимизацию, а доказательства корректности заказчик получает в подарок.

Открытый вопрос

Тезис: пока замер на проде не перепроверен чередованием до и после, результат от шума нагрузки не отличить.

Слабое место я назвал сам - тяжёлый отчёт в чередование не помещается, а именно тяжёлые и переписывают. Счётчики чтений закрывают вопрос наполовину: с ними доказано меньшее количество работы, но не выросшая скорость.

Если нужна оптимизация, которую можно предъявить, - у нас это отдельная услуга с замерами и протоколом приёмки, и обе половины дисциплины из этой статьи в неё входят.