Непридуманные истории по оптимизации. История 1

Я решил начать цикл статей о том, как мы решаем те или иные технические проблемы связанные с 1С. В основном меня интересуют административные вопросы, то есть моя основная задача – сделать так, чтобы продуктивная система работала, несмотря на все попытки разработчиков и бизнес-аналитиков ее положить J

Говорил в предыдущих статьях, но напомню:

База ~4 Тб, 6 app серверов, 2 MS SQL сервера объединенных в AlwaysOn, сильно переписанная УТ 11.3.

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

Обращаю внимание – все нижеописанные проблемы имеют несколько решений, не всегда мое решение оптимальное, но оно точно помогло. Объективная критика приветствуется.

Итак, проблема этой недели. Повышенная нагрузка на ЦПУ в начале каждого часа и продолжающаяся примерно 5-10 минут.

Вот так выглядит проблема:

Вот более крупно самый большой всплеск в 21 час.

Следствием нагрузки на ЦПУ SQL сервера становится повышенный средний CALL (время вызова), а следовательно растет и время выполнения основных операций. Система «тормозит».

Причина всплеска на самом деле достаточно проста, у нас 3 с лишним тысячи магазинов по всей стране, в 16 часов по МСК начинают закрываться магазины. При закрытии магазина происходит много ресурсоемких операций, закрытие смены, печать документов, различные расчеты и прочее. В 21 час по МСК закрывается больше всего магазинов, поэтому и пик в это время наиболее длительный и высокий. Жалоб от пользователей не поступает, но… как то не аккуратненько.

Для решения решил посмотреть, а что за запросы массово выполняются в период с 20:55 до 21:20. Надеюсь вы собираете технологический журнал, потому что если не собираете – я не знаю, как вы анализируете ваши проблемы. Длинные call у меня собираются этим куском ТЖ:

<log location="D:\TJ_logs\Long_1" history="25">
     <event>
          <eq property="name" value="DBMSSQL" />
          <gt property="duration" value="10000" />
     </event>
<event>

Дальше у нас есть некое самописное ПО которое парсит технологический журнал и аккуратно складывает данные в базу MS SQL. Есть множество обработок на 1С делающие аналогичное, просто у нас объемы, с которыми 1С не справляется, мы используем C#, причем на создание и оптимизацию разработчик потратил пару месяцев.

Делаем запрос к БД и смотрим, какой контекст выполнялся за указанный период дольше всего:

SELECT TOP 10 Context, sum(_duration)/1000000, count(*)

  FROM [1C_Log].[dbo].[TJ_Long_1]

  WHERE _event = 'DBMSSQL'

  AND _eventDate between '2019-06-10 20:55' and '2019-06-10 21:20'

  GROUP by Context

  ORDER by sum(_duration) DESC

Получаем такой результат.

Видим, что основное время SQL сервера уходит на первые две операции. Посмотрим на первый запрос, который выполняется в это время:

контекст:

  SELECT top 1 sql

  FROM [1C_Log].[dbo].[TJ_Long_1]

  WHERE context = 'Форма.Вызов : Обработка.ЗакрытиеДня.Форма.Форма.Модуль.ЗакрытьСобытияНаСервереОбработка.ЗакрытиеДня.Форма.Форма.Форма : 659 : СистемаИнформирования.ОтметитьВыполненностьСобытийСистемыИнформирования(ЗакрываемоеПодразделение); ОбщийМодуль.СистемаИнформирования.Модуль : 507 : РезультатЗапроса = Запрос.Выполнить();'

  AND _eventDate between '2019-06-10 20:55' and '2019-06-10 21:20'

Результат:

INSERT INTO #tt390 WITH(TABLOCK) (_Q_000_F_000, _Q_000_F_001, _Q_000_F_002RRef, _Q_000_F_003RRef, _Q_000_F_004_TYPE, _Q_000_F_004_RTRef, _Q_000_F_004_RRRef) SELECTMAX(T1._Fld24158),MAX(T1._Fld24162),T1._Fld24159RRef,T1._Fld24160RRef,T1._Fld24161_TYPE,T1._Fld24161_RTRef,T1._Fld24161_RRRefFROM dbo._InfoRg24157 T1WHERE ((T1._Fld26199 = ? AND T1._Fld773 = ?)) AND ((T1._Fld24159RRef = ?))GROUP BY T1._Fld24159RRef,T1._Fld24160RRef,T1._Fld24161_TYPE,T1._Fld24161_RTRef,T1._Fld24161_RRRefp_0: 0Np_1: 0Np_2: 0x80FA5CB9019038F011E7EAD0A1C5BCF8

Вставка во временную таблицу. Выделяем отсюда запрос

SELECT

MAX(T1._Fld24158),MAX(T1._Fld24162),T1._Fld24159RRef,T1._Fld24160RRef,

T1._Fld24161_TYPE,T1._Fld24161_RTRef,T1._Fld24161_RRRef

FROM dbo._InfoRg24157 T1

WHERE ((T1._Fld26199 = 0 AND T1._Fld773 = 0))

AND ((T1._Fld24159RRef = 0x80FA5CB9019038F011E7EAD0A1C5BCF8))

GROUP BY T1._Fld24159RRef,T1._Fld24160RRef,T1._Fld24161_TYPE,T1._Fld24161_RTRef,T1._Fld24161_RRRef

И выполняем его.

Видим, что время выполнения составляет 54 секунды. Как-то многовато. А сколько в таблице записей?

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

Посмотрим на план запроса и на индекс, который нам предложит Management Studio

CREATE NONCLUSTERED INDEX [<Name of Missing Index, sysname,>]

ON [dbo].[_InfoRg24157] ([_Fld24159RRef],[_Fld26199],[_Fld773])

INCLUDE ([_Fld24158],[_Fld24160RRef],[_Fld24161_TYPE],[_Fld24161_RTRef],[_Fld24161_RRRef],[_Fld24162])

Ну в принципе необходимость этого индекса мы могли бы предсказать и без помощи SQL, просто посмотрев на запрос и имеющиеся индексы, но так же проще J

ОК, немного упрощаем запрос, пишем:

CREATE NONCLUSTERED INDEX [<Name of Missing Index, sysname,>]

ON [dbo].[_InfoRg24157] ([_Fld24159RRef])

INCLUDE ([_Fld24158],[_Fld24160RRef],[_Fld24161_TYPE],[_Fld24161_RTRef],[_Fld24161_RRRef],[_Fld24162])

WITH (ONLINE = ON)

Два поля мы убрали из индекса так как это общие реквизиты, у нас в базе они не используются (достались от типовой) и всегда равны 0.

Ну а ONLINE = ON нужно чтобы при построении индекса пользователи могли продолжать работу.

Итак, строим индекс, время на построение на продуктивной системе ушло 2.5 часа.

Результат нагрузки на SQL.

 И выделим покрупней 21-ый час.

Видно, что нагрузка ушла. В Long данный контекст так же ушел из ТОП-10.

Задача решена.