We have a solution to retrieve audit data from Dynamics 365 Customer Engagement. Since March 2019, we are running into quite some performance issue or timeout or error message in retrieving audit data. Please see end of post for some exception message details.
We are using RetrieveMultipleRequest and fetch XML to retrieve IDs for audit data and then retrieve details by using RetrieveAuditDetailsRequest based on those audit record IDs. Please see end of post for fetch XML. The first run would only have le condition (less than current timestamp) and subsequent runs would have gt and le for about 6 hours time range.
We used to have 500 as batch size for both ID and details retrieval, and audit retrieval was good. During Audit Details retrieval, we are getting TimeoutException ( we have 10 minute time out right now) or ObjectDisposedException ( see end of post for full stacks) even for small amount of records in some cases. We reduced the batch size for detailed record retrieval to 200 while keeping ID retrieval to 500 to reduce the load on CRM env, it seems that it helps.
In some run we have in customer Dynamics env, the retrieval rate is about 0.7 record/per second for various batch size ranging from 50 to 400. The performance is quite poor here.
Based on CRM on premise, here is the Audit table structure:
CREATE TABLE [dbo].[AuditBase](
[AttributeMask] [nvarchar](max) NULL,
[TransactionId] [uniqueidentifier] NOT NULL,
[Action] [int] NULL,
[ObjectId] [uniqueidentifier] NOT NULL,
[ObjectIdName] [nvarchar](1) NULL,
[UserId] [uniqueidentifier] NOT NULL,
[ChangeData] [nvarchar](max) NULL,
[CreatedOn] [datetime] NOT NULL,
[Operation] [int] NOT NULL,
[AuditId] [uniqueidentifier] NOT NULL,
[CallingUserId] [uniqueidentifier] NULL,
[ObjectTypeCode] [int] NULL,
[RegardingObjectId] [uniqueidentifier] NULL,
[RegardingObjectIdName] [nvarchar](4000) NULL,
[UserAdditionalInfo] [nvarchar](400) NULL
)
GO
ALTER TABLE [dbo].[AuditBase] ADD DEFAULT (newsequentialid()) FOR [AuditId]
Note that there is no key at all and the audit data for all entities would be stored in the same table. Plus we are retrieving the record with some gt and le condition, will CRM backup sort the records by “CreatedOn” as well? With sorting, the retrieval would definitely be slow although I am not sure what amount of data it is sorting internally.
Anyone could shed some lights on this?
[Update]: we tried by using a Fetch XML with less condition by followings the suggestions below in the answer, see below [Fetch XML 2], it won't help much either. Right now the performance bottleneck is not at Audit ID retrieval, rather the audit details retrieval.
Fetch XML:
<fetch no-lock='true'>
<entity name='audit'>
<filter type='and' >
<condition attribute='operation' operator='in' >
<value>2</value>
<value>3</value>
</condition>
<condition attribute='action' operator='not-in' >
<value>14</value>
<value>15</value>
<value>48</value>
<value>49</value>
<value>53</value>
<value>54</value>
<value>55</value>
<value>56</value>
<value>57</value>
<value>58</value>
<value>59</value>
<value>60</value>
<value>62</value>
<value>63</value>
<value>64</value>
<value>65</value>
<value>100</value>
<value>101</value>
<value>102</value>
<value>103</value>
<value>104</value>
<value>105</value>
<value>106</value>
<value>107</value>
<value>108</value>
<value>109</value>
<value>110</value>
<value>111</value>
<value>112</value>
<value>113</value>
</condition>
<condition attribute='objecttypecode' operator='eq' value='1' />
<condition attribute='createdon' operator='gt' value='2019-06-18T10:01:13.8571635Z' />
<condition attribute='createdon' operator='le' value='2019-06-18T16:00:53.9247159Z' />
</filter>
</entity>
</fetch>
Fetch XML 2:
<fetch no-lock='true'>
<entity name='audit'>
<attribute name='auditid' />
<filter type='and' >
<condition attribute='objecttypecode' operator='eq' value='1' />
<condition attribute='createdon' operator='gt' value='2020-01-18T16:01:13.8571635Z' />
<condition attribute='createdon' operator='le' value='2020-02-13T16:00:53.9247159Z' />
</filter>
</entity>
</fetch>
Exception 1:
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'System.ServiceModel.Security.TransportSecurityProtocol'.
Server stack trace:
at System.ServiceModel.Channels.CommunicationObject.ThrowIfClosedOrNotOpen()
at System.ServiceModel.Security.TransportSecurityProtocol.VerifyIncomingMessage(Message& message, TimeSpan timeout)
at System.ServiceModel.Security.SecurityProtocol.VerifyIncomingMessage(Message& message, TimeSpan timeout, SecurityProtocolCorrelationState[] correlationStates)
at System.ServiceModel.Channels.SecurityChannelFactory`1.SecurityRequestChannel.ProcessReply(Message reply, SecurityProtocolCorrelationState correlationState, TimeSpan timeout)
at System.ServiceModel.Channels.SecurityChannelFactory`1.SecurityRequestChannel.Request(Message message, TimeSpan timeout)
at System.ServiceModel.Dispatcher.RequestChannelBinder.Request(Message message, TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs, TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(IMethodCallMessage methodCall, ProxyOperationRuntime operation)
at System.ServiceModel.Channels.ServiceChannelProxy.Invoke(IMessage message)
Exception rethrown at [0]:
at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
at Microsoft.Xrm.Sdk.IOrganizationService.Execute(OrganizationRequest request)
Exception 2:
System.TimeoutException: The request channel timed out while waiting for a reply after 00:09:59.9990005. Increase the timeout value passed to the call to Request or increase the SendTimeout value on the Binding. The time allotted to this operation may have been a portion of a longer timeout. ---> System.TimeoutException: The HTTP request to 'https://xxx.dynamics.com/XRMServices/2011/Organization.svc' has exceeded the allotted timeout of 00:10:00. The time allotted to this operation may have been a portion of a longer timeout. ---> System.Net.WebException: The operation has timed out
at System.Net.HttpWebRequest.GetResponse()
at System.ServiceModel.Channels.HttpChannelFactory`1.HttpRequestChannel.HttpChannelRequest.WaitForReply(TimeSpan timeout)
--- End of inner exception stack trace ---
at System.ServiceModel.Channels.HttpChannelUtilities.ProcessGetResponseWebException(WebException webException, HttpWebRequest request, HttpAbortReason abortReason)
at System.ServiceModel.Channels.HttpChannelFactory`1.HttpRequestChannel.HttpChannelRequest.WaitForReply(TimeSpan timeout)
at System.ServiceModel.Channels.RequestChannel.Request(Message message, TimeSpan timeout)
--- End of inner exception stack trace ---
Server stack trace:
at System.ServiceModel.Channels.RequestChannel.Request(Message message, TimeSpan timeout)
at System.ServiceModel.Channels.SecurityChannelFactory`1.SecurityRequestChannel.Request(Message message, TimeSpan timeout)
at System.ServiceModel.Dispatcher.RequestChannelBinder.Request(Message message, TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs, TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(IMethodCallMessage methodCall, ProxyOperationRuntime operation)
at System.ServiceModel.Channels.ServiceChannelProxy.Invoke(IMessage message)
Exception rethrown at [0]:
at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
at Microsoft.Xrm.Sdk.IOrganizationService.Execute(OrganizationRequest request)
at Microsoft.Xrm.Sdk.Client.OrganizationServiceProxy.ExecuteCore(OrganizationRequest request)
at Microsoft.Xrm.Sdk.Client.OrganizationServiceProxy.Execute(OrganizationRequest request)
The number of conditions in that FetchXML might be contributing to the issue. My thoughts are:
See if you can enlist Microsoft Support to help you add custom indexes to ObjectTypeCode, Operation, Action, and CreatedOn, or perhaps a "covering index" for this particular query.
Narrow down the conditions considerably - see how it performs with only the ObjectTypeCode and CreatedOn conditions. Then do the additional filtering in memory. Yes, you'll retrieve more records, but the speed increase of filtering in RAM might be worth it.
You may also want to experiment with retrieving only certain columns, rather than the whole entity. One approach would be on the first pass to retrieve only the columns needed to do the filtering and page through those to get the ID's of the actual records you want. Then maybe page through the ID's and issue a Fetch with say 50 ID's at a time to retrieve the rest of the columns for those records.
In the interest of keeping the audit data set as small as possible, if you have any processes or apps that updating Account records, make sure they are updating only the necessary columns. If the audit history is showing a lot of unchanged data getting pushed back into the same fields, you may be able to update your code to pare down the fields that are getting updated.
Perhaps look into the option of exporting the audit data to SQL.