Пример поиска неоптимальности при загрузке SQL-сервера по CPU на 100%

 select 
      sql = cast(SUBSTRING( ST.text, (er.statement_start_offset/2) + 1,((CASE er.statement_end_offset WHEN -1 THEN DATALENGTH(ST.text) ELSE er.statement_end_offset END -   er.statement_start_offset)/2) + 1)as varchar(max)), 
      er.session_id, CPU     = cast( er.cpu_time as bigint), lReads  = er.logical_reads, lWrites = er.writes, fReads  = er.reads, Duration = cast( er.total_elapsed_time as bigint), er.start_time
  from     
      sys.dm_exec_requests AS er with(nolock)
      outer APPLY sys.dm_exec_sql_text(er.sql_handle) as ST
  where er.session_id > 50
  order by CPU desc

  exec sp_WhoIsActive @sort_order = '[CPU] DESC'

Большая часть запросов вида  INSERT INTO #tt5 (_Q_000_F_000,_Q_000_F_001RRef) VALUES(@P1,@P2)

Захожу в "консоль серверов 1С", в соединения соответствующей БД - оказыватся, полку "шелезяк" прибыло, появился новый вид фоновых  "ФормированиеЗаказа":


Эти новые фоновые CPU на sql-сервере скушали, и памяти на серверах кластера 1С нахватали от души.
Ищу документацию по "ФормированиеЗаказа", иду к соответствующему ведущему программисту.
Он и говорит : "да, вот две недели назад с понедельника потихонечку и запустили.. заказ в точку теперь с серверной стороны идет - расчет всякой красивой статистики, сезонность, мощный математический аппарат, все дела.. При тестировании все было отлично!".

Ладно, копаю дальше..
Коль работает две недели - глянем лидеров по CPU за две недели на сервере  (этим инструментом)


 
На первые места вылезли странные вставки во времянки
INSERT INTO #ttNN (VAL) VALUES(@P1)
и, ага, то самое
INSERT INTO #ttNN (VAL,VAL) VALUES(@P1,@P2)
Количество зафиксированных в sys.dm_exec_query_stats экземпляров запросов обоих видов - изрядно более обычного. В расшифровке видно, что и количество исполнений одного экземпляра - огромное. Миллионы вставок.

Постфактум посмотрел более короткий период - полчаса максимальной загрузки сервера по CPU, с 16:10 по 16:40 - тут еще более наглядно:


Попробую поймать контексты исполнения данного запроса
Несколько (15 штук) уже попались, это  

 ----------- вес контекста 15.00 ---------  
  ОбщийМодуль.Фоновые.Модуль : 2658 : Результат = Документы.ПулЗаказов.СозданиеЗаказовРозн(Параметры);
      Документ.ПулЗаказов.МодульМенеджера : 939 : Док.ЗаполнитьЗаказДанными();
          Документ.ЗаказТочки.МодульОбъекта : 3898 : Запрос = ПолучитьПолныйЗапрос(Открытие,ДляОтчета,Пересчет,СтруктураПараметров);
              Документ.ЗаказТочки.МодульОбъекта : 3437 : ТаблНастр =   Справочники.НастройкиЗаказаТочки.Определить...
                  Справочник.НастройкиЗаказаТочки.МодульМенеджера : 471 : ПолучитьСервисныеВременныеТаблицы(...);
                      Справочник.НастройкиЗаказаТочки.МодульМенеджера : 309 : Запрос.Выполнить();

для   INSERT INTO #ttXX (VAL) VALUES(@P1)
На фоне сотен запусков этого как-то маловато, да и контекст для  INSERT INTO #ttXX (VAL,VAL) VALUES(@P1,@P2) не определен.

Настраиваю техжурнал на серверах кластера, дополняя его вот такой конструкцией:
    <log history="1" location="Z:\Server1C\logsInsTMP">
      <event>
       <eq property="name" value="dbmssql"/>
       <like property="Sql" value="%INSERT INTO #tt%(%)%VALUES(%"/>
      </event>
      <property name="all"/>
    </log>
Жду.
Директории Z:\Server1C\logsInsTMP за 20 минут вырастают до 2 и 1,5Gb (два сервера к кластере).
Убираю настройку, смотрю содержимое части logsInsTMP (по UID rphost-ов отобрал пяток объемистых директорий) - группировка по контексту с выводом количества событий.

Картинка вот такая: 

7 729                     
INSERT INTO #ttNN (VAL,VAL) VALUES(?,?)
ОбщийМодуль.Фоновые.Модуль : 2658 : Результат = Документы.ПулЗаказов.СозданиеЗаказовРозн(Параметры);
    Документ.ПулЗаказов.МодульМенеджера : 939 : Док.ЗаполнитьЗаказДанными();
        Документ.ЗаказТочки.МодульОбъекта : 3898 : Запрос = ПолучитьПолныйЗапрос(Открытие,ДляОтчета,Пересчет,СтруктураПараметров);
            Документ.ЗаказТочки.МодульОбъекта : 3437 : ТаблНастр = Справочники.НастройкиЗаказаТочки.Определить...
                Справочник.НастройкиЗаказаТочки.МодульМенеджера : 470 : ПроверкаОграниченияТовары = Рез...
                    Справочник.НастройкиЗаказаТочки.МодульМенеджера : 269 : Возврат ПолучитьРезультатЗапрета(...);
                        Справочник.НастройкиЗаказаТочки.МодульМенеджера : 244 : Возврат Запрос.Выполнить().Выгрузить();
7 479
INSERT INTO #ttNN (VAL,VAL,VAL) VALUES(?,?,?)
ОбщийМодуль.Фоновые.Модуль : 2658 : Результат = Документы.ПулЗаказов.СозданиеЗаказовРозн(Параметры);
    Документ.ПулЗаказов.МодульМенеджера : 939 : Док.ЗаполнитьЗаказДанными();
        Документ.ЗаказТочки.МодульОбъекта : 3817 : Результат = Запрос.Выполнить();                                                                                              
4 839
INSERT INTO #ttNN (VAL,VAL) VALUES(?,?)
ОбщийМодуль.Фоновые.Модуль : 2658 : Результат = Документы.ПулЗаказов.СозданиеЗаказовРозн(Параметры);
    Документ.ПулЗаказов.МодульМенеджера : 939 : Док.ЗаполнитьЗаказДанными();
        Документ.ЗаказТочки.МодульОбъекта : 3898 : Запрос = ПолучитьПолныйЗапрос(Открытие,ДляОтчета,Пересчет,СтруктураПараметров);
            Документ.ЗаказТочки.МодульОбъекта : 3634 : ТаблЗап = Справочники.РазрешенияНаЗаказТовараВТочках.Определить...
                Справочник.РазрешенияНаЗаказТовараВТочках.МодульМенеджера : 315 : ПроверкаОграничения = ПолучитьРезультатЗапрета(...);
                    Справочник.РазрешенияНаЗаказТовараВТочках.МодульМенеджера : 239 : Возврат Запрос.Выполнить().Выгрузить();
566
INSERT INTO #ttNN (VAL) VALUES(?)
ОбщийМодуль.Фоновые.Модуль : 2658 : Результат = Документы.ПулЗаказов.СозданиеЗаказовРозн(Параметры);
    Документ.ПулЗаказов.МодульМенеджера : 1037 : Док.ЗаполнитьНачальныеНастройки_Модуль(Доформирование);
        Документ.ЗаказТочки.МодульОбъекта : 4482 : ТЗ = Справочники.НастройкиЗаказаТочки.ЗаполнитьНачальныеНастройкиЗак(...);
            Справочник.НастройкиЗаказаТочки.МодульМенеджера : 717 : ПроверкаОграничения = ПолучитьРезультатЗапрета(...);
                Справочник.НастройкиЗаказаТочки.МодульМенеджера : 244 : Возврат Запрос.Выполнить().Выгрузить();

 

Иду к ведущему, разбираемся..
Ну вот, ситуация примерно ясна.
Крутится она вокруг двух справочников, НастройкиЗаказаТочки и РазрешенияНаЗаказТовараВТочках.
Справочники - для удобства - содержат не сами ссылки на точку, а ее параметр. И не сами товары - а их свойства.
Например, что-то вроде  "точка вышей категории" / "дней запаса для товаров Типа А" / "100".
Ну, точки гуляют меж категориями, товары меняют характеристики, а тут один раз задал - и не паришься.
Удобно.
Но перед использованием все это счастье разворачивается в плоские таблицы.
Вместо 
   "точка высшей категории" / "дней запаса для товаров Типа А" / "100" 
будет несколько тысяч записей вида 
   "магазин 135" / "товар1" / "100" 
   "магазин 135" / "товар2" / "100" 
и т. д.
Сделано это все.. сюрприз - через таблицы значений.
В ф-ю менеджера справочника кидаем списки точек и прочих параметров, они попадают в запрос при помощи конструкций Запрос.УстановитьПараметр("Таблица1",Таблица1); / первая порция Insert/, далее получаем результат, который заливаем в таблицу значений на стороне сервера 1С (Возврат Запрос.Выполнить().Выгрузить();), таблицу возвращаем в формирующий документ, далее ее - правильно - опять посылаем на сторону sql-сервера (Запрос.УстановитьПараметр("Настройки", ТаблНастр);) /вторая порция Insert/.

Таблицы немаленькие (обрабатываем за итерацию ~100 точек  * 5000 товаров * 10 параметров), строк миллионы - и все это медленно и печально гуляет туда-сюда.
И, как ни странно, жрет CPU. 

Переделать это все как-то кардинально "не представляется возможным по техническим причинам" ("Ну ты ж понимаешь, это не единственный косяк, и если все перебрать "как надо", то переделок тут на тучу часов, ну где их взять?").
Договорились просто - не будем выгружать в таблицы значений, будем параметром передавать объект Запрос с менеджером временных таблиц, да создавать в нем еще одну времянку. 

Вот, делают.. жду.. сервер временами виснет..

 

 

 

Пару дней назад прочитал комментарий Андрей Sh. (ansh15) от 25.02.18 11:09, и полез проверять.

Если и изменилось что - то на пару процентов.

 

Подкараулил момент формирования - один в один та же картинка:

 

Фиолетовые пики - это, кстати, Processor Queue Length (Количество процессов, отмеченных как «отложенные» в очереди готовности процессора и ожидающих назначения на выполнение.) Вне формирования заказов оно чаще нулевое.

Проделываю ту же процедуру с <like property="Sql" value="%INSERT INTO #tt%(%)%VALUES(%"/>

Результат тот же, за вычетом контекста с упоминанием  Справочник.РазрешенияНаЗаказТовараВТочках (ну и номера строк в некоторых местах немного поменялись - видно, что код правили).

Задача числится исполненной в начале февраля, с вердиктом "поправил проблемное место".

Ведущий : "разработчик занимался, я не в курсе".

Исполнитель : "ну я по-быстрому поправил самое тяжелое, по моему мнению".

В задаче, говорю, было несколько контекстов - "ну остальное же мелочь".

Экономят время, да.

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

Поставил еще одну задачу, в конце добавил "оттрассировать процесс формирования заказа в тестовой после правок, трассу предоставить".

Продолжение, видимо, следует..

 

 

Дополнение 23.04.2018.

В итоге починили. Пока чинили - испортили новым функционалом (тяжелый запрос не вписали в индекс), но и это тоже победили.

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

Финал вышел неплохим

Вот момент формирования заказов

А вот обычная, вне формирования заказов, загрузка сервера по CPU

Т.е. загрузку удалось снизить со средней 75-80% (прыжки до 90-100%) до средней 40-45% (прыжки до 90%).

Причем пикизагрузки теперь более короткие (<3 мин на 80-90%), чем ранее.

И бонусом: формирование пула заказов укладывается в 8-10 мин (против 30-40 мин ранее).

Это все на том же сервере, с примерно той же загрузкой, и только правкой кода.

 

Стоит ли улучшать далее?

На настоящий момент в топе по CPU нет ярко выраженного лидера, первый десяток занимают запросы по 4%-3%-2%.. Наверное, при тех же усилиях толку будет на порядки меньше. Да и статистики пока маловато. Пока затаюсь на месяц, а там посмотрим.. Ответ "скорее нет, чем да - следует подождать новых чудесных механизмов от отдела разработки.. или поломок старых механизмов."

 

И таки полностью убрать "INSERT INTO #ttXX.." не удалось.. остались куски запросов к статистическим базам на чистом t-sql + вставки результатов выполнения в запросы 1С через таблицы значений.. тут разве что только переписывать всю логику на хранимые процедуры t-sql, что чревато большими затратами.