59:23.797001-0,EXCP,0,process=rphost,ClientID=59,Exception=NetDataExchangeException,Descr='server_addr=(2)127.0.0.1:35130 descr=recv returns zero, disconnected line=3059 file=./src/DataExchangeServerImpl.cpp'

не похоже на подключение к серверу. Тут наоборот разрыв какой-то

суть в том что подключений никаких нет.

На сервере никто не рабтает

на итс есть по этому поводу статья https://its.1c.ru/db/metod8dev#content:5860:hdoc

у тебя регламентные задачи включены?

Не понимаю при чем тут сеансовые данные.

Да, регламентные задачи включены.

Однако повторяю, две одинаковые конфигурации на вин и centos серверах по разному работают. На centos подобные ошибки выше постоянны. В win машине очень редки.

эти разрывы могут происходить из-за регламентных задач, под линуксом они коряво работают

еще проверь открыт порт 35324 на сервере

нет, не открыт

попробуй открыть, т.к. он обращается к этому порту

никто и ничего не слушает этот порт прямо сейчас.

тогда не понятно почему он обращается к нему EXCP,0,process=rphost,ClientID=101,Exception=NetDataExchangeException,Descr='server_addr=(2)127.0.0.1:35324 descr=recv returns zero, disconnected

значение порта в ошибках же разное всегда

Вообще не могу понять все равно, почему при использовании сервера на centos платформа стартует значительно медленнее чем на win сервере.

При том что субд postgres при этом не нагружается. Медленных запросов нет.

у тебя видно конфиг постгриса добром не настроен

Он нормально настроен.

И вручную правил, и mamonsu tune подгонял

там уже дальше некуда особо тюнить.

незнай, у меня пострис работал быстро и в холостую не нагружался

причем реально, субд не нагржуается. если взять запросы которые посылает 1с-ка и прогнать их вручную - они отрабатывают моментально.

у тебя 1с и постгрис как стоит?, на одном сервере или раздельно

на одном.

виртуализация есть?

виртуальная машина, да.

но и вин сервер тоже самое.

если есть, то поставь на разные виртуалки

характеристики одинаковые.

вот скажем остановил сервис 1с, запустил. Потом запускаю клиент.

44:17.270002-1,HASP,1,process=1cv8,Txt=' NETHASP_LASTSTATUS(,prog=17,ser=ORGL8,,,,)->NStat=0,SysErr=0,stat=0,' 44:17.301000-0,CONN,2,process=1cv8,Txt='addrBelongsToThisComputer2, address=1c-td, result=false' 44:17.301001-0,CONN,2,process=1cv8,ClientID=1,Protected=1,Txt='Connected, client=(2)10.10.31.121:4203, server=(2)10.10.101.131:1541' 44:17.317000-0,CONN,2,process=1cv8,Txt=Clnt: MyUserName1: USER@VS33004606WG 44:17.551000-233999,SCALL,2,process=1cv8,ClientID=1,Interface=7f58f27d-5ad8-43a1-aa1e-c982f41bed5c,IName=IRemoteCreatorService,Method=0,CallID=2663,MName=createRemoteInstance 44:17.551001-0,CONN,2,process=1cv8,Txt=Clnt: DstUserName1: StartProtocol: 0 Error 44:17.566000-0,EXCP,2,process=1cv8,Descr=InitializeSecurityContext: Error 80090308! 44:17.566002-1,SCALL,2,process=1cv8,ClientID=1,Interface=73b7d3a3-fe0b-4fdf-ba70-b74b3589ffc3,IName=ISelectSrvrProcess,Method=0,CallID=2665,MName=selectProcess 44:17.582000-0,CONN,3,process=1cv8,ClientID=2,Protected=1,Txt='Connected, client=(2)10.10.31.121:4204, server=(2)10.10.101.131:1560' 44:17.597000-0,CONN,3,process=1cv8,Txt=Clnt: MyUserName1: USER@VS33004606WG 44:18.923000-1325999,SCALL,3,process=1cv8,ClientID=2,Interface=7f58f27d-5ad8-43a1-aa1e-c982f41bed5c,IName=IRemoteCreatorService,Method=0,CallID=2666,MName=createRemoteInstance 44:18.923001-0,CONN,3,process=1cv8,Txt=Clnt: DstUserName1: StartProtocol: 0 Error 44:18.923002-0,EXCP,3,process=1cv8,Descr=InitializeSecurityContext: Error 80090308! 44:18.923003-1653000,CONN,1,process=1cv8,ClientID=1,Txt=Outgoing connection closed 45:30.679000-71755996,SCALL,2,process=1cv8,ClientID=2,Interface=ef207edb-9db6-4e8e-ad4b-d20992a2853a,IName=IServerInfoBase,Method=1,CallID=2669,MName=connect

встал почти на минуту например.

после работ с хаспом.

из-за чего, фиг знает.

Или например открываешь форму документа. Встал опять секунд на 20. Со стороны клиента это как вызов формы в логе, 20 секунд тишины - потом ответ от сервера.

я эксперементировал с 1с и пострисом, ставил на одном сервере, так 1с сжирала все ресурсы и на постгрис ресурсов не хватало

Зато последующие заходы формы происходят моментально

да, 1с ест очень сильно ресурсы на линуксе.

Или например открываешь форму документа. Встал опять секунд на 20. Со стороны клиента это как вызов формы в логе, 20 секунд тишины - потом ответ от сервера.

кеша нехватает

кеша чего? 1с-ного?

да, 1с ест очень сильно ресурсы на линуксе.

разбивай на разные виртуалки

или базы данных?

кеша чего? 1с-ного?

постгриса

базы мелкие, они хоть целиком в шаред буфферс залезть могут:)

смотри, я включил логирование долгих запросов и средставми 1с и средствами постгреса

в буфер не желательно

все что дольше 2 секунд должно сыпаться в лог

но лог пустой

т.е. запросы отрабатываются быстро

59:23.797001-0,EXCP,0,process=rphost,ClientID=59,Exception=NetDataExchangeException,Descr='server_addr=(2)127.0.0.1:35130 descr=recv returns zero, disconnected line=3059 file=./src/DataExchangeServerImpl.cpp'

Это еще не говорит о наличии каких-либо проблем.

44:17.270002-1,HASP,1,process=1cv8,Txt=' NETHASP_LASTSTATUS(,prog=17,ser=ORGL8,,,,)->NStat=0,SysErr=0,stat=0,' 44:17.301000-0,CONN,2,process=1cv8,Txt='addrBelongsToThisComputer2, address=1c-td, result=false' 44:17.301001-0,CONN,2,process=1cv8,ClientID=1,Protected=1,Txt='Connected, client=(2)10.10.31.121:4203, server=(2)10.10.101.131:1541' 44:17.317000-0,CONN,2,process=1cv8,Txt=Clnt: MyUserName1: USER@VS33004606WG 44:17.551000-233999,SCALL,2,process=1cv8,ClientID=1,Interface=7f58f27d-5ad8-43a1-aa1e-c982f41bed5c,IName=IRemoteCreatorService,Method=0,CallID=2663,MName=createRemoteInstance 44:17.551001-0,CONN,2,process=1cv8,Txt=Clnt: DstUserName1: StartProtocol: 0 Error 44:17.566000-0,EXCP,2,process=1cv8,Descr=InitializeSecurityContext: Error 80090308! 44:17.566002-1,SCALL,2,process=1cv8,ClientID=1,Interface=73b7d3a3-fe0b-4fdf-ba70-b74b3589ffc3,IName=ISelectSrvrProcess,Method=0,CallID=2665,MName=selectProcess 44:17.582000-0,CONN,3,process=1cv8,ClientID=2,Protected=1,Txt='Connected, client=(2)10.10.31.121:4204, server=(2)10.10.101.131:1560' 44:17.597000-0,CONN,3,process=1cv8,Txt=Clnt: MyUserName1: USER@VS33004606WG 44:18.923000-1325999,SCALL,3,process=1cv8,ClientID=2,Interface=7f58f27d-5ad8-43a1-aa1e-c982f41bed5c,IName=IRemoteCreatorService,Method=0,CallID=2666,MName=createRemoteInstance 44:18.923001-0,CONN,3,process=1cv8,Txt=Clnt: DstUserName1: StartProtocol: 0 Error 44:18.923002-0,EXCP,3,process=1cv8,Descr=InitializeSecurityContext: Error 80090308! 44:18.923003-1653000,CONN,1,process=1cv8,ClientID=1,Txt=Outgoing connection closed 45:30.679000-71755996,SCALL,2,process=1cv8,ClientID=2,Interface=ef207edb-9db6-4e8e-ad4b-d20992a2853a,IName=IServerInfoBase,Method=1,CallID=2669,MName=connect

45:30.679000-71755996,SCALL,2,process=1cv8,ClientID=2,Interface=ef207edb-9db6-4e8e-ad4b-d20992a2853a,IName=IServerInfoBase,Method=1,CallID=2669,MName=connect 71 секунду вызов обрабатывался сервером. Ищите соответствующий ему call в rphost и разбирайтесь, что он делал

ммм. а где вы увидели что 71 секунду?

-71755996 - длительность события в микросекундах

это значение сразу появляется вместе со всей строчкой.

как оно может быть 71 секунду, если оно в логе появилось мгновенное после запуска платформы?

И самое главное как понять что именно делал сервер в этот момент? Например запрос вида 38:36.339007-0,VRSREQUEST,2,process=1cv8,Usr=Администратор,Method=GET,URI='/e1cib/cmi/commands?subtree=false&sysver=8.3.9.1818

после нее он встал на какое-то время

нашел я аналогичную строчку в логе сервера. она выглядит точно так же

как это можно анализировать и диагностировать?

38:56.278000-0,CONN,0,process=rphost,ClientID=87,Txt=Incomming connection closed: long still 38:57.471000-0,CONN,0,process=rphost,ClientID=88,Txt=Incomming connection closed: long still

вот например из лога сервера.

далее по времени

В промежутке между действиями вижу выполнение фоновых заданий на других ИБ. 38:58.964000-29999,HASP,3,process=rphost,p:processName=gp,t:clientID=100,t:applicationName=BackgroundJob,t:computerName=servername,t:connectID=104,Txt=' LOCALHASP_ENCODEDATA(,port=201,ser=EN8SA,,size=46,,buf=0235FE595F6B15A624F6525F29C2197833CF61360F2283E31854AC50B3E28BB518890E77F5231E191A7078433291)->,,stat=0,buf=123BB53C34A1639EC9A901927385FACB992CEA4B6229CF770B3B283A44E46B57F092F6A2BED732BDE0E0651F2E6B'

ERROR: S client not available

как оно может быть 71 секунду, если оно в логе появилось мгновенное после запуска платформы?

смотрите на время события и на время предыдущего события.

И самое главное как понять что именно делал сервер в этот момент? Например запрос вида 38:36.339007-0,VRSREQUEST,2,process=1cv8,Usr=Администратор,Method=GET,URI='/e1cib/cmi/commands?subtree=false&sysver=8.3.9.1818

Если речь о событии SCALL - ищите на сервере событие CALL с тем же CallID и смотрите, что происходило перед ним с тем же t:clientID

А если речь идет о VRSREQUEST - для него парное событие - следующий VRSRESPONSE с тем же vrs_session

А если речь идет о VRSREQUEST - для него парное событие - следующий VRSRESPONSE с тем же vrs_session

Да, был ответ. Там задержки нет. Потом висит событие что выше привел. Висит согласно Вашим расшифровкам 29 секунд.

Если 1 рпхост, то весь сервер встает на этом событии?

нет, конечно же

вызовы различных сеансов исполняются параллельно

Да, был ответ. Там задержки нет. Потом висит событие что выше привел. Висит согласно Вашим расшифровкам 29 секунд.

не 29 секунд, а 29 миллисекунд

не 29 секунд, а 29 миллисекунд

Миллионные доли?

Блин, Вы бы хоть приставки кратности разучили https://ru.wikipedia.org/wiki/%D0%9F%D1%80%D0%B8%D1%81%D1%82%D0%B0%D0%B2%D0%BA%D0%B8_%D0%A1%D0%98#.D0.9F.D1.80.D0.B8.D1.81.D1.82.D0.B0.D0.B2.D0.BA.D0.B8_.D0.B4.D0.BB.D1.8F_.D0.BA.D1.80.D0.B0.D1.82.D0.BD.D1.8B.D1.85_.D0.B5.D0.B4.D0.B8.D0.BD.D0.B8.D1.86

Разучите - вот вам следующий материал: https://1c.ru/news/info.jsp?id=20028

Разучите - вот вам следующий материал: https://1c.ru/news/info.jsp?id=20028

Не актуально в рамках другой ос и субд.

Я правильно вас понимаю, что если в событии после временной метки «-» стоит 0, то выполняется без задержек? А если между операциями при этом от одной сессии имеются временные зазоры, то что их пораждает?

Я правильно вас понимаю, что если в событии после временной метки «-» стоит 0, то выполняется без задержек? А если между операциями при этом от одной сессии имеются временные зазоры, то что их пораждает?

Правильно ли Вы меня понимаете или нет, Вам станет понятнее, когда Вы ознакомитесь с документацией по используемому ПО. Цитировать документацию мне лень.

Правильно ли Вы меня понимаете или нет, Вам станет понятнее, когда Вы ознакомитесь с документацией по используемому ПО. Цитировать документацию мне лень.

Как-то вы не по доброму реагируете на вопросы. Конечно я смотрел документацию. Однако в книжках что у меня есть информация уже подустарела (например у меня секунды отображаются в других порядках), а часть информации нет (например о том как правильно сопоставить вызовы на клиенте и сервере). Да и нет понимания как реагировать на сообщения в журнале с длительностью 0. Ведь по-любому оно выполняется какое-то время, и всяко не равное 0. Как складывать задержку из кучки событий в серверном журнале на одно событие в клиентском и как их вообще связать при налиции различных информационных баз и сеансов ( в том числе фоновых и регламентных заданий). И куда смотреть если задержка все же больше чем то что видно в серверном логе (хотя возможно я не включил все возможные события в серверном логе). Так что подводных камней куда больше чем описано в паре страниц книжки ( большая часть при том описание событий журнала и их атрибутов). Потому картинку целиком работы сервера в журнале сложить тяжело, тем более если не имеется тонны часов подобных изучений в прошлом. Но все равно спасибо вам за ответы :)

Правильные источники документации = its.1c.ru и kb.1c.ru Любая бумажная книга когда-то устареет.

Что касается длительности события - вы путаете условие (их два - duration и durationus) с отображаемым значением. Следовательно, документацию не читаете

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

Что касается длительности события - вы путаете условие (их два - duration и durationus) с отображаемым значением. Следовательно, документацию не читаете

duration и durationus - это если условие ставить... Но после "-" идет время в микросекундах для 8.3 и миллисекундах для 8.2

Что касается длительности события - вы путаете условие (их два - duration и durationus) с отображаемым значением. Следовательно, документацию не читаете

Возможно я не так выразился или точнее не теми терминами которыми вы оперируете. Я пытаюсь понять на каком моменте происходит затык в работе сервера. Соответсвенно я сверяю время окончания двух ближайших событий в журнале. У некоторых событий есть продолжительность. Но между некоторыми у которых нет продолжительности есть зазоры скажем в 20 секунд. Соответсвенно я пытаюсь найти на сервере что происходит в эти 20 секунд.

duration и durationus - это если условие ставить... Но после "-" идет время в микросекундах для 8.3 и миллисекундах для 8.2

спасибо, это я уже освежил в памяти.

О чем говорят SCALL в тех журнале на стороне сервера? Например IClusterLocks

О чем говорят SCALL в тех журнале на стороне сервера? Например IClusterLocks

о вызове к сервисам кластера. Парный ему Call нужно искать в rmngr

Есть такой вот кусок в логе клиента

34:28.168007-0,VRSREQUEST,2,process=1cv8,Usr=Администратор,Method=GET,URI='/e1cib/cmi/commands?subtree=false&sysver=8.3.9.1818&user=2&fover=f56435cd-43d5-ed77-704d-fc0f7f5cb68c&rolesId=128&navVer=00000000-0000-0000-0000-000000000000&taxi=1&fragment=e0666db2-45d6-49b4-a200-061c6ba7d569&confver=ba80e7aba8c67bc48e071aad3985b25662f20913&clang=ru&categories=1&fo=true',Headers='Accept-Charset: utf-8 1C-ApplicationName: 1CV8 User-Agent: 1CV8 Accept-Encoding: deflate,1CSDC;q=0.5 Accept: application/xml Accept-Language: ru-RU Content-Length: 0 1C-BaseLocation: e1c://server/servername/bb',Body=0 34:55.578001-27409993,SCALL,2,process=1cv8,Usr=Администратор,ClientID=2,Interface=bc15bd01-10bf-413c-a856-ddc907fcd123,IName=IVResourceRemoteConnection,Method=0,CallID=16357,MName=send 34:55.578002-0,VRSRESPONSE,2,process=1cv8,Usr=Администратор,Status=204,Phrase=No content,Headers='Cache-Control: private, max-age=31536000 Content-Language: ru-RU Content-Length: 0 Server: 1C:Enterprise/8.3.9.1818',Body=0 34:55.578003-0,VRSREQUEST,2,process=1cv8,Usr=Администратор,Method=GET 34:55.239000-27407000,CALL,2,process=rphost,p:processName=bb,t:clientID=5,t:applicationName=1CV8,t:computerName=vs33004606wg,t:connectID=1,SessionID=7,Usr=Администратор,Interface=bc15bd01-10bf-413c-a856-ddc907fcd123,IName=IVResourceRemoteConnection,Method=0,CallID=16357,MName=send,Memory=157524840,MemoryPeak=162491880,InBytes=41594428,OutBytes=39139105

соответствующий фрагмент на сервере https://pastebin.ubuntu.com/23450194/

Там море запросов к базе которые выполняются довольно быстро. Но вот их кол-во смущает. Не понятно где в конфигурации они генерируются.

а разве не сервер их генерит? тем более если включены регламентные задания

Даже если сервер, то они все равно относятся к моему клиенту от которого я выполняю вход согласно t:clientID=5. И они замедляют соответственно вход. Есть еще несколько таких мест в логе, которые суммарно затормозили вход в систему на минуту.

Это же не нормально

хм, странно конечно, но для 1с вполне возможно...

кстати, а какой у тебя режим установлен?