Расследование ошибки "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. Скорее всего, и в ранних версиях тоже. Возможно, и в актуальных.

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