Расследование ошибки "TCP Provider: An existing connection was forcibly closed by the remote host" и неожиданные результаты

29.10.24

База данных - HighLoad оптимизация

Неожиданные результаты расследования ошибки "TCP Provider: An existing connection was forcibly closed by the remote host".

В статье речь пойдет о моем расследовании ошибки "TCP Provider: An existing connection was forcibly closed by the remote host" и неожиданных находках в процессе исследования.

Техническая информация:

  • Сервер базы данных: MSSQL
  • Версии платформ: 8.3.23.2236, 8.3.24.1691 (в процессе исследования обновили версию платформы)
  • Конфигурация: ERP 2.5.12.270

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

Попытался понять, что происходит в консоли администрирования, но она не отвечала.

Кое-как перезапустил толстый клиент и посмотрел в Журнал регистрации - он весь был полон ошибками как на изображении:

 

 

Подключился к SQL серверу через SMSS и обнаружил какие-то странные ошибки в логах, множество событий kill и что-то связанное с некорректным содержимым потока (stream).

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

С трудом зашел по RDP на сервер кластера 1С и обнаружил 100% загрузку процессора. Памяти вроде как хватает, а все рабочие процессы активно потребляют ядра. Принял решение перезагрузить сервер.

На следующий день ситуация повторилась... Снова перезагрузил сервер. Начал искать в интернете информацию об этих ошибках. Чего только там нет, поставил SQLTRACE для отслеживания проблем соединений, какие-то настройки версии TLS. Не помогло - на третий день ситуация повторилась.

Стал внимательнее изучать поведение рабочих процессов. Вижу, что запускаются новые. Почему непонятно, ведь занято 100Гб, а Maximum доступных показывает 200Гб. Обратил внимание, что в процентах показывает, что занято 82% оперативной памяти. Вспомнил про настройки кластера и то, что при достижении порога занятой оперативной памяти в 80% рабочие процессы перезапускаются.

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

Решил для начала разобраться, почему сервер показывает что занято 82% ОЗУ от 100Гб, а максимум доступных - 200. Ведь должно показывать 50%...

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

Но 1С по какой-то причине не умеет этого определять!

Пришлось выставить значение "-1" в настройках кластера рабочего сервера.

Нормальной работы пользователей уже начало хватать на 2 дня, память динамически расширялась и среднее потребление было где-то на уровне 86% без перезапуска рабочих процессов. Для начала неплохо.

Дальше стал искать причины такого быстрого расхода памяти, которого раньше не наблюдалось.

Настроил счетчики памяти на сервере. Оставил на день, поймал несколько сильных "всплесков" без освобождения. Рабочий процесс занимал 4Гб ОЗУ, а потом за 2 минуты расход +10Гб.

Настроил такой ТЖ:

 

<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
	<log history="48" location="F:\LOG\MEM">
		<property name="all"/>
		<event>
			<eq property="name" value="mem"/>
		</event>
		<event>
			<eq property="name" value="CALL"/>
			<gt property="memorypeak" value="100000000"/>
		</event>
		<event>
			<eq property="name" value="CALL"/>
			<gt property="memory" value="100000000"/>
		</event>
	</log>
	<mem/>
	<property name="all"/>
	<dump create="false" type="3" prntscrn="false" location="F:\LOG\DUMPS"/>
	<defaultlog location="F:\LOG\SYSTEM"/>
</config>

 

Значение 100000000 (100Мб) подобрал эмпирическим путем ориентируясь на то, что всплески расхода памяти были значительными. Включил ТЖ и стал посматривать за счетчиками потребления памяти, чтобы отключить ТЖ в нужный момент и не сильно мешать работе пользователей.

Удалось поймать несколько подобных записей:

 

31:39.157012-78001975,CALL,1,process=rphost,p:processName=db1,OSThread=3608,t:clientID=49356,t:applicationName=1CV8C,t:computerName=Comp1,t:connectID=47583,callWait=0,first=0,Usr=Пользователь1,SessionID=115331,Context=Форма.Вызов : ВнешнийОтчет.Отчет1.Форма.Модуль.ЗагрузитьРезультатФормированияОтчета,Interface=bc15bd01-10bf-413c-a856-ddc907fcd123,IName=IVResourceRemoteConnection,Method=0,CallID=7493,MName=send,Memory=17474943872,MemoryPeak=17488718712,InBytes=36820,OutBytes=0,CpuTime=74125000

 

Memory - 17474943872 (16Гб)

MemoryPeak - 17488718712 (16Гб)

Мне подсказали, что значение Memory/MemoryPeak могут не относиться к вызову (CALL), а просто фиксировать значение расхода памяти рабочим процессом на момент события.

Все равно ничего больше не остается как проверять каждого, к счастью таких набралось 3-4 пользователя. Поэтому открыл ЖР и нашел отчет, который формировал пользователь в тот момент времени. Настроил такой же ТЖ на тестовом контуре. Зашел под пользователем в копию рабочей базы и, не меняя настроек его отчета, нажал "Сформировать". ТЖ на тестовом контуре показал сопоставимый расход памяти в событии CALL. А расход памяти рабочим процессом точно так же скаканул резко вверх.

И вроде бы на этом можно было бы и закончить. Ну формируют пользователи отчеты без отборов, потом сидят и прокручивают миллионы строк, пытаясь попасть в ползунок скроллбара. Мы и так с самого начала догадывались, что дело в отчетах - скажете вы.

Только вот отчет выполнился быстро и ... ничего не показал, вообще...

Так откуда расход памяти может быть, если данные с SQL сервера не вернулись?

Задал я себе этот вопрос и полез в настройки отчета, чтобы убедиться, что там не стоят какие-нибудь фильтры, которые отбрасывают данные уже после получения данных. И их там не было.

Я подумал, что возможно отчет сначала заполняет какую-нибудь Таблицу Значений, а потом подставляет её в СКД как НаборДанных. Но тоже мимо...

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

Для этого я воспользовался утилитой VMMap. Подключился и открыл Strings в поисках чего-нибудь интересного и повторяющегося. Там я обнаружил странную последовательность строк (около 300к):

 

 

(DATETIME(2024,9,1,0,0,0),DATETIME(2024,9,1,0,0,0),UNDEFINED,261:AD4F02008100001811EDB1CE602AFEAD,86:ACFE02008100001811E9B45E7BE...
(DATETIME(2024,9,1,0,0,0),DATETIME(2024,9,1,0,0,0),UNDEFINED,261:AD4D02008100001811EDA3ECF2174552,86:ACFE02008100001811E9B4569BD...

 

Похоже на строки SDBL запроса... Несколько ссылок расшифровал - ведут на реальные объекты. Но что это?

Решил запустить отчет под отладчиком и передать Макет Компоновки в консоль запросов через "Инструменты Разработчика".

Выполнил запрос отчета, и он все также ничего в результаты не выводил. Сначала у меня была мысль, что механизмы СКД делают отдельный запрос к БД, которые невозможно отладить, разве что через SQL Профайлер (или XEvents) ловить. И я почти начал уже двигаться в этом направлении в своем расследовании, но взгляд упал на список временных таблицу, в одной из которых красовалось количество записей равное 1,6 миллионам строк. Временная таблица называлась "ОстаткиИДвижения".

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

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

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

 

А в проблемном уже так:

 

Т.е. после параметра построителя (Партия).* отсутствует кусок:

 



ЗНАЧЕНИЕ(Перечисление.ХозяйственныеОперации.ПустаяСсылка) КАК ХозяйственнаяОперация,

ЗНАЧЕНИЕ(ПланВидовХарактеристик.СтатьиДоходов.ПустаяСсылка) КАК СтатьяДоходов,

ЗНАЧЕНИЕ(ПланВидовХарактеристик.СтатьиРасходов.ПустаяСсылка) КАК СтатьяРасходов,

НЕОПРЕДЕЛЕНО КАК СтатьяДоходовРасходов,

НЕОПРЕДЕЛЕНО КАК АналитикаДоходов,

НЕОПРЕДЕЛЕНО КАК АналитикаРасходов,

НЕОПРЕДЕЛЕНО КАК АналитикаДоходовРасходов,

НЕОПРЕДЕЛЕНО КАК Договор,

ЗНАЧЕНИЕ(Документ.ЗаказКлиента.ПустаяСсылка) КАК Заказ,

ЗНАЧЕНИЕ(Справочник.Партнеры.ПустаяСсылка) КАК Партнер,

ЗНАЧЕНИЕ(Справочник.Контрагенты.ПустаяСсылка) КАК Контрагент,

ЗНАЧЕНИЕ(Справочник.СоглашенияСКлиентами.ПустаяСсылка) КАК Соглашение,

ЗНАЧЕНИЕ(Перечисление.ТипыЗапасов.ПустаяСсылка) КАК ТипЗапасов,

ЗНАЧЕНИЕ(Справочник.НастройкиХозяйственныхОпераций.ПустаяСсылка) КАК ХозяйственнаяОперацияСправочник,

ЗНАЧЕНИЕ(Перечисление.ХозяйственныеОперации.ПустаяСсылка) КАК ХозяйственнаяОперацияПрихода,

ЗНАЧЕНИЕ(Перечисление.ХозяйственныеОперации.ПустаяСсылка) КАК ХозяйственнаяОперацияРасхода
 

 

Посмотрев на то, какой отбор в отчете стоит у пользователя, стало понятно, что отбирает он по АналитикаРасходов и Периоду. У регистра СебестоимостьТоваров АналитикаРасходов это не измерение, а реквизит, остатка по нему не получить. А так как отбора нет, то во временную таблицу возвращаются все возможные остатки за период... Как я писал выше, у нас это около 1,6 млн. строк остатков.

Если добавить отсутствующие отборы построителя в проблемный участок, то СКД преобразует условие запроса к виртуальной таблице таким образом:

 

РегистрНакопления.СебестоимостьТоваров.ОстаткиИОбороты(&НачалоПериода {(&НачалоПериода)}, &КонецПериода {(&КонецПериода)}, Авто, , НЕОПРЕДЕЛЕНО = &АналитикаРасходов)

 

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

Но этим отчетом уже пользуются годами, и должно было быть что-то еще. Если возвращаться к результатам ТЖ, где я сказал, что подозрительных пользователей было несколько, то там я поймал еще пользователя, формирующего мой недавно написанный отчет. Как ни странно, там тоже используется таблица ОстаткиИОбороты, и тоже пользователь решил сформировать его за все века. Он точно так же съел кучу памяти рабочего процесса (честно говоря, это вообще был первый подозреваемый, которого я  обнаружил в ТЖ, и после некоторых доработок отчета проблема должна была уйти, но т.к. это не сильно помогло, то я перешел ко второму...).

Вероятно, кто-то уже догадался, что проблемный отчет - типовой, из ERP. Это один из самых популярных отчетов у пользователей - "СебестоимостьТоваров". Проблема сохраняется с ERP 2.5.12.270 и до 2.5.17.143. Скорее всего, и в ранних версиях тоже. Возможно, и в актуальных.

 

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

TCP Provider Платформа 1С Разрыв

См. также

Сервера Системный администратор Бесплатно (free)

На первый взгляд, добавление второго сервера в кластер 1С не должно вызывать проблем – все просто должно работать. Но на практике дело обстоит иначе. Несмотря на то, что все действительно работает, многие при этом сталкиваются с трудностями. Расскажем, когда нужно задуматься о втором сервере 1С в кластере, какие особенности работы второго сервиса с файлами и сервисами, и какие настройки ТНФ можно сделать для лицензий ПРОФ и КОРП.

31.10.2024    6917    a.doroshkevich    20    

60

HighLoad оптимизация Программист Платформа 1С v8.3 Конфигурации 1cv8 Бесплатно (free)

Анализ простого плана запроса. Оптимизация нагрузки на ЦП сервера СУБД используя типовые индексы.

13.03.2024    5051    spyke    28    

49

HighLoad оптимизация Инструменты администратора БД Системный администратор Программист Платформа 1С v8.3 Конфигурации 1cv8 Абонемент ($m)

Обработка для простого и удобного анализа настроек, нагрузки и проблем с SQL сервером с упором на использование оного для 1С. Анализ текущих запросов на sql, ожиданий, конвертация запроса в 1С и рекомендации, где может тормозить.

2 стартмани

15.02.2024    12274    236    ZAOSTG    80    

115

HighLoad оптимизация Программист Платформа 1С v8.3 Конфигурации 1cv8 Абонемент ($m)

Встал вопрос: как быстро удалить строки из ТЗ? Рассмотрел пять вариантов реализации этой задачи. Сравнил их друг с другом на разных объёмах данных с разным процентом удаляемых строк. Также сравнил с выгрузкой с отбором по структуре.

09.01.2024    13564    doom2good    49    

71

HighLoad оптимизация Системный администратор Программист Бесплатно (free)

При переводе типовой конфигурации 1C ERP/УТ/КА на PostgreSQL придется вложить ресурсы в доработку и оптимизацию запросов. Расскажем, на что обратить внимание при потерях производительности и какие инструменты/подходы помогут расследовать проблемы после перехода.

20.11.2023    13337    ivanov660    6    

80

HighLoad оптимизация Бесплатно (free)

Казалось бы, КОРП-системы должны быть устойчивы, быстры и надёжны. Но, работая в рамках РКЛ, мы видим немного другую картину. Об основных болевых точках КОРП-систем и подходах к их решению пойдет речь в статье.

15.11.2023    7060    a.doroshkevich    22    

74
Оставьте свое сообщение