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

Вечер пятницы, ничто не предвещало..
Звонок из техподдержки: «центральная база розничной сети лежит».
Далее расследование причин.

ЦБ розницы тут ласково называют "планета Шелезяка". Потому что "населена роботами". В нее стекаются данные от кучи розничных точек (уж далеко за две тысячи), живут в ней пять десятков "роботов" (фоновых заданий) двух типов — "выгрузка" да "загрузка", кидают туда-сюда гигабайты данных. Наиболее частая проблема — кто-то нажал "не туда" (а иной раз — сознательно "именно туда"), в план обмена зарегистрировалось "полмира" — и поехало оно выгружаться, с коллапсом серверов 1С (оно не только файлы кидает, оно их еще и архивирует — экономия трафика однако). 
Иду на сервера кластера 1С — тихо.. нет признаков массовой выгрузки или загрузки. Что-то другое.

Смотрю счетчики sql-сервера — ага, вот оно:

Загрузка по CPU близка к 100% — это при среднесуточном значении в 50%.
Все 32 logical processors — под завязку.

Смотрим на sql-сервере запросы, потребляющие CPU,
вот так:

 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

и еще с помощью sp_WhoIsActive:

  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:Server1ClogsInsTMP">
      <event>
       <eq property="name" value="dbmssql"/>
       <like property="Sql" value="%INSERT INTO #tt%(%)%VALUES(%"/>
      </event>
      <property name="all"/>
    </log>

Жду.
Директории Z:Server1ClogsInsTMP за 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. 

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

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

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

Пару дней назад прочитал комментарий Андрей Sh. (ansh15) от 25.02.18 11:09, и полез проверять.
Если и изменилось что — то на пару процентов.
 
Подкараулил момент формирования — один в один та же картинка:
 
Фиолетовые пики — это, кстати, Processor Queue Length (Количество процессов, отмеченных как «отложенные» в очереди готовности процессора и ожидающих назначения на выполнение.) Вне формирования заказов оно чаще нулевое.
Проделываю ту же процедуру с <like property="Sql" value="%INSERT INTO #tt%(%)%VALUES(%"/>
Результат тот же, за вычетом контекста с упоминанием  Справочник.РазрешенияНаЗаказТовараВТочках (ну и номера строк в некоторых местах немного поменялись — видно, что код правили).
Задача числится исполненной в начале февраля, с вердиктом "поправил проблемное место".
Ведущий : "разработчик занимался, я не в курсе".
Исполнитель : "ну я по-быстрому поправил самое тяжелое, по моему мнению".
В задаче, говорю, было несколько контекстов — "ну остальное же мелочь".
Экономят время, да.
И я на слово верю, а регламент выявил бы ситуацию только в апреле, и роботы — железные товарищи — не жалуются, и редкие живые пользователи видать привыкли.
Поставил еще одну задачу, в конце добавил "оттрассировать процесс формирования заказа в тестовой после правок, трассу предоставить".
Продолжение, видимо, следует..
 
 
Дополнение 23.04.2024.
В итоге починили. Пока чинили — испортили новым функционалом (тяжелый запрос не вписали в индекс), но и это тоже победили.
В процессе, между делом, убрали еще два грузящих 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, что чревато большими затратами.
 

31 Comments

  1. PerlAmutor

    Вашему руководству повезло, что Вы у них есть.

    Наш администратор серверов 1С единственное что делает так это перезагружает сервер, делает бэкапы, восстанавливает бэкапы. Прямой доступ программистам 1С к серверу не дает и сам никуда лезть не хочет разбираться. У него одна отмазка — «вы программисты там чего-то понаписали, что всех подвесили, вот сами и исправляйте.». Это конечно правда, но иногда вешают сервак типовые механизмы, а бывает что и работа других программистов в команде, которые молча себе что-то там делают, а потом сами же и спрашивают друг друга «а чего мы висим?». Так вот обычному программисту 1С крайне неудобно искать какие именно запросы подвешивают все. Приходится проводить целые расследования — определять сеансы, по номеру сеанса искать в журнале регистрации записи о том кто чего запустил, а если записей нет и сеанс — пользовательский, то заходить под ним на время подменяя пароль, а затем лезть в его историю пользователя, чтобы выяснить куда он лазил в последнее время…

    Reply
  2. Gilev.Vyacheslav

    (0) Я надеюсь первым шагом Вы tempdb на рам-диск положили?

    Reply
  3. spezc

    Автор крут. Уверен, если он в Москве, то с ЗП явно больше 200т.р. Если меньше, значит вас не ценят)))

    Reply
  4. PerlAmutor

    (2) Я не ошибусь если скажу, что в MSSQL 2014 эта проблема ушла и такой необходимости больше нет? https://blogs.msdn.microsoft.com/psssql/2014/04/09/sql-server-2014-tempdb-hidden-performance-gem/

    Reply
  5. DenisCh

    Руки оборвать писателям…

    Reply
  6. Armando

    (0) Если у вас все так серьёзно, то стоит подумать о нагрузочном тестировании доработок перед внедрением в продуктив.

    Reply
  7. ansh15
    Загрузка по CPU близка к 100% — это при среднесуточном значении в 50%.

    Все 32 logical processors — под завязку.

    Эти новые фоновые CPU на sql-сервере скушали, и памяти на серверах кластера 1С нахватали от души.

    (0) Попросите выделить больше процессоров и памяти, судя по фразе «32 логических процессора», у вас виртуальная среда.

    Reply
  8. kolya_tlt

    (6)

    то стоит подумать о нагрузочном тестировании доработок перед внедрением в продуктив.

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

    ну и камень в огород программистам, которые не подумали о том какие и самое главное сколько данных будут в регистрах и как это повлият на обмен. не удивлюсь если тупо стоит авторегистрация у регистра

    Reply
  9. a.kapustin

    Интересный инструмент используете для поиска долгих запросов.

    Попробуйте сервис Гилева http://www.gilev.ru/querytj/

    Его полюс в том, что сразу видно ТОР 10 долгих запросов, которые требуют оптимизации.

    Reply
  10. fhqhelp

    (1) Десяток лет назад я был «обычным программистом 1С». Не знал про блокировки, ни разу не видел планов исполнения, смутно представлял себе индексы, совсем не понимал слова «статистика». Кинули на блок, который безбожно вис. Пришлось «проводить расследования», да.. Научился чему-то, более в области MS SQL Server, менее в области кластеров 1С. Ну просто выхода не было, должен же кто-то.

    Reply
  11. fhqhelp

    (2) На данном конкретном сервере — нет.

    256 Gb оперативки, практически все отдана под MS SQL, page life expectancy болтается в районе 2000 сек, с резкими и частыми падениями до нуля — ему явно имеющихся гигабайт не хватает.

    Под эксперименты с tempDB не отрезать.

    Да и размер tempDB под 300 Gb (обрезать — так за день вырастет).

    На сервере, кроме ЦБ розницы, еще и кучка статистических баз на чистом sql без примеси 1С — там сканы/сорты ого-го.

    А так, tempDB лежит на массиве из SSD и «среднюю задержку операции чтения» кажет ~2 мс (по sys.dm_io_virtual_file_stats) — вроде неплохо.

    В общем, я б поэкспериментировал — да кто ж мне даст оперативки?..

    Reply
  12. fhqhelp

    (5) Ха. Тогда придется начать с себя. Гляжу на свой код образца 2005 года — хочется харакири сделать 🙂 И он до сих пор работает, кстати.

    Вообще обучать надо людей, тщательно и планомерно, но как правило «нам некогда пилу точить — пилить надо».

    Reply
  13. fhqhelp

    (3) У нас тут провинция.. 200 и в дирекции-то нет..

    Вообще московские зарплаты вызывают оторопь, а цены на московские квартиры — полный ступор и потерю ориентации в пространстве.

    Как другая планета, правда..

    Reply
  14. fhqhelp

    (6) Да, нагрузочное пытаемся сделать, но не во всех продуктах пока внедрено.

    Все упирается в написание толковых сценариев — это ж время..

    Reply
  15. fhqhelp

    (7) Нет, физическая железка. Новую поставить не выйдет, приказано выжимать досуха что есть.

    Reply
  16. ifilll

    (12) Весьма верно, времени нету, суррогаты плодим ))

    А с кодом этом всегда так, меня код и годичной давности в ступор вводит.

    Reply
  17. fhqhelp

    (9) >> Попробуйте сервис Гилева…

    Ну так я примерно то же самое (взгляд более со стороны sql-сервера — те же самые TOP 10), самописное — и рекламирую.

    https://infostart.ru/public/712722/

    Сервисы с http://www.gilev.ru — как появились — пытался поставить.

    Руководство отказало, «низя стороннее ПО», у нас тут «защита конфиденциальной информации» иной раз принимает формы маразма.

    Поставили ЦУП — но он не подходит для круглосуточного мониторинга.

    Итог — пришлось изобретать свой велосипед.

    Что, кстати, весьма полезный опыт.

    Reply
  18. firma111

    Имхо, не так сложно найти причину проблемы, когда имеет место быть какая-то одна обработка или документ или еще что-то. Гораздо сложнее, когда нагрузка создается разными объектами понемногу, когда на сервере не наблюдается каких-то явных всплесков нагрузки, и тем не менее «все тормозит». Особенно когда все это крутится на виртуалках. Но все равно статья интересная, спасибо.

    Reply
  19. Maxisussr

    (0)

    Огромный плюс автору за статью, редкий случай применения знаний 1С:Эксперта, не высосанный из пальца!

    Reply
  20. Дмитрий74Чел

    (3) Просто откройте в Гугле «Заволжск» и посмотрите на картинку справа…

    Reply
  21. Дмитрий74Чел

    Почувствовал что на сайте остро не хватает функции «подписаться на новые статьи автора».

    Reply
  22. Evil Beaver

    (13) в квартирах вся загвоздка. Допустим, я специалист не из Москвы и хочу работать в конторе Х. Чтобы к ним переехать, мне нужно +45к только на аренду жилья, транспорт и разницу в ценах на жизнь. И это только чтобы выйти в ноль. А я же хочу и еще прибавить в доходе, верно? Поэтому зарплаты такие, да, но почти половину съедают накладные расходы.

    Reply
  23. w.r.

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

    Reply
  24. ansh15

    Удалось ли автору публикации решить обозначенные в статье проблемы(загрузка CPU и памяти до 100%, подвисания сервера и, как следствие, сильная затрудненность или невозможность работы)? Может быть, были приняты решения о приобретении нового, более производительного, серверного оборудования(модернизация имеющегося) или найдено доп. финансирование на человеко-часы для кардинальной оптимизации ПО(по хорошему и то и другое)?

    Reply
  25. Brawler

    (21) или может слева?

    Reply
  26. Brawler

    Видимо у меня скилы на неком хорошем уровне ибо при виде

    INSERT INTO #ttNN (VAL,VAL) VALUES(@P1,@P2)

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

    Тут бы ладно на уровне SQL только такая белеберда происходила, но оно же и на уровне внутреннего SDBL языка платформы происходит. Сначала таблица значений перегоняется в SDBL, потом SDBL в SQL той СУБД на которой пашет база.

    Тут да, выход только один, не гонять таблицы значений с большим массивом данных в качестве параметров запросов, а нужно стараться по максимуму все просчитывать во временных таблицах в самом запросе. Не спроста типовые конфы становятся супер сложными, возьмите ту же ЗУП 3.Х, запросы пестрят временными таблицами, один объект запроса используется по туче раз, и в него докидываются всё новые и новые тексты запросов, добавляющие временные таблицы, и вся эта кухня что-то даже высчитывает в конце. В промежутках еще могут делаться расчеты на встроенном языке 1С.

    Reply
  27. Armando

    С INSЕRТ INТО еще есть подстава, это запросы вида «ВЫБРАТЬ Ссылка Из Справочник.Пользователи ГДЕ Справочник.Реквизит в (&Значения)». Казалось бы с виду все норм, обычный запрос. НО, если в массиве &Значения будет больше 256 элементов, то платформа начинает генерить временную таблицу для использования в запросе. И делает это на каждые 256 элементов. Т.е. если передать 2560 элементов, то получим 10 запросов INSЕRТ INТО по 256 строк.

    Reply
  28. Maxisussr

    (3)

    Такое знание редко, где нужно, поэтому «продать» такие знания — очень трудно, так что о зарплатах в разы больше 200 т.р. говорить не приходится)))

    Reply
  29. Terve!R

    (1) вашего неадекватного администратора серверов давно пора или уволить или морду набить.

    Reply
  30. sokir

    (2) Посоветайте РАМ диск.

    Уже ставил 2 программы, но на них темпдб не становится — скуль пишит что нет места — короче не понимает что оно есть — получается какая то не полная эмуляция диска.

    Reply
  31. Gilev.Vyacheslav

    (31) http://www.gilev.ru/ram-disk/ список программ

    Reply

Leave a Comment

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