Открытая транзакция Dynamics AX

[Александр_161]

Добрый день просьба помочь , я MSSQL DBA , со стороны админа Dynamic AX появилась такая проблема  :


==============================

Введение

 

Каждый AOS при старте создает поток, который инициирует отдельное соединение с MS SQL. Через это соединение AOS обновляет поля Workload и LastUpdateTime в таблице SysServerSessions, причем обновление выполняется отдельными запросами для каждого поля. Поле LastUpdateTime обновляется раз в 5 минут, поле Workload обновляется значительно чаще, предположительно, при подключении очередной клиентской сессии. Также через это соединение выполняется чтение данных из таблицы SysServerSessions. Процесс MS SQL, который обслуживает данное соединение, имеет CONTEXT_INFO = «-AOS- 1 CLIENT 0». Если «убить» данный процесс, то AOS порождает новое соединение, CONTEXT_INFO соответствующего процесса MS SQL будет равен «-AOS- 1 CLIENT ХХХ», где ХХХ – некоторое произвольное число. «Убийство» этого процесса порождает в свою очередь создание нового такого же, у которого будет другое число ХХХ, и так далее. Основное отличие всех этих новых запросов от исходного (у которого ХХХ = 0) заключается в том, что они не выполняют запросы на обновление, только на чтение из таблицы SysServerSessions.

 

Проблема

 

AOS стартует, начинает обновляет поля Workload и LastUpdateTime таблицы SysServerSessions через соединение с CONTEXT_INFO = «-AOS- 1 CLIENT 0». Через некоторое время после запуска (для портального AOS’а обычно через 2-3 минуты) процесс MS SQL с этим контекстом устанавливает эксклюзивную блокировку по первичному индексу строки таблицы SysServerSessions (той строки, в которой содержится информация о данном AOS’е, которую процесс должен обновлять). В информации о последнем выполненном запросе для данного процесса MS SQL, отображается запрос на чтение из таблицы SysServerSessions. В лог проблемного AOS’а начинает ежесекундно записываться сообщение об ошибке: «Object Server 01:  RPC error: Exception 3765269347 occurred in session 1,process: Ax32Serv.exe ,thread: ХХХХ».

 

Блокировка строки таблицы самостоятельно не снимается, ее можно снять только «убив» процесс. После «убийства» процесса создается новый процесс с произвольным ХХХ в CONTEXT_INFO, который не обновляет таблицу SysServerSessions. Через полчаса один из других AOS’ов заметив, что обновление поля LastUpdateTime не происходило длительное время, устанавливает для проблемного AOS’а значение поля Status в таблице SysServerSessions равным 0, после чего обнуляет статус всем клиентам этого AOS’а в таблице SysClientSessions. При подключении нового клиента к любому из AOS’ов, ему выделяется минимальный номер клиентской сессии (из таблицы SysClientSessions), у которой статус равен 0. Если это «живая» клиентская сессия проблемного AOS’а, то он, заметив, что его клиентская сессия используется повторно, выдает сообщение об ошибке: «Object Server 01:  Unexpected situation. More Information: Session Allocation Failed: Session is already allocated.». После чего завершает работу.

==============================



Почему может быть такое что транзакция аксапты не завершается и соотвественно не снимает лок с базы. Используя EE я собрал данные по всем активностям к БД со стороны сессий Aosov , проблема проявляется в виде сессии AOS в sleeping статусе и с одной открытой транзакцией , со стороны БД нет проблем при выполнении этой транзакции - никаких эроров или дедлоков., проблема в том что нет завершения транзакции она просто остается открытой ( вывод сделан по тому что найден transaction_id в собранных данных EE и эта транзакция не имеет события коммита). Много форумов облазил и ничего толкового не нашел , кастомер утрверждает что проблема в БД хотя со стороны БД нет ни одного признака проблемы. Дайте пожалуйста знать если ситуация знакома так как я совсем из другой сферы.

[Vadik]

А если отключить обновление contextinfo ?

[trud]

Я не слышал о подобных проблемах. В любом случае эти таблицы обновляются ядром, вы с этим ничего сделать не сможете.
Типовой рекомендацией является следующее
При остановленных АОСах очистите таблицу SysServerSessions
Если проблема повторится - обновите SQL и бинарные компоненты АХ до последней версии.
не мешает также проверить что вы используете одну версию компонент - можно таким запросом, в выводе должно быть одно число

select BUILDNUM from SYSUSERLOG
where LOGOUTDATETIME > CONVERT(datetime, '2020-04-10', 120)
group by BUILDNUM

[Logger]

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

Но это проявлялось на обычных таблицах.
Для системных не замечал.

[Raven Melancholic]

А какая версия DAX и какой билд сервера?
Насколько помню, еще в DAX2009 выпускался патч, немного помогающий снять эту проблему.
Что интересно, уже кучу времени АОС 64-х разрадный, а процесс так и называется Ax32Serv.exe.

Цитата:

кастомер утрверждает что проблема в БД

Несмотря на корпоративную солидарность, могу сказать что проблема явно со стороны DAX, хотя с большой долей вероятностью не прикладного разработчика, а ядра. Такие проблемы были, но уже давно с ними не сталкивался.
PS: мне бы DBA так расписывал.

[Logger]

Цитата:

Сообщение от Raven Melancholic

Что интересно, уже кучу времени АОС 64-х разрадный, а процесс так и называется Ax32Serv.exe.

Ну это как бы в стиле MS
На 64 разрядной винде
C:\Windows\System32 - это 64-битный код.
C:\Windows\SysWOW64 - наоборот, 32-битный.

[Raven Melancholic]

И в первую очередь стоит воспользоваться советом trud

Цитата:

проверить что вы используете одну версию компонент

Чтобы не было, разные версии клиента и сервера, разных клиентов, практически гарантировано ведут к проблемам.

[AndyD]

Похоже, ошибка происходит при попытке отправить запрос на обновление SysServerSessions сиквелу со стороны AOS'а.
Ошибка не обрабатывается и транзакция не закрывается.

Я бы предложил попробовать снять трассировку обмена с помощью NetMon или чего-то подобного и посмотреть, что же за запрос пытается отправить AOS

Так же можно снять Аксптовские трассировки выполнения кода на самом АОСе и посмотреть, что там происходит

Так выглядят нормальные вызовы


И что предшествовало появлению этой ошибки?

Насчет предложений выше проверить, что версии клиентов и АОСов совпадают - поддерживаю в принципе)
Но не думаю, что в данном случае это имеет какое-то значение

Сессия -AOS- 1 создает при старте AOSа (так же как и похожая на нее сессия 2) и живет своей жизнью, никак не связанной с работой клиентов.
Т.е. она будет работать и при отсутствии любых внешних подключений

[Александр_161]

Цитата:

Сообщение от AndyD

Похоже, ошибка происходит при попытке отправить запрос на обновление SysServerSessions сиквелу со стороны AOS'а.
Ошибка не обрабатывается и транзакция не закрывается.

Я бы предложил попробовать снять трассировку обмена с помощью NetMon или чего-то подобного и посмотреть, что же за запрос пытается отправить AOS

Так же можно снять Аксптовские трассировки выполнения кода на самом АОСе и посмотреть, что там происходит

Так выглядят нормальные вызовы
Вложение 12903

И что предшествовало появлению этой ошибки?

Насчет предложений выше проверить, что версии клиентов и АОСов совпадают - поддерживаю в принципе)
Но не думаю, что в данном случае это имеет какое-то значение

Сессия -AOS- 1 создает при старте AOSа (так же как и похожая на нее сессия 2) и живет своей жизнью, никак не связанной с работой клиентов.
Т.е. она будет работать и при отсутствии любых внешних подключений

Добрый день ,

Спасибо за предложения коллеги

Я всё отлавливал через EE сессию , отлавливал событие sql_transaction в котором можно увидеть старт и коммит транзакции. На утро мы получаем на стороне SQL server три сессии AOS каждая висит с открытой транзакцией. Обычно активность от сессии поступала такая :

name timestamp transaction_id session_id transaction_state statement
sql_transaction 2020-07-21 17:32:54.8126509 5572442858 343 Begin NULL
rpc_starting 2020-07-21 17:32:54.8135127 5572442858 343 NULL declare @p2 int set @p2=0 declare @p3 int set @p3=24592 declare @p4 int set @p4=8193 declare @p5 int set @p5=126 exec sp_cursorexecute 1073741835,@p2 output,@p3 output,@p4 output,@p5 output,1,N'RUMOSMSXAOS52@2712' select @p2, @p3, @p4, @p5
sp_statement_starting 2020-07-21 17:32:54.8135966 5572442858 343 NULL SELECT T1.SERVERID,T1.AOSID,T1.INSTANCE_NAME,T1.VERSION,T1.LOGINDATETIME,T1.LOGINDATETIMETZID,T1.STATUS,T1.LOADBALANCE,T1.WORKLOAD,T1.LASTUPDATEDATETIME,T1.LASTUPDATEDATETIMETZID,T1.AOSACCOUNT,T1.RECVERSION,T1.RECID FROM SYSSERVERSESSIONS T1 WHERE ((SERVERID=@P1) AND (AOSID=@P2))
sp_statement_completed 2020-07-21 17:32:54.8139773 5572442858 343 NULL SELECT T1.SERVERID,T1.AOSID,T1.INSTANCE_NAME,T1.VERSION,T1.LOGINDATETIME,T1.LOGINDATETIMETZID,T1.STATUS,T1.LOADBALANCE,T1.WORKLOAD,T1.LASTUPDATEDATETIME,T1.LASTUPDATEDATETIMETZID,T1.AOSACCOUNT,T1.RECVERSION,T1.RECID FROM SYSSERVERSESSIONS T1 WHERE ((SERVERID=@P1) AND (AOSID=@P2))
rpc_completed 2020-07-21 17:32:54.8141576 5572442858 343 NULL declare @p2 int set @p2=180150055 declare @p3 int set @p3=16 declare @p4 int set @p4=1 declare @p5 int set @p5=1 exec sp_cursorexecute 1073741835,@p2 output,@p3 output,@p4 output,@p5 output,1,N'RUMOSMSXAOS52@2712' select @p2, @p3, @p4, @p5
rpc_starting 2020-07-21 17:32:54.8152341 5572442858 343 NULL exec sp_execute 13,'2020-07-21 14:32:55',1952004025,1,346766790
sp_statement_starting 2020-07-21 17:32:54.8152939 5572442858 343 NULL UPDATE SYSSERVERSESSIONS SET LASTUPDATEDATETIME=@P1,RECVERSION=@P2 WHERE ((SERVERID=@P3) AND (RECVERSION=@P4))
sp_statement_completed 2020-07-21 17:32:54.8158490 5572442858 343 NULL UPDATE SYSSERVERSESSIONS SET LASTUPDATEDATETIME=@P1,RECVERSION=@P2 WHERE ((SERVERID=@P3) AND (RECVERSION=@P4))
rpc_completed 2020-07-21 17:32:54.8159312 5572442858 343 NULL exec sp_execute 13,'2020-07-21 14:32:55',1952004025,1,346766790
sql_transaction 2020-07-21 17:32:54.8166274 5572442858 343 Commit NULL

=================================
Не знаю как оформить более ровно , прошу прощения

Как видите за одну транзакцию проходит SELECT и UPDATE и есть sql_transaction 2020-07-21 17:32:54.8166274 5572442858 343 Commit

У проблемных открытых транзакций нет события Commit но все операции внутри транзакции успешно выполняются - есть completed события для rpc и стейтмента внутри rpc , то есть почему-то приложение просто не досылает COMMIT. Дедлоков и событий error_reported не было никаких.В проблемной транзакции последовательность такая транзакция стартует прогоняет аналогичный селект и апдейт как выше указывал и после чего постоянно начинает отслыать с большой частотой селекты только в рамках одной это транзакции - она в свою очередь остается открытой и не завершается.

[Vadik]

Ок, выяснили что commit-а по какой-то причине нет. А ошибки в трейсе или в event log на проблемных AOS в это время были? В errorlog на AOS есть что-то интересное? Хотя это по-хорошему уже вне зоны ответственности DBA

[Александр_161]

Цитата:

Сообщение от Vadik

Ок, выяснили что commit-а по какой-то причине нет. А ошибки в трейсе или в event log на проблемных AOS в это время были? В errorlog на AOS есть что-то интересное? Хотя это по-хорошему уже вне зоны ответственности DBA

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

[AndyD]

Цитата:

Сообщение от Александр_161

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

Если речь о трейсе кода аксапты, то не обольщайтесь
При интенсивной работе АОСа он потребует очень много места (~1ГБ и больше в минуту)
Лучше снимайте трейс непостредственно, когда ошибки будут
Все равно, что именно вызвало саму ошибку в нем вы не увидите

[Logger]

Права доступа к SysServerSessions

Вот еще из похожего.
Я бы права перепроверил у юзера admin и у всех кто в момент ошибки залогинен. Дал бы им полные права на эту табличку.