Я решил начать цикл статей о том, как мы решаем те или иные технические проблемы связанные с 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.
Задача решена.
