Каталог решений - История оптимизации одного большого запроса средствами MSSQL Profiler и 1С

Добрый день, уважаемые коллеги.

Небольшая предыстория. Основной целью проекта являлась консолидация двух достаточно больших нетиповых баз ЗУП 2.5 (общее количество подразделений 140, сотрудников 4700). Базы ЗУП до нас дорабатывались и сопровождались другими подрядчиками, а нас привлекли именно на консолидацию. После консолидации пользователи сообщили о сильно возросшей длительности операции заполнения документа «Начисление зарплата сотрудникам». Собственно с этого момента я подключился к этому вопросу.

Часть I – Подготовительная:

Если театр начинается с вешалки, то любая оптимизация начинается с установки подсистемы «Замеры производительности» из БСП. Как внедрять и что за подсистема неплохо описано, например, в этой статье //sale.itcity.ru/public/193233/, поэтому на этом подробно останавливаться не буду. Описание самой методики APDEX хорошо дано на kb.1c.ru, а так же у Славы Гилева http://www.gilev.ru/apdex-teoriya/ и Антона Гусева (наш сотрудник — http://antongusev.ru/article2.html).

Если вкратце, то методика APDEX является широко распространенным международным стандартом оценки производительности информационных систем и является:

• объективной: оценка не зависит от субъективных факторов (эмоции, мнения и т.п.);
• прикладной: оценка отражает реальную производительность прикладных операций, а не абстрактные технические показатели;
• интегральной: оценка учитывает все аспекты работы системы, все требования бизнес-логики системы и удобство работы каждого пользователя;
• количественной: оценка является численной для того, чтобы можно было сравнивать производительность, полученную при разных обстоятельствах (например, до и после оптимизации);
• качественной: оценка интерпретируется в терминах «хорошо» — «плохо».

Сказать, что у нас дела были плохо – это значит не сказать ничего . Оценка показывала «неприемлемо».

 Время выполнения в максимуме иногда достигало 20 минут (см. ниже).

Теперь понятно, ЧТО нужно оптимизировать, пока непонятно КАК. Идем дальше…

Часть II – Неудачная, но длинная

Естественно, что первым делам был сделан замер производительности средствами 1С. Он обрадовал и не обрадовал одновременно. 95% на один запрос из 10 минут — это конечно хорошо, так как мы сходу нашли «узкое место», с другой стороны – не стоит рассказывать про монструозность запросов в ЗУП о которых ходят легенды. Запросы на тысячу строк кода и десятками временных таблиц, собираемый по кусочкам из разных мест. К сожалению, мне попался именно такой запрос – соответственно, как я говорил выше, провести нормальный рефакторинг кода, учитывая полное отсутствие каких-либо комментариев со стороны разработчиков ЗУП, дело мягко говоря неблагодарное.

Простой перезапуск запроса через консоль в тестовой базе подтвердил достаточно длительное время выполнения запроса, но пытаться найти вручную один «плохой» запрос из пары десятков не очень хотелось. Было принято решение запустить запрос через SQL Profiler, т.к. через него я смогу сузить область поиска «плохого» запроса.

Запускаем Microsoft SQL Profiler (performance tools в Пуск). Как запустить SQL Profiler и подключиться к нужному серверу – выходит за рамки статьи – это более подробно описано в других местах (sql.ru / BOL).

Запускаем новый trace со следующим набором событий (Events) (см. ниже). Можно уменьшить выборку колонок, которые будут собираться, но для упрощения можно просто выделить все — пока не принципиально.

Не забываем установить фильтры событий, чтобы не собирать всякий «мусор» (т.е. события других баз, в т.ч. основной базы, напоминаю, что мы работаем в тестовой базе). Чтобы узнать ID базы можно выполнить запрос select DB_ID ( [ ‘database_name’ ] ) в SQL Server Management Studio

Стартуем трейс перед началом заполнения и останавливаем после завершения. Дальше выгружаем его в таблицу для удобства работы.

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

SELECT *

FROM [tempdb].[dbo].[temp]

ORDER BY Duration DESC

//temp – название таблицы в которую выгрузили трейс из Profiler

Пример выполнения запроса на скриншоте ниже (немного другого :), но суть та же)

Видим две строчки с ОЧЕНЬ высоким Duration с ними и будем разбираться. В MS SQL Profiler находим по StartTime – EndTime (все строчки расположены по возрастанию EndTime). Проанализируем вторую строчку, как наибольшую. Находим строчку в замере Profiler’а.

Смотрим план запроса (это строчка сразу НАД найденной строкой). Этим кстати и объясняются все танцы с бубном вокруг выгрузки трейса в таблицу, так как у планов выполнения запроса нет метрики Duration и найти план выполнения запроса без привязки к основному запросу крайне затруднительно. Не буду приводить полный ПВЗ, а покажу только его часть – в ПВЗ видим постоянные table scan с весом в 14% каждый с одной и той же таблицей #tt38.

Смотрим таблицу #tt38 в ней обнаруживается 2 миллиона строк (см. ниже)!!! Явная ошибка именно в этой таблице —  в данных по зарплате по одному подразделению не может быть такого количества записей даже с самой маленькой детализацией (если только не предположить, что у сотрудников посекундная тарификация :))

Находим наш запрос в 1С. Вот он — куча левых соединений с таблицей ЗначенияПоказателей.

Я думаю у многих возникает вопрос: «А как найти аналог запроса 1С по известному нам запросу SQL?». Для этого есть следующие «помощники»:

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

Это последний (результирующий) запрос в пакете. Разбираться надо с таблицей #tt38 (это кстати вторая строка по длительности в трейсе – insert into #tt38). Аналогичным образом находим ПВЗ для таблицы #tt38 (см. ниже).

Проблема начинается в выделенном фрагменте (именно с этого момента возникает 2 миллиона строк), на входе у нас приходит две таблицы на 3000 строк, которые объединяются. Подумал, что стоит на всякий случай проверить — нет ли ошибки при объединении, так как уже было сказано выше — 2 млн. строк быть не должно.

Мы уже знаем, что нам нужна таблица ЗначенияПоказателей — ниже приведен текст проблемного запроса. И действительно была обнаружена ошибка в соединении, которая выделена подчеркиванием (в конце запроса).