Открытая транзакция 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 так расписывал.

[Raven Melancholic]

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

Цитата:

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

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

[Logger]

Цитата:

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

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

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

[AndyD]

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

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

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

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


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

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

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

[Logger]

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

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

[Александр_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ГБ и больше в минуту)
Лучше снимайте трейс непостредственно, когда ошибки будут
Все равно, что именно вызвало саму ошибку в нем вы не увидите

[vmoskalenko]

Скорее всего этот ответ не совсем в тему. Но возможно наведёт на правильные мысли. Это для AX2012, Несколько леттому назад


Symptoms:
You should found new AOS instance record in the table SYSSERVERSESSIONS
SELECT * FROM SYSSERVERSESSIONS
If not, please read text below


I am glad to inform you that we found solution of our falling AOS.
 
Valery and Maksym found that issue was tied with sql stored procedure CreateServerSessions. Stored procedure was unable to add new record to sysServerSessions table, and without this record AOS was falling.
Procedure tried to add a record to table but failed due to inappropriate table definition and stored procedure statements.
AOS is working after I have added default values for 3 fields to table definition.
 
I would like to thank Maksym for his precious help.
And Valery who did everything and  just brought me possible point of failure.
 
Details:
Table definition from database with falling AOS:


Every field defined as NOT NULL     MUST have values during insert. But during insert in stored procedure 3 fileds are not listed and don’t have values: [LOGINDATETIMETZID], [LASTUPDATEDATETIMETZID], [RECVERSION].
 
Insert part from stored procedure:

 
Here is error during insert: Cannot insert the value NULL into column 'LOGINDATETIMETZID', table 'ENC_US_AX_TST.dbo.SYSSERVERSESSIONS'; column does not allow nulls. INSERT fails.
If we cannot pass these fields to table during insert, we should have DEFAULT values on table definition.
 
Here is table definition from database with working AOS:


 
And here is the script to add default values to this table to bring it “standard” look:
ALTER TABLE [dbo].[SYSSERVERSESSIONS]
       ADD DEFAULT 0 FOR [SERVERID],
              DEFAULT '' FOR [AOSID],
              DEFAULT '' FOR [INSTANCE_NAME],
              DEFAULT 0 FOR [VERSION],
              DEFAULT ('1900-01-01 00:00:00.000') FOR [LOGINDATETIME],
              DEFAULT 37001 FOR [LOGINDATETIMETZID],
              DEFAULT 0 FOR [STATUS],
              DEFAULT 0 FOR [LOADBALANCE],
              DEFAULT 0 FOR [WORKLOAD],
              DEFAULT ('1900-01-01 00:00:00.000') FOR [LASTUPDATEDATETIME],
              DEFAULT 37001 FOR [LASTUPDATEDATETIMETZID],
              DEFAULT 1 FOR [RECVERSION]
GO
ALTER TABLE [dbo].[SYSSERVERSESSIONS]  WITH CHECK ADD CHECK  (([RECID]<>(0)))
GO