AX2009 TraceParcer issue

[DSPIC]

Всем привет,

AX2009

может кто-то сталкивался с ошибкой при попытке импортитовать лог в TraceParcer?





пробовал сделать то же самое на совершенно независимом энве - аналогичная ошибка.

[Logger]

Багу не встречал.

Идеи:
1. Возможно загрузка полагается на порядок следования полей в базе и загрузка значения происходит не в тот столбец. Сиквел пытается автоматически сконвертировать значение и происходит переполнение.
Что можно сделать - посмотреть какой SQL запрос идет. Угадать правильный порядок столбцов. пересоздать табличку с нужным порядком следования столбцов в базе.

2. Может формат базы не тот ? Опять можно потрассировать запросы и попытаться угадать какой должен быть правильным.

[DSPIC]

Спасибо, но похоже, дело не в этом. Поигравшись, заметил, что ошибка возникает уже после загрузки трейса в DB и появляется каждый раз когда, скажем, переключаешся между сессиями юзеров, т.е. при перестроении дерава колл стека. Колл стек, тем не менее, отрисовывается, но время исполнения выполнения кода кривое, прописывается значение, как максимально-возможное для типа int(или long-int), что коррелирует с сообщением об ошибке. Т.е. ошибка, похоже чисто на UI.

[Logger]

Да он вообще немного глючный
Тормозит создание буфера.

[Logger]

У меня вот такой был. Microsoft Dynamics AX Trace Parser.rar

[Sergicc]

скиньте пжл дистр. парсера если не трудно не могу найти нигде.спс

[alexkrut]

Привет!

Понимаю, что форум теперь больше экономический, чем про аксапту, но рискну спросить.

Столкнулся с той же проблемой что и топикстартер, причем на двух разных аксаптах (2009 и 2012) и двух разных трейспарсерах соответственно.

Исследования показали, что сами трейспарсеры не при чем (трейсы собранные на моей личной виртуалке, открываются без проблем что в 2012, что в 2009).

Сама проблема в записи (или интерпретации) sql запросов (если записывать в трейс только X++) все работает.
А конкретно не работает интерпретация AxPrepDuration:

Запускаю запись трейсов вот так:

SysTraceControl::startClientTrace( @"C:\temp\trace.etl", 
                                        #AXTRACE_DEFAULT_BUFFER_SIZE,
                                        #AXTRACE_DEFAULT_MINBUFFERS,
                                        #AXTRACE_DEFUALT_MAXBUFFERS,
                                        0x34);
    
    select * from inventTable;

    info( inventTable.ItemId );
    
    SysTraceControl::stopClientTrace();

Получаю вот такое в etl (сконвертил etl в xml):

PHP код:

<Data Name="seqNum">318586</Data>
<Data Name="AxServerName">...</Data>
<Data Name="AxUserName">...</Data>
<Data Name="AxSessionId">3</Data>
<Data Name="AxRC">1</Data>
<Data Name="AxConDBSpid">59</Data>
<Data Name="AxSqlStmt">SELECT T1.ITEMID,T1.ITEMTYPE,T1.PURCHMODEL,T1.HEIGHT,T1.WIDTH,T1.SALESMODEL,T1.COSTGROUPID,T1.REQGROUPID,T1.EPCMANAGER,T1.PRIMARYVENDORID,T1.NETWEIGHT,T1.DEPTH,T1.UNITVOLUME,T1.BOMUNITID,T1.ITEMPRICETOLERANCEGROUPID,T1.DENSITY,T1.COSTMODEL,T1.USEALTITEMID,T1.ALTITEMID,T1.MATCHINGPOLICY,T1.INTRACODE,T1.PRODFLUSHINGPRINCIP,T1.MINIMUMPALLETQUANTITY,T1.PBAITEMAUTOGENERATED,T1.WMSARRIVALHANDLINGTIME,T1.BOMMANUALRECEIPT,T1.PHANTOM,T1.INTRAUNIT,T1.BOMLEVEL,T1.BATCHNUMGROUPID,T1.AUTOREPORTFINISHED,T1.ORIGCOUNTRYREGIONID,T1.STATISTICSFACTOR,T1.ALTCONFIGID,T1.STANDARDCONFIGID,T1.PRODPOOLID,T1.PROPERTYID,T1.ABCTIEUP,T1.ABCREVENUE,T1.ABCVALUE,T1.ABCCONTRIBUTIONMARGIN,T1.COMMISSIONGROUPID,T1.SALESPERCENTMARKUP,T1.SALESCONTRIBUTIONRATIO,T1.SALESPRICEMODELBASIC,T1.NAMEALIAS,T1.PRODGROUPID,T1.PROJCATEGORYID,T1.GROSSDEPTH,T1.GROSSWIDTH,T1.GROSSHEIGHT,T1.STANDARDPALLETQUANTITY,T1.QTYPERLAYER,T1.SORTCODE,T1.SERIALNUMGROUPID,T1.ITEMBUYERGROUPID,T1.TAXPACKAGINGQTY,T1.WMSPALLETTYPEID,T1.ORIGSTATEID,T1.WMSPICKINGQTYTIME,T1.TARAWEIGHT,T1.PACKAGINGGROUPID,T1.SCRAPVAR,T1.SCRAPCONST,T1.STANDARDINVENTCOLORID,T1.STANDARDINVENTSIZEID,T1.ITEMDIMCOSTPRICE,T1.ALTINVENTSIZEID,T1.ALTINVENTCOLORID,T1.FORECASTDMPINCLUDE,T1.PRODUCT,T1.PALLETTAGGING,T1.ITEMTAGGINGLEVEL,T1.DEFAULTDIMENSION,T1.BOMCALCGROUPID,T1.PBAITEMCONFIGURABLE,T1.PBAINVENTITEMGROUPID,T1.PBAHIDEDIALOG,T1.PBAHIDEAPPROVAL,T1.PBAAUTOSTART,T1.PBAMANDATORYCONFIG,T1.PDSCWWMSSTANDARDPALLETQTY,T1.PDSCWWMSMINIMUMPALLETQTY,T1.PDSCWWMSQTYPERLAYER,T1.ALTINVENTSTYLEID,T1.BATCHMERGEDATECALCULATIONMETHOD,T1.PDSBASEATTRIBUTEID,T1.PDSBESTBEFORE,T1.PDSFREIGHTALLOCATIONGROUPID,T1.PDSITEMREBATEGROUPID,T1.PDSPOTENCYATTRIBRECORDING,T1.PDSSHELFADVICE,T1.PDSSHELFLIFE,T1.PDSTARGETFACTOR,T1.PDSVENDORCHECKITEM,T1.PMFPLANNINGITEMID,T1.PMFPRODUCTTYPE,T1.PMFYIELDPCT,T1.STANDARDINVENTSTYLEID,T1.MODIFIEDDATETIME,T1.DEL_MODIFIEDTIME,T1.MODIFIEDBY,T1.CREATEDDATETIME,T1.DEL_CREATEDTIME,T1.CREATEDBY,T1.RECVERSION,T1.PARTITION,T1.RECID FROM INVENTTABLE T1 WHERE ((PARTITION=?) AND (DATAAREAID=?))</Data>
<Data Name="AxDuration">7203</Data>
<Data Name="AxPrepDuration">0</Data> 


Как можно видеть, AxPrepDuration = 0
Но если загрузить этот трейс в трейс парсер, получаем следующее:

Prep Time (ms) : -922,337,203,685,478.00 (и так реально лежит в базе трейспарсера для этой строки трейса)

Выглядит так, будто в процессе импорта 0 из AxPrepDuration зачем-то интерпретируется, как минимальное значение long.

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

Может у кого-то возникнут идеи, хотябы в каком направлении копать?

Сервер 2019
SQL 2017
билд 2012 - 6.3.6000.151
билд 2009 - 5.0.1500.3761

[Logger]

Если мне не изменяет память, загрузку в базу вы делаете в самом трейспарсере.
А он представляет из себя сборку .net
Можно посмотреть исходник ILSpy-ем. Или может даже они где-то есть на гитхабе.
Посмотрите это место в коде. Возможно там некорректно работа с типами идет.

[Masel]

А если собрать через perfmon.exe? Я просто только так и собираю. Там еще есть проблема с версией ОС. На 2019 не работает. Вроде максимум на 2016. То есть файл формируется, но в парсер грузится с ошибкой на 2019.

[alexkrut]

Цитата:

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

А если собрать через perfmon.exe?

Через него тоже пробовал, с аналогичным результатом. А можете подсказать, с какими настройками вы его запускаете? (Keywords для провайдера, размер буфера и т д)

И по поводу версии ос где-то были статьи и\или официальный анонс, почему именно не будет работать с 2019?

Вот здесь тоже люди встречались с подобным и пишут, что может случиться на версиях сервера младше 2019

https://community.dynamics.com/ax/f/...flow-exception

[Logger]

Названия полей там интересные упомянуты

Columns : inclusivedurationnano , databasedurationnano , binddurationnano, exclusivedurationnano , prepdurationnano , rowfetchdurationnano

Может там счетчики старта завершения длительности в тиках стоят. И в более свежих виндах (более свежих версиях .net) они приобретают более высокие значения ? Тикают с большей точностью чем на старых виндах и быстрее достигают значений приводящих к переполнению.

Обычно разные счетчики обнуляются с перезагрузкой винды.
Попробуйте сервак перезагрузить и снова трейс собрать и загрузить.

Реально я не исследовал - это только поверхностные предположения.

[Masel]

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

[Товарищ ♂uatr]

Привет.
При регистрации новой БД приложение выдает ошибку. Для меня является загадкой причина по которой не был сделан динамический вывод информации о причине ошибки, тем не менее... после кастомизации Microsoft.Dynamics.AX.Tracing.Data.dll пришло понимание, что текст ошибки звучит как: 'PK__TraceLin__9FC961DF25869641' is not a constraint.
Удалось найти проблемный запрос к БД:

ALTER TABLE [dbo].[TraceLines] DROP CONSTRAINT [PK__TraceLin__9FC961DF25869641]

Понятное дело, что "игра называется угадай, а что в БД на самом деле", а там "PK__TraceLin__9FC961DF4E1C95DE".
Мой вопрос - насколько это обыденная проблема при работе с данным ПО? У меня может дитрибутив "битый"?

[gl00mie]

Цитата:

Сообщение от Товарищ ♂uatr

Мой вопрос - насколько это обыденная проблема при работе с данным ПО? У меня может дитрибутив "битый"?

Еще бы версию Trace Parser-а привести для понимания...

Цитата:

Сообщение от Товарищ ♂uatr

При регистрации новой БД приложение выдает ошибку: 'PK__TraceLin__9FC961DF25869641' is not a constraint. В БД на самом деле "PK__TraceLin__9FC961DF4E1C95DE".

Не встречал при регистрации новой БД Trace Parser ошибок, кроме связанных с отсутствием права create database на сервере. В целом же после ковыряний с D365FO и ее глючной синхронизацией я лично решил для себя, что если приложение хочет дропнуть в базе что-то, чего там нет, то проще дать ему это дропнуть: создать недостающий constraint с нужным именем (любого содержания), или поле, или индекс, или что там приложение не может найти, но хочет изничтожить. Пусть дропнет и не мотает нервы

[Товарищ ♂uatr]

Совсем забыл...речь идет о Version 6.0.947.9033.

Да, создать нужный объект мне тоже хотелось и это было бы решением, если бы (много бы) утилита умела валидировать целостность БД и продолжать выполнение с момента предыдущего прерывания. У нее 2 состояния - создать новую БД или использовать существующую.

Проблемы, на самом деле две:
Первая - в коде исполняемого файла, в функции Microsoft.Dynamics.AX.Tracing.TraceParser.Presentation.DatabaseRegister.CollectDatabaseRegistrationConnectionString. Изображение прикрепил, стрелками синего цвета отмечен путь в случае когда БД есть, серого - БД нет.
Вторая - можно вызвать "Microsoft.Dynamics.AX.Tracing.Data.DatabaseHelper.CreateDatabase" через то же консольное приложение, но там "затык" уже в самих запросах к БД. Первым запросом идет "create database" - снова "свалится", БД же есть к этому моменту.

Вижу 2.5 путей решения:
1. Разобраться с генерацией названия PK;
2. Видоизменить проблемный код в библиотеке;
2.5. Запустить скрипты по подготовке БД самостоятельно.
Понятное дело, что 1-ый вариант вызывает интерес. Для эксперимента взял другую машину (SQL другой, ОС другая) результат - "PK__TraceLin__9FC961DFECC085B4". Документации официальной на тему правил генерации наименований не вижу, может кто-то владеет такой информацией?

[Товарищ ♂uatr]

Насколько понял принцип генерации - симбиоз sessionID и timestamp.

Спасибо Logger'у, теперь у меня есть с чем сравнить и просто "повезло нарваться" на "правильную" версию, видимо она устарела в современных реалиях (SQL server).
В 6.0.947.9033:

ALTER TABLE [dbo].[QueryBindParameters] DROP CONSTRAINT [FK_QueryBindParameters_TraceLines]

    ALTER TABLE [dbo].[XppParameters] DROP CONSTRAINT [FK_XppParameters_TraceLines]

    ALTER TABLE [dbo].[TraceLines] DROP CONSTRAINT [PK__TraceLin__9FC961DF25869641]

    ALTER TABLE [dbo].[TraceLines] ADD  CONSTRAINT [PK__TraceLin__9FC961DF25869641] PRIMARY KEY NONCLUSTERED
    (
    [TraceLineId] ASC
    )

В 6.3.164.0:

ALTER TABLE [dbo].[QueryBindParameters] DROP CONSTRAINT [FK_QueryBindParameters_TraceLines]

ALTER TABLE [dbo].[XppParameters] DROP CONSTRAINT [FK_XppParameters_TraceLines] 

declare @tempPkName nvarchar(128);

SELECT @tempPkName = idx.name
FROM
	sys.indexes idx
	INNER JOIN sys.tables tbl
		ON idx.object_id = tbl.object_id
WHERE
	tbl.name = 'TraceLines'
	AND idx.is_primary_key = 1

exec(
'ALTER TABLE [dbo].[TraceLines] DROP CONSTRAINT ' + @tempPkName);

exec('ALTER TABLE [dbo].[TraceLines] ADD  CONSTRAINT '+ @tempPkName + ' PRIMARY KEY NONCLUSTERED 
(
	[TraceLineId] ASC
)');

[Товарищ ♂uatr]

Воспроизвел исходную ошибку данной темы.
Валится здесь:

			IQueryable<XppAggregate> source = (from t in entities.TraceLines
			join m in entities.MethodNames on t.MethodHash equals (long?)m.MethodHash
			where t.UserSessionProcessId >= startSessionId && t.UserSessionProcessId <= endSessionId
			group t by new
			{
				t.MethodHash,
				m.Name
			} into topXppGroup
			orderby topXppGroup.Sum((TraceLine x) => x.IsRecursive.Value ? 0 : x.InclusiveDurationNano) descending
			select new XppAggregate
			{
				Name = topXppGroup.Key.Name,
				Count = topXppGroup.Count(),
				InclusiveTotal = (double)topXppGroup.Sum((TraceLine x) => x.IsRecursive.Value ? 0 : x.InclusiveDurationNano) / 10000.0,
				ExclusiveTotal = (double)topXppGroup.Sum((TraceLine x) => x.IsRecursive.Value ? 0 : x.ExclusiveDurationNano) / 10000.0,
				InclusiveRpcTotal = topXppGroup.Sum((TraceLine x) => x.IsRecursive.Value ? 0 : x.InclusiveRpc),
				DatabaseCallsTotal = topXppGroup.Sum((TraceLine x) => x.IsRecursive.Value ? 0 : x.DatabaseCalls)
			}).Take(top);
			List<XppAggregate> list = source.ToList();

Как SQL оно выглядит так:

exec sp_executesql N'SELECT TOP (5) 
[Project1].[C5] AS [C1], 
[Project1].[Name] AS [Name], 
[Project1].[C2] AS [C2], 
[Project1].[C6] AS [C3], 
[Project1].[C7] AS [C4], 
[Project1].[C3] AS [C5], 
[Project1].[C4] AS [C6]
FROM ( SELECT 
	[GroupBy1].[A1] AS [C1], 
	[GroupBy1].[A2] AS [C2], 
	[GroupBy1].[A5] AS [C3], 
	[GroupBy1].[A6] AS [C4], 
	[GroupBy1].[K2] AS [Name], 
	1 AS [C5], 
	 CAST( [GroupBy1].[A3] AS float) / cast(10000 as float(53)) AS [C6], 
	 CAST( [GroupBy1].[A4] AS float) / cast(10000 as float(53)) AS [C7]
	FROM ( SELECT 
		[Filter1].[K1] AS [K1], 
		[Filter1].[K2] AS [K2], 
		SUM([Filter1].[A1]) AS [A1], 
		COUNT([Filter1].[A2]) AS [A2], 
		SUM([Filter1].[A3]) AS [A3], 
		SUM([Filter1].[A4]) AS [A4], 
		SUM([Filter1].[A5]) AS [A5], 
		SUM([Filter1].[A6]) AS [A6]
		FROM ( SELECT 
			[Extent1].[MethodHash] AS [K1], 
			[Extent2].[Name] AS [K2], 
			CASE WHEN ([Extent1].[IsRecursive] = 1) THEN cast(0 as bigint) ELSE [Extent1].[InclusiveDurationNano] END AS [A1], 
			1 AS [A2], 
			CASE WHEN ([Extent1].[IsRecursive] = 1) THEN cast(0 as bigint) ELSE [Extent1].[InclusiveDurationNano] END AS [A3], 
			CASE WHEN ([Extent1].[IsRecursive] = 1) THEN cast(0 as bigint) ELSE [Extent1].[ExclusiveDurationNano] END AS [A4], 
			CASE WHEN ([Extent1].[IsRecursive] = 1) THEN 0 ELSE [Extent1].[InclusiveRpc] END AS [A5], 
			CASE WHEN ([Extent1].[IsRecursive] = 1) THEN 0 ELSE [Extent1].[DatabaseCalls] END AS [A6]
			FROM  [dbo].[TraceLines] AS [Extent1]
			INNER JOIN [dbo].[MethodNames] AS [Extent2] ON [Extent1].[MethodHash] = [Extent2].[MethodHash]
			WHERE ([Extent1].[UserSessionProcessId] >= @p__linq__0) AND ([Extent1].[UserSessionProcessId] <= @p__linq__1)
		)  AS [Filter1]
		GROUP BY [K1], [K2]
	)  AS [GroupBy1]
)  AS [Project1]
ORDER BY [Project1].[C1] DESC',N'@p__linq__0 int,@p__linq__1 int',@p__linq__0=26,@p__linq__1=26

Ну и очень хорошо воспроизводится - это проблема данных в БД. Предположу, что причиной является конкретный лог трассировки.

[Logger]

А вы обратили внимание что везде повторяется одна "магическая" константа "-9223372036854775808"

И если погуглить
https://www.google.com/search?q="-9223372036854775808"

То легко увидеть что это 2^63 со знаком минус. Явно было какое то переполнение.
А судя по тому что описывают тут
https://stackoverflow.com/questions/...f-a-2d-array-a

https://github.com/numpy/numpy/issues/13101

Такие числа получаются если вещественный Nan приравнять целому числу. Тогда получается MinInt соответствующей размерности (для int64 будет -2^63 т.е. наш случай)
Там явно где то при сборе трейсов идет ошибка.

Думаю, что раз трейс смог закачаться в SQL базу то можно одним SQL запросом перебить эту магическую константу на 0 и тогда с трейсом можно будет обращаться.
Судя по скрину там был вызов ConPeek() (если мне не изменяет память, то qpeek это ConPeek()) - он не должен очень много занимать. Если обнулить, то погрешность вероятно будет не слишком большой.

[Logger]

Цитата:

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

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

А вы не пробовали запускать приложение в режиме совместимости с предыдущими версиями Windows ? Может поможет снизить частоту возникновения проблем. Аос можно как консольное приложение запускать и прописать для него соответствующую совместимость.

[Logger]

А возможно что там на входе 64-битный счетчик типа аксаптовского \Classes\WinAPI\getTickCount64
(System.DateTime::get_Now())

который считает некие тики. Если это тики процессора, то переполняться может достаточно часто (кстати, если не ошибаюсь, то размер "тик"-а для System.DateTime зависит от версии .net - отсюда и зависимость частоты возникновения глюков от версии винды. Выше версия винды - более мелкий тик - чаще переполняется счетчик).

И возможно что значение этого счетчика трактуется в коде как беззнаковое целое, а используется знаковое целое и при переходе через максимальное целое нормально не обрабатывается при этом.
Получается что если TickStart был положительным целым, а TickFinish перемахнул в область отрицательных, то разница их по модулю всегда будет больше или равная чем 2^63 А само число будет всегда меньше или равно чем -2^63
Но больше не влезает в размерность числа, вот мы и получаем всегда -2^63

Если эти предположения верны, то можно попробовать пофиксить приложение, чтобы корректно обрабатывало такие случаи (где бы еще взять исходники. Хотя при определенном желании можно дизассемблировать и пересобрать).

Ну или заставить все это работать с меньше точностью (задействовать более старую версию дотнет или запустить в режиме совместимости со старой версией винды)