Весёлые картинки о работе Performance Monitor на Windows Server 2016 Std по мотивам расследования потери производительности на базе 1С

23.11.19

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

Данная публикация посвящена одной особенности Performance Monitor на Windows Server 2016 Std. Как понимать графики Performance Monitor на Windows Server 2016 Std при расследовании проблем в работе 1С.

При расследовании проблем производительности в информационных системах на платформе 1С часто приходится проверять не выполнялся ли в момент жалоб пользователей на "зависания" и медленную работу перезапуск рабочих процессов в кластере 1С, т.к. "при аварийном завершении рабочего процесса, кластер серверов запускает новый рабочий процесс. Затем выполняется попытка перенести все клиентские сеансы, которые обслуживал завершившийся рабочий процесс, на новый рабочий процесс. Это приводит к тому, что пользователи могут наблюдать существенные паузы в работе: клиентское приложение перестает реагировать на пользовательские команды, создается ощущение, что клиентское приложение «зависло»." (https://its.1c.ru/db/v8316doc#bookmark:cs:TI000000259). Один из способов это определить - это посмотреть на график использования рабочим процессом памяти (Частный рабочий набор) в байтах. 

И в Perfmon Windows часто приходится видеть такого вида графики:

Почему зелёный график имеет такую форму? Наш основной rphost вдруг освободил чуть ли не всю память, а затем продолжил работать как ни в чём не бывало? 

Спойлер, для ищущих быстрое решение
 
 

Предлагаю рассмотреть этот вопрос подробнее и график, соответственно, поближе.

Ниже будет описание в виде басни. Почему-то именно сегодня мне захотелось оформить данную публикацию именно так. Могу опубликовать тоже самое с описанием формальным языком отдельно. Предлагаю написать в комментариях, кому не понравится изложение в виде басни. Сюжет основан на реальных событиях. Имена хостов и ID процессов изменены. Всякое совпадение является случайным. Кстати, прошу строго не судить - это моя первая публикация на Инфостарте. Так сказать проба пера.

Итак:

Жили-были agent-папа, mngr-мама и сын их rphost и был у него PID 10428. И был rphost одинок.

Как-то сожрали мама с сыном лишних 164 с небольшим мегабайт оперативной памяти и решил папа, что предел его 5-тиминутному терпению лопнул и решил он сына остановить:

28:22.387011-0,ATTN,1,process=ragent,OSThread=11908,Descr=Temporary allowed memory limit exceeded for server,ServerID=7d61e944-8c4f-456b-94c9-46ebeb290d6b,HostName=m1.app.nodeN.domain.local,TotalMemory(Kb)=25165300,TempAllowedProcessesMemory(Kb)=15625000,TempAllowedTimeLimit=300,ExcessStartTime=20191010092321,ExcessDuration(sec)=301,ProcessList[pid, mem(Kb)]='[10428, 14720016], [8296, 1073628]'

28:22.387015-0,ATTN,1,process=ragent,OSThread=11908,Descr=Process exceeded temporary allowed memory limit and would be stopped,agentURL=tcp://m1.app.nodeN.domain.local:1540,procURL=tcp://m1.app.nodeN.domain.local:1560,Pid=10428,Name=rphost

 

Предварительно сделал папа нового сына rphost и присвоила матрица ОСь ему PID 13532, а Performance Monitor окрестил его rphost#1:

28:23.887000-93986,PROC,0,process=ragent,OSThread=4632,Txt='Run process from user. Prog=C:\Program Files\1cv8\8.3.15.1534\bin\rphost.exe, Command=("C:\Program Files\1cv8\8.3.15.1534\bin\rphost.exe" -range 1560:1591 -reghost m1.app.nodeN.domain.local -regport 1541 -pid 354eb8ed-587c-4d61-9e3a-642223f84145 -fromsrvc), Domain=DOMAIN, User=USER, logon success, win API loaded, ProfilePath=C:\Users\USER, user profile loaded, user environment loaded, success, pid=13532'

 

и перестал старший rphost быть одинок пока через полторы минуты не помер, послав на прощание всем своим клиентам ошибку:

30:02.263020-0,PROC,0,process=rphost,OSThread=6296,Txt=Process terminated. Any clients finished with error.

30:02.263022-0,PROC,0,process=rphost,OSThread=6296,Err=0,Txt=1C:Enterprise 8.3 (x86-64) (8.3.15.1534) Working Process terminated.

30:02.709019-0,ATTN,1,process=ragent,OSThread=11908,Descr=Process is abandoned,agentURL=tcp://m1.app.nodeN.domain.local:1540,procURL=tcp://m1.app.nodeN.domain.local:1560,Pid=10428,Name=rphost

30:02.709021-0,EXCP,0,process=ragent,OSThread=13496,Exception="GetExitCodeProcess('10428',10428)",Descr=process exited

30:02.709022-0,ATTN,0,process=ragent,OSThread=13496,Descr=Process terminated,agentURL=tcp://m1.app.nodeN.domain.local:1540,procURL=tcp://m1.app.nodeN.domain.local:1560,Pid=10428,Name=rphost

 

Тогда Performance Monitor сделал rphost#1 старшим и переименовал его в rphost.

И жил rphost с PID 13532 счастливо, пока в 14:28:26 не умер из-за сбоя в матрице OSException.

28:26.071000-0,EXCP,0,process=rphost,p:processName=RHostRoot,OSThread=16660,OSException=rphost_8.3.15.1534_0b127ca0_20191010142826_13532 enabled external

Пока умерший rphost с PID 13532 пытался оставить после себя хоть что-то:

28:26.071003-0,EXCP,0,process=rphost,p:processName=RHostRoot,OSThread=16660,DumpError=DirBin property is empty

Папа сделал ещё одного сына rphost и присвоила матрица ему PID 17064, а Performance Monitor дал ему имя в мониторинге rphost#1:

28:31.368000-77985,PROC,0,process=ragent,OSThread=4632,Txt='Run process from user. Prog=C:\Program Files\1cv8\8.3.15.1534\bin\rphost.exe, Command=("C:\Program Files\1cv8\8.3.15.1534\bin\rphost.exe" -range 1560:1591 -reghost m1.app.nodeN.domain.local -regport 1541 -pid 354eb8ed-587c-4d61-9e3a-642223f84145 -fromsrvc), Domain=DOMAIN, User=USER, logon success, win API loaded, ProfilePath=C:\Users\USER, user profile loaded, user environment loaded, success, pid=17064'

Затем папа понял что старший сын таки потерян:

28:36.446034-0,ATTN,1,process=ragent,OSThread=11908,Descr=Process is abandoned,agentURL=tcp://m1.app.nodeN.domain.local:1540,procURL=tcp://m1.app.nodeN.domain.local:1561,Pid=13532,Name=rphost

И после второго запроса решил, что потерян давно и совсем:

28:46.477031-0,ATTN,0,process=ragent,OSThread=2872,Descr=Process is abandoned long enough,agentURL=tcp://m1.app.nodeN.domain.local:1540,procURL=tcp://m1.app.nodeN.domain.local:1561,Pid=13532,Name=rphost,expirationTimeout=100,abandonedTimestamp=-946632333

И решил его добить:

28:46.477032-0,ATTN,0,process=ragent,OSThread=2872,Descr=Process will be killed,agentURL=tcp://m1.app.nodeN.domain.local:1540,procURL=tcp://m1.app.nodeN.domain.local:1561,Pid=13532,Name=rphost,logOnly=0,createDump=1

Оставив на память его скальп:

28:46.477033-0,EXCP,0,process=ragent,OSThread=2872,OSException=rphost_8.3.15.1534_00000000_20191010142846_13532 enabled external

30:48.614008-0,EXCP,0,process=ragent,OSThread=2872,DumpError=Created dump file: C:\КаталогСервера\Dumps\rphost_8.3.15.1534_00000000_20191010142846_13532.mdmp

 

В таких случаях при довольно частых опросах (pingTimeout=5000, pingPeriod=1000) папы жив ли сын, сын при обжорстве частенько не успевает оставить после себя полноценный скальп (дамп) со смещением отличным от 00000000 и скальп (типа rphost_8.3.15.1534_0b127ca0_20191010142826_13532) может оказаться недописанным.

 

Это была присказка, а теперь сказка.

 

 Сколько rphostoв перезапустилось в 14:51 судя по данным графика ниже?

Папа версии 8.3.15.1534 очень плодовит. Причём настройки скопления 1С, предполагающие что ему не нужно иметь более одного потомка в один момент времени, ему не указ.

 

Судя по книге жизни, rphost с PID 17064, родившийся в 14:28:31.368, прожил недолго. До 14:51:08 того же дня. Потому что папа-agent наклепал других rphost, они вместе съели всю разрешённую им папой память и даже чуть больше. За что наш 17064-й и поплатился жизнью, так как съел больше остальных, ибо был старшим, и папа решил его остановить:

51:02.422010-0,ATTN,1,process=ragent,OSThread=11908,Descr=Temporary allowed memory limit exceeded for server,ServerID=7d61e944-8c4f-456b-94c9-46ebeb290d6b,HostName=m1.app.nodeN.domain.local,TotalMemory(Kb)=25165300,TempAllowedProcessesMemory(Kb)=15625000,TempAllowedTimeLimit=300,ExcessStartTime=20191010144426,ExcessDuration(sec)=396,ProcessList[pid, mem(Kb)]='[17064, 6640356], [17060, 4938764], [13780, 2529248], [8296, 1077264], [14188, 688396]'

51:02.422014-0,ATTN,1,process=ragent,OSThread=11908,Descr=Process exceeded temporary allowed memory limit and would be stopped,agentURL=tcp://m1.app.nodeN.domain.local:1540,procURL=tcp://m1.app.nodeN.domain.local:1560,Pid=17064,Name=rphost

Мемуары 17064-го оканчиваются такими же строками как и у его предшественника:

51:08.751012-0,PROC,0,process=rphost,OSThread=11960,Txt=Process terminated. Any clients finished with error.

51:08.751013-0,PROC,0,process=rphost,OSThread=11960,Err=0,Txt=1C:Enterprise 8.3 (x86-64) (8.3.15.1534) Working Process terminated.

 

Таким образом зелёная линия должна была упереться в землю где-то в точке между 14:50:30 и 14:52:00.

 

А младшие братья были благополучно переименованы Performance Monitor'ом: rphost#1 в rphost, rphost#2 в rphost#1, rphost#3 в rphost#2. В связи с чем и получаем такие весёлые картинки.

 

Поэтому глядя на подобные графики Performance Monitor мы должны видеть следующее (отредактировано в MS Paint):

Эх, не хватает нам в Performance Monitor’е привязки к ID процесса.

 

Мораль сей басни такова: не стоит обольщаться графиками подобными первому, думая, что наш основной rphost вдруг освободил чуть ли не всю память, а затем продолжил работать как ни в чём не бывало!

Это, как говорится, уже совсем другой rphost

Performance Monitor Windows Server 2016 rphost расследование проблем

См. также

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

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

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

13.03.2024    2982    spyke    26    

42

Быстродействие типовой 1С

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

Оказывается, в типовых конфигурациях 1С есть, что улучшить!

13.03.2024    5111    vasilev2015    19    

37

Анализируем SQL сервер глазами 1С-ника

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

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

1 стартмани

15.02.2024    7642    158    ZAOSTG    68    

96

Удаление строк из таблицы значений различными способами с замером производительности

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

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

09.01.2024    5979    doom2good    48    

63

Опыт оптимизации 1С на PostgreSQL

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

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

20.11.2023    8873    ivanov660    6    

76

ТОП проблем/задач у владельцев КОРП лицензий 1С на основе опыта РКЛ

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

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

15.11.2023    5105    a.doroshkevich    20    

72

Начните уже использовать хранилище запросов

HighLoad оптимизация Запросы

Очень немногие из тех, кто занимается поддержкой MS SQL, работают с хранилищем запросов. А ведь хранилище запросов – это очень удобный, мощный и, главное, бесплатный инструмент, позволяющий быстро найти и локализовать проблему производительности и потребления ресурсов запросами. В статье расскажем о том, как использовать хранилище запросов в MS SQL и какие плюсы и минусы у него есть.

11.10.2023    16187    skovpin_sa    14    

98
Комментарии
В избранное Подписаться на ответы Сортировка: Древо развёрнутое
Свернуть все
1. Evil Beaver 8107 22.10.19 10:49 Сейчас в теме
Статья норм. Единственное, что думать об "освобождении памяти" точно никогда не стоит. Резкий прыг вниз почти всегда означает смерть rphost, собственно ответ на главный вопрос статьи "а что случилось на графике" понятен сразу. А расследование "книги жизни" - интересное. Пишите еще.
ikalmykia; students; ershz; Созинов; vihrov_av; EugeneSemyonov; +6 Ответить
2. EugeneSemyonov 22 22.10.19 16:38 Сейчас в теме
(1) Андрей, спасибо Вам за поддержку!
3. nordoil 23.10.19 10:46 Сейчас в теме
Попробуйте сделать настройку на сервере, чтобы процессы в Performance Monitor’е именовались не по умолчанию rphost, rphost#1, rphost#2, ...., а с PID-ами процессов, вида rphost_17064, rphost_13532, ...., как описано в https://infostart.ru/public/966270/. Тогда возможно все станет яснее.
triviumfan; dvsidelnikov; +2 Ответить
5. EugeneSemyonov 22 23.10.19 17:34 Сейчас в теме
(3) Сергей, спасибо, за подсказку! Добавил указанную Вами публикацию в избранное. Обсужу с коллегами возможность внедрения данной настройки с учётом замечания.
11. VKislitsin 960 19.12.19 19:41 Сейчас в теме
(5)
Евгений, это я публиковал заметку про настройку. Настройка работает на всех моих проектах уже несколько лет.
Проверил, действительно, на сайте MS ссылка теперь выдает 404-ю страницу. Причем все внутренние ссылки у них же так же ведут на прежние расположения. Очень многое не удается найти. Возможно всё-таки поправят или перенесут. Пока я не нашел у Microsoft нового расположения этой статьи KB.
Мир для чего-то бросился перекраивать свои десятилетиями наработанные сайты... Вот и 1С не устояла. На v8.1c.ru тоже теперь половину не найти из того что было.

Веб-архив еще помнит эту страницу:
http://web.archive.org/web/20190420052123/https://support.microsoft.com/en-us/help/281884/the-process-object-in-performance-monitor-can-display-process-ids-pids
4. Gilev.Vyacheslav 1910 23.10.19 14:34 Сейчас в теме
про производительность из заголовка можно убрать, скорее это "про потребление ресурсов, падения, перезапуски и стабильность"
а вообще графики очень познавательно периодически изучать - иногда rphost отрывается от агента и живет своей жизнью и сразу не сообразишь где проблема
6. EugeneSemyonov 22 23.10.19 17:55 Сейчас в теме
(4) Доброго дня, Вячеслав! Спасибо за комментарий и замечание, подумаю как лучше поправить заголовок, но 1С пока не исправила ситуацию с производительностью в момент перезапуска рабочих процессов и пишет об этом открыто в документации к версии для ознакомлении 8.3.16, в которой предлагается использовать резервирование рабочих процессов для уменьшения проявлений "тормозов" клиентских приложений в момент перезапуска рабочих процессов в кластере.
7. Gilev.Vyacheslav 1910 23.10.19 21:39 Сейчас в теме
(6) ну вот с выдержкой из документации этот комментарий в начале статьи и воткните, так хотя бы будет понятна взаимосвязь
8. Созинов 25.10.19 09:30 Сейчас в теме
Отличная статья! Интересная подача, достаточно хорошо разжевали и не скучно было. Пишите еще!
9. EugeneSemyonov 22 26.10.19 20:56 Сейчас в теме
(8) Спасибо, Сергей! Думаю, у меня найдётся интересный материал ещё для парочки публикаций.
10. spbsichkar 29.10.19 19:40 Сейчас в теме
Было занимательно ) пишите еще.
maksa2005; +1 Ответить
Оставьте свое сообщение