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

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

28.01.2022
21 мин
9648

В этой статье речь пойдет о двух расследованиях утечки памяти на процессах кластера 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С

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

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

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

Вы читаете статью из рубрики:
От экспертов «1С-Рарус»

Есть вопросы по статье? Задайте их нам!

Рассылка «Новости компании»: узнавайте о новых продуктах, услугах и спецпредложениях

Посмотреть все рассылки «1С‑Рарус»

Поле не должно быть пустым
Электронная почта указывается только латиницей, обязательно должен присутствовать знак @, доменное имя не может быть короче двух символов

Посмотреть все рассылки «1С-Рарус»

Иконка «Предупреждение» Отправляя эту форму, Вы соглашаетесь с Политикой конфидециальности и даете согласие на обработку персональных данных компанией «1С-Рарус»

Заинтересованы в сотрудничестве?
Нужна консультация?
Свяжитесь с нами!