Реальные кейсы утечек памяти в 1С из-за полнотекстового поиска данных и внешней компоненты

Авторы

Избыточное потребление памяти процессом rmngr при поиске с использованием ППД в 1С
Потребление всей памяти сервера процессами rphost из-за внешней компоненты печати штрихкодов
Неочевидные причины падения производительности 1С

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

Избыточное потребление памяти процессом rmngr при поиске с использованием ППД в 1С

Проявление у пользователей

Предприятие ведет учет в системе «Альфа-Авто». Кластер серверов 1С:Предприятия состоит из 1 рабочего сервера, регламентные операции на БД (обновление статистики, реиндексация) выполняются раз в сутки в течение двухчасового технологического окна.

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

Инфраструктура исследуемой системы

Операционная система Windows Server 2012.
База данных Microsoft SQL Server 2016 SP2 64х SE.
Версия сервера 1C: 8.3.16.1148.
Виртуализация с 180 Гб выделенной оперативной памяти и 40 ядер CPU 3 ГГц на сервере 1С.
275 Гб и 24 ядра CPU 3 ГГц на сервере БД.
1200+ работающих пользователей.

Расследование

Первоначально появилась гипотеза, что рабочие процессы перезапускаются или аварийно завершаются. Настроили сбор событий ATTN, EXCP, PROC в logcfg.xml:


<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
    <log history="72" location="e:\logs">
        <property name="all"/>
        <event>
            <eq property="name" value="ATTN"/>
        </event>
        <event>
            <eq property="name" value="EXCP"/>
        </event>
        <event>
            <eq property="name" value="PROC"/>
        </event>
    </log>
</config>

По событиям ATTN фиксируем скачок памяти на процессе rmngr, приблизительно совпадающим со временем зависания системы:

12:25:22.355000-0,ATTN,1,process=ragent,OSThread=9440,Descr=Critical memory limit exceeded for server,ServerID=28796356-b742-4a4d-9b78-9ed1524a8687,HostName=***,TotalMemory(Kb)=150994420,CriticalProcessesMemory(Kb)=0 (95% of TotalMemory),ExcessStartTime=20210326184717,ExcessDuration(sec)=5,ProcessList[pid, mem(Kb)]='[3604, 51094152], [23676, 12854720], [15128, 10667756], [17992, 10639276], [10052, 10469188], [8280, 10117472], [15588, 10058112], [21924, 9962948], [24872, 9315156], [20388, 8696892]'

При достижении критического объема памяти, занятого процессами 1С, происходит незамедлительное завершение самого большого по памяти процесса rphost. Подробнее про это можно прочитать в статье.

В этой же статье можно прочитать, как настроить сбор счетчиков производительности, чтобы получить графики потребления памяти каждым процессом rmngr и rphost, только обязательно в реестре задаем ProcessNameFormat = 2 в ветке HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\PerfProc\Performance, для того, чтобы сопоставить графики с PID процессов из события ATTN.

Кстати, в perfmon есть много различных счетчиков потребления памяти процессами ОС, опытным путем мы определили, что именно счетчик «байт виртуальной памяти» показывает те же значения, что и фиксируются в событии ATTN.

Кратковременный скачок на процессе rmngr

Изучив график и сопоставив PID процесса из события ATTN и PID процесса на графике, выяснили, что скачок происходил на процессе rmngr и понимаем, что скачок был кратковременный (в данном примере около 18 сек), после память процесса возвращается к исходному значению, хотя сам скачок был десятикратный (с 5,3 Гб до 53 Гб).

Для поиска виновника, мы включили сбор всех событий CALL в серверном ТЖ:


<?xml version="1.0" encoding="UTF-8"?>
config xmlns="http://v8.1c.ru/v8/tech-log">
    <log history="24" location="e:\logs">
        <property name="all"/>
        <event>
            <eq property="name" value="CALL"/>
        </event>
    </log>
</config>

Напомним значения свойств Memory и MemoryPeak событий CALL технологического журнала:

Memory — объем памяти в байтах, занятой, но не освобожденной за серверный вызов.
MemoryPeak — пиковое значение за вызов памяти в байтах.

Гипотеза была следующая:
На rmngr мы должны увидеть CALL со свойством Memory или MemoryPeak около 50 Гб, либо множество CALL с суммарным Memory или MemoryPeak около того же значения.

Ниже приведены скрипты по поиску топовых вызовов по свойствам Memory и MemoryPeak соответственно за исследуемый период (12-й час):

  
cat rmngr*/*12.log|grep ',CALL,' |sed -r 's/.*Memory=([^,]*).*MemoryPeak=([^,]*).*/\1 \0/'|sort -rnb|head

  
cat rmngr*/*12.log|grep ',CALL,' |sed -r 's/.*Memory=([^,]*).*MemoryPeak=([^,]*).*/\2 \0/'|sort -rnb|head

Разберем, как работают эти скрипты на примере следующей строки:

55:09.063105-2719042,CALL,1,process=rmngr,p:processName=RegMngrCntxt,p:processName=ServerJobExecutorContext,OSThread=10956,t:clientID=45428,t:applicationName=ServerProcess,t:computerName=***,callWait=0,Interface=425a5e7b-b6a2-4b36-b7f6-ef61cb2e21a1,IName=IClusterOperativeTimestamp,Method=3,CallID=2452510,MName=clearObjectsByKeys,Memory=514769,MemoryPeak=566465,InBytes=0,OutBytes=0,CpuTime=859375

sed -r 's/.*Memory=([^,]*).*MemoryPeak=([^,]*).*/\1 \0/' выделяет адресные переменные со значениями свойств Memory и MemoryPeak и помещает их в переменные \1 и \2 соответственно, в переменной \0 хранится сама строка целиком, поэтому в зависимости от того, выводим мы \1 \0 или \2 \0, мы получим ТОП вызовов по Memory или MemoryPeak после сортировки в обратном порядке sort -rnb.

Гипотеза о наличии CALL с высоким значением Memory или MemoryPeak не подтвердилась.

Также не подтвердилась и гипотеза по суммарному значению Memory или MemoryPeak, так как по всем событиям CALL они не превышали нескольких Гб.

Просуммировать события CALL по свойствам Memory и MemoryPeak можно следующими скриптами:

  
cat rmngr*/*12.log|grep ',CALL,' |sed -r 's/.*Memory=([^,]*).*MemoryPeak=([^,]*).*/Total###\1/'|awk -F"###" '{sum[$1]+=$2;} END {for(i in sum) {print i "  " sum[i]}}'

  
cat rmngr*/*12.log|grep ',CALL,' |sed -r 's/.*Memory=([^,]*).*MemoryPeak=([^,]*).*/Total###\2/'|awk -F"###" '{sum[$1]+=$2;} END {for(i in sum) {print i "  " sum[i]}}'

Здесь также, как и в скрипте выше, в зависимости от вывода Total###\1 или Total###\2 мы получаем строки со значениями свойств Memory и MemoryPeak соответственно, записанных с префиксом Total###, а следующим оператором awk с разделителем ### мы суммируем значения второй колонки, группируя по значению первой колонки (в нашем случае строка Total) и получаем на выходе искомое суммарное значение.

Следующей мыслью был поиск события CALL точно совпадающий с началом и окончанием скачка по памяти (для этого отбираем CALL завершившийся в 12:12:33 и продолжавшийся более 18 секунд).

  
cat rmngr*/*12.log|grep '12:33.*,CALL,' | sed 's/-/,/' | awk -F ',' '{if($2 > 18000000) {print}}'|head

12:33.771040-18119014,CALL,2,process=rmngr,p:processName=RegMngrCntxt,p:processName=ServerJobExecutorContext,OSThread=29468,t:clientID=6733,t:applicationName=ServerProcess,t:computerName=***,callWait=0,Interface=43b1b75a-6252-4140-bb78-390b1502e448,IName=IClusterFullText,Method=2,CallID=2995575,MName=searchText,Memory=33250879,MemoryPeak=178593384,InBytes=10313674,OutBytes=0,CpuTime=18040625

Как видим, MemoryPeak всего около 170 Мб, но само событие посекундно совпадает со скачком памяти на графике.

По данному событию CALL подозрение пало на поиск в индексе ППД (по свойствам IName=IClusterFullText, MName=searchText). Описав проблему на v8@1c.ru и собрав диагностические данные получили ссылку на внутреннюю ошибку платформы 10223632 (Избыточное потребление памяти менеджером при поиске по строке). Исправлено в 8.3.16.1659 и выше.

Письмо 1С Линии консультации

Полнотекстовый поиск данных в 1С (англ. Full Text Searching, ППД) — это способ осуществления поиска в текстовых данных. В 1С в основном данный вид поиска используют для поиска в большом объеме данных, т.к. он существенно быстрее обычного поиска, который можно осуществить на языке запросов с помощью предиката ПОДОБНО (LIKE).
Индекс ППД — это индекс полнотекстового поиска данных в информационной базе и часть механизма полнотекстового поиска. Индекс ППД может быть создан программно или интерактивно и обновляться по мере необходимости. Подробнее про ППД можно прочитать в нашей статье.

Проблема на текущем релизе платформы ушла сразу после отключения индекса ППД в базе.

Потребление всей памяти сервера процессами rphost из-за внешней компоненты печати штрихкодов

Проявление у пользователей

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

Инфраструктура исследуемой системы

Операционная система Windows Server 2012 R2.
База данных Microsoft SQL Server 2014 SP3 64х SE.
Версия сервера 1C: 8.3.16.1973.
Виртуализация с 256Гб выделенной оперативной памяти и 12 ядер CPU 2.4 ГГц на сервере 1С+БД.
200+ работающих пользователей.

Расследование

Вдобавок к проявлениям проблемы в примере с ППД, добавились жалобы системных администраторов на утечку оперативной памяти на сервере, причем в диспетчере задач некоторые процессы rphost росли по памяти на глазах, достигая значений в 100+ Гб, пока подсистема мониторинга кластера не завершала их при достижении critical memory limit.

Настроив сбор счетчиков производительности «байт виртуальной памяти» по процессам сервера 1С, увидели следующую картину:

Работа на процессоре rphost

Начиная с какого-то момента память на процессах rphost начинала линейно утекать до самого завершения.

По событиям CALL конкретного процесса rphost по свойствам memory и memoryPeak не обнаружили факта повышенного потребления памяти ни конкретными вызовами, ни суммарно (примеры скриптов приведены ниже).

  
cat rphost_{number}/*.log|grep ',CALL,' |sed -r 's/.*Memory=([^,]*).*MemoryPeak=([^,]*).*/\1 \0/'|sort -rnb|head

  
cat rphost_{number}/*.log|grep ',CALL,' |sed -r 's/.*Memory=([^,]*).*MemoryPeak=([^,]*).*/\2 \0/'|sort -rnb|head

  
cat rphost_{number}/*.log|grep ',CALL,' |sed -r 's/.*Memory=([^,]*).*MemoryPeak=([^,]*).*/Total###\1/'|awk -F"###" '{sum[$1]+=$2;} END {for(i in sum) {print i "  " sum[i]}}'

  
cat rphost_{number}/*.log|grep ',CALL,' |sed -r 's/.*Memory=([^,]*).*MemoryPeak=([^,]*).*/Total###\2/'|awk -F"###" '{sum[$1]+=$2;} END {for(i in sum) {print i "  " sum[i]}}'

Тогда решили заглянуть внутрь проблемного процесса. В ОС Windows это можно сделать с помощью утилиты Process Explorer.

Process Explorer — бесплатная программа для мониторинга процессов в ОС Windows, созданная Sysinternals, и затем приобретённая Microsoft Corporation. Используя эту программу, можно отследить какой-либо процесс и уточнить используемые этим процессом файлы и папки.

Выводимая Process Explorer информация значительно подробнее, чем у диспетчера задач Windows.

Открыв исследуемый процесс двойным кликом мыши, во вкладке Threads можно увидеть все потоки этого процесса. Также можно провалиться внутрь потока двойным кликом мыши по нему. В нем будет отображаться меняющийся стек вызовов, который можно обновлять по кнопке Refresh.

Открыв утекающий по памяти rphost и отсортировав все потоки по колонке Start Address, обнаружили подозрительный контекст, ссылающийся на tmp файл.

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

Стек потоков

Открыв стек этих потоков видим, что в некоторых из них была строка !FT_Error_String. Подозрение пало на этот tmp файл, открыть его свойства можно по нажатию на кнопку Module для выделенного треда в свойствах процесса.

Переименовывание tmp файла в *.dll

Помня, что проблема в базе появилась после релиза конфигурации, и о том, что в релизе было обновление библиотеки БПО, пришла идея переименовать этот tmp файл в *.dll.

Это оказалась компонента печати штрихкодов 1C barcode library версии 9.0.12.8.

Компонента печати штрихкодов 1C barcode library версии 9.0.12.8

Откатив в конфигурации макет с этой библиотекой, проблема сразу же ушла.

Интересен еще тот факт, что в логах WER (см. ниже) были сообщения о некорректном завершении процессов rphost, со ссылкой на tmp файл версии 9.0.12.8, но сам файл очищался из каталога временных файлов после завершения процесса и посмотреть на него мы уже не могли.

Process Explorer же позволил нам найти этот временный файл и вычислить, что это за внешняя компонента.

Поиск в Process Explorer временного файла

Неочевидные причины падения производительности 1С

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

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

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