Закэшированный план выполнения запроса SQL подвел

Всем привет! Столкнулся тут недавно я с проблемой долгого проведения документа.

Вводные данные: конфигурация «Управление производственным предприятием, редакция 1.3 (1.3.52.1)», документ «Платежное поручение входящее». Жалоба: проведение в рабочей базе длится 20-30 секунд, что интересно в копии базы этот же документ проводится 2-4 секунды. О расследованиях и причине такого поведения читайте ниже.

 

Итак, с помощью замера производительности, как его использовать думаю, все знают, было найдено место-виновник:

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

По данным замера производительности эта операция занимала 13 секунд, если посчитать среднее, то получается 0,5 секунды на регистр, вечность просто!

Как мы все знаем, запись мы оптимизировать не можем, но тут явно что-то не так.
Для дальнейшего анализа открываем SQL Server Profiler и настраиваем получение трассировки. Для анализа использовал классы событий:

  • Showplan Statistics Profile
  • Showplan XML Statistics Profile
  • RPC Completed
  • SQL:BatchCompleted.

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

В настройках трассировки есть фильтр по SPID:

SPID — это идентификатор процесса сервера баз данных. В случае с 1С по сути соединение между сервером 1С и СУБД, посмотреть его можно в консоли администрирования серверов 1С в колонке «Соединение с СУБД».

Отображается в том случае, если в данный момент соединение с базой данных захвачено сеансом: либо выполняется вызов СУБД, либо открыта транзакция, либо удерживается объект «МенеджерВременныхТаблиц», в котором создана хотя бы одна временная таблица.

Напишем обработку для удержания SPID, в ней будет одна процедура:

Важно, чтобы удерживаемый объект соединения, в нашем случае менеджер временных таблиц, был определен как переменная обработки. Открываем обработку, запускаем процедуру и до тех пор, пока она открыта, SPID будет зафиксирован. Открываем консоль администрирования серверов 1С:

Итак, SPID получен, вводим его значение в фильтр и получаем трассировку из рабочей базы ток по своему сеансу. При анализе трассировки была найдена операция, которая выполнялась 11 секунд:

Также в глаза бросилось количество чтений — 1872578, но я сразу не придал этому значения и начал разбирать, что и с какой таблицей тут делается.

exec sp_executesql N'SELECT TOP 1
0x01
FROM dbo._AccRg1465 T1
WHERE (T1._RecorderTRef = 0x0000022D AND T1._RecorderRRef = @P1) AND ((((T1._Period <= @P2) AND (T1._Fld1466RRef = @P3)) OR ((T1._Period <= @P4) AND (T1._Fld1466RRef = @P5))) OR ((T1._Period <= @P6) AND (1=0)))’,N’@P1 varbinary(16),@P2 datetime2(3),@P3 varbinary(16),@P4 datetime2(3),@P5 varbinary(16),@P6 datetime2(3)’,0x8A2F00155DBF491211E87F56DD1A416E,’4018-05-31 23:59:59′,0x00000000000000000000000000000000,’4018-05-31 23:59:59′,0x9A95A0369F30F8DB11E46684B4F0A05F,’4018-05-31 23:59:59'

Как видно по запросу SQL обрабатывается таблица «AccRg1465» это таблица регистра бухгалтерии Хозрасчетный. Текстовое представление плана выполнение запроса:

Как видно по плану выполнения запросу SQL ничего страшного не происходит, обрабатывается таблица «AccRg1465», везде используется поиск по кластерному индексу.

Графическое представление плана запроса:

По графическому плану тоже ничего страшного не увидел, хотя показался мне слишком раздутым — тут есть и слияние, и два вложенных цикла непонятно зачем. Откуда же такое количество чтений и гигантское время выполнения?

Как было сказано выше, в свежей копии базы проблема не воспроизводилась, копия была снята с рабочей базы после появления в ней проблемы, поэтому было решено проанализировать ее поведение в SQL Server Profiler на том же документе.
Вот результаты:

Текст запроса в SQL:

EXEC sp_executesql N'SELECT TOP 1
0x01
FROM dbo._AccRg1465 T1
WHERE (T1._RecorderTRef = 0x0000022D AND T1._RecorderRRef = @P1) AND ((((T1._Period <= @P2) AND (T1._Fld1466RRef = @P3)) OR ((T1._Period <= @P4) AND (T1._Fld1466RRef = @P5))) OR ((T1._Period <= @P6) AND (1=0)))',N'@P1 varbinary(16),@P2 datetime2(3),@P3 varbinary(16),@P4 datetime2(3),@P5 varbinary(16),@P6 datetime2(3)',0x8A2F00155DBF491211E87F56DD1A416E,'4018-05-31 23:59:59',0x00000000000000000000000000000000,'4018-05-31 23:59:59',0x9A95A0369F30F8DB11E46684B4F0A05F,'4018-05-31 23:59:59'

Текстовое представление плана запроса:

Графическое представление плана запроса:

Тексты запроса совпадают, планы выполнения отличаются кардинально. В чем же может быть дело? Грешил на статистику в SQl, но она одинаковая между рабочей и копией базы, а статистика хранится в базе для каждой таблицы:

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

DBCC FLUSHPROCINDB(< database_id >)

где < database_id > — это идентификатор базы. Чтобы узнать идентификатор базы нужно выполнить скрипт

select name, database_id from sys.databases

он вернет нам список баз и их идентификаторы.

Получаем опять трассировку:

Текстовое представление плана запроса:

Графическое представление плана запроса:

Как видно план запроса был заново получен оптимизатором, а не использовался старый закэшированный, время выполнение пришло в норму, как и количество чтений. Что стало причиной не ясно, возможно большое количество обменов или закрытие прошлых периодов, тяжело сказать. Регламентное обслуживание баз настроено. Впервые сталкиваюсь с обманом закэшированного плана выполнения запроса.

Спасибо за внимание!

Помогла ли вам данная статья?
Да, спасибо, помогла.
Немного помогла.
Совсем не помогла.
Не то, что я искал(а).
Смотреть результаты
Запись опубликована в рубрике Эксперт 1С с метками , . Добавьте в закладки постоянную ссылку.


3 Responses to Закэшированный план выполнения запроса SQL подвел

  1. Олег говорит:

    Доброго дня, стоит ли в планы обслуживания добавить очистку процедурного кэша и как часто его выполнять?

    • Виталий Онянов говорит:

      Здравствуйте.

      Очистку процедурного кэша стоит выполнять совместно с операциями обновления статистики и реорганизации индексов.
      Добавляется в план обслуживания в виде задачи «Выполнение инструкции T-SQL» с инструкцией:

      DBCC FREEPROCCACHE

      https://msdn.microsoft.com/ru-ru/library/ms174283(v%3Dsql.120).aspx

  2. Зенков Никита говорит:

    «Грешил на статистику в SQl, но она одинаковая между рабочей и копией базы, а статистика хранится в базе для каждой таблицы» Скрин «Анализируем дальше, если статистика одна и та же….»

    У меня такое ощущение, что актуальность статистики смотрится не так. Я думаю, что с очисткой процедурного кэша вам просто повезло, если бы статистика была бы out of date, тогда это не сработало бы. Для начала следует проверить актуальность статистики.
    И, в случае, если какая-то статистика окажется в неактуальном состоянии, точечно обновить её.

    Почитайте, пожалуйста, следующий материал, о том, как посмотреть дату последнего обновления статистики для SQL Server: https://docs.microsoft.com/ru-ru/sql/t-sql/functions/stats-date-transact-sql?view=sql-server-2017

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

Добавить комментарий для Виталий Онянов Отменить ответ

Ваш адрес email не будет опубликован. Обязательные поля помечены *