При расследовании проблем производительности в информационных системах на платформе 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) может оказаться недописанным.
Это была присказка, а теперь сказка.
Сколько rphost’oв перезапустилось в 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…
