Is there an easy way to log or debug a performance issue with the BaqSvc for REST calls? I have a BAQ that takes around 100 ms to run in the Epicor client, according to the BAQ screen. The exact same BAQ with the same parameters takes 7-9 seconds to return using REST. Even running the call on the server that houses the app server it takes the same amount of time. Other similar BAQs take around 2 seconds on a REST call.
I tried the application server log, but that didn’t log anything.
Shotgunning here - problem only need one of the following so baby steps in diagnosing:
<add uri=“profile://system/db/hits” />
<add uri=“trace://ice/fw/BPM” />
<add uri=“trace://ice/fw/restapi” />
and for the mother of all traces:
<add uri=“profile://system/db/epiprovider/sqltext” />
The last one will shows you ever sql statement executed on behalf of the app server call. Make sure your log is set large enough. VERBOSE is an under statement.
Perfect, thanks. I forgot about the extra options. I was just going off what the Admin Console UI offered.
We keep on adding traces faster than we can add to the UI.
And … other reasons… SAFE HARBOR
…
I ended up adding everything to log since I’m in a test environment. Here is what I found.
There are three events in the log for one REST BaqSvc call.
The events look like this
TablesetEvent tsName=“BAQDesignerTableset” method=“AfterGetRows” duration="…"
The durations on all three events add up to 90-95% of the time to execute the operation. It is just under 3 full seconds on each event.
So the questions I’m looking into at the moment are why this executes 3 times and why does it take so long. This seems to be an operation executed after the query has run, at least I think. It running three times throws me off. We don’t have any custom field attributes on this query or specialized field security. I’ve inspected the execution plan, added an index, which reduced the time from 300 ms to 100 ms according to the BAQ Analyze tab. I don’t think the query is the problem. I’m leaning towards the complexity of the BAQ.
So this is definitely something to do with loading the BPM. The same thing is occurring when I try to load the BPM into the designer. It also takes the same amount of time as well. BTW, we’re on 10.1.600.latest. We’re upgrading to 10.2.latest over the weekend, so I think I’ll hold off and hopefully the upgrade takes care of it.
Hmm… I can think of some issues in 600 for web farms but other than that, would be interested in the details of those AfterGetRows.
Sorry. I put BPMs in the last post, I meant BAQ. In the BAQ designer it takes 9 seconds to load. In the REST call it takes 9 seconds to return. So it’s as if the REST call is performing the same steps as loading it in the BAQ designer.
How would I get you the details of the AfterGetRows? I can also send the BAQ. It’s not too special. There are a few joined tables and a subquery within the BAQ. It’s trying to recreate the information I would need to generate a pack out based on an order.
After the move to 10.2.200.latest, the performance didn’t improve. It’s still ~9 seconds to load the BPM and ~9 seconds to run the query through a REST call. I have the 10.2 server trace with everything turned on. Here are the AfterGetRows events (3 times for 1 call to pull the data)
[TablesetEvent tsName=“BAQDesignerTableset” method=“AfterGetRows” duration=“2821.291” /]
[TablesetEvent tsName=“BAQDesignerTableset” method=“AfterGetRows” duration=“2928.4152” /]
[TablesetEvent tsName=“BAQDesignerTableset” method=“AfterGetRows” duration=“2676.4502” /]
I ran a REST call using a different but similar BPM and it takes less than 2 seconds to complete. It’s something to do, I’m guessing, with the design layout of this BPM. These events happen after this entry in the server trace
[Sproc name="[Ice]._ZFW_BAQDesigner_GetByID" duration=“6.1203” /]
What’s the operation that the aftergetrows is in?
(Or just post the operation here?)
Here’s the full verbose logging details for this operation. The AfterGetRows are near the bottom.
[Op Utc=“2018-08-15T14:17:35.9920670Z” act="" dur=“8684.0179” cli="" usr="" machine=“SERVERNAME” pid=“2652” tid=“30”]
[Sql queries=“16” cacheHits=“11” time=“34.6421” qryTypeCount=“4” /]
[DataContext msg=“New DataContext ID:2272107c-6cec-4ad2-9732-5ec73f8dacc3 created on SPID:” /]
[EpiConnection oper=“Opened” spid=“60” /]
[Trigger msg=“Disabling SysUserFile” /]
[EFQueryCache count=“1146” /]
[EpiCommand hashCode=“4039218143737099188” queryType=“SELECT,SELECT,SELECT” spid=“60” table="[Ice].[SysLock]"]
[parameters]
[parameter name=“p__linq__0” type=“String”][![CDATA[]]][/parameter]
[parameter name=“p__linq__1” type=“String”][![CDATA[DataAdm]]][/parameter]
[/parameters][![CDATA[
SELECT
CASE WHEN ( EXISTS (SELECT
1 AS [C1]
FROM [Ice].[SysLock] AS [Extent1]
WHERE ([Extent1].[Company] = @p__linq__0) AND ([Extent1].[SysFunction] = @p__linq__1)
)) THEN cast(1 as bit) ELSE cast(0 as bit) END AS [C1]
FROM ( SELECT 1 AS X ) AS [SingleRowTable1]
]]][/EpiCommand]
[DBStatement type=“Boolean” duration=“0.8822” rowCount=“1” hashCode=“4039218143737099188” dbContextId=“2272107c-6cec-4ad2-9732-5ec73f8dacc3”]
[stackTrace]
[stackFrame method=“TResult Epicor.Data.DBExpressionCompiler.InvokeSingle(Expression expression, Cache currentCacheSetting, Boolean cacheQuery, TContext dataContext, Func2 getDataCacheKey, Func2 compileQuery, Func3 executeQuery)" module="Epicor.System.dll" file="C:\_Releases\ICE\ICE3.2.200.10\Source\Framework\Epicor.System\Data\DBExpressionCompiler.cs" line="311" /] [stackFrame method="TResult Epicor.Data.DBExpressionCompiler+<>c__DisplayClass34_04[TContext,TArg1,TArg2,TResult].<Compile>b__0(TContext context, TArg1 arg1, TArg2 arg2)” module=“Epicor.System.dll” file=“C:_Releases\ICE\ICE3.2.200.10\Source\Framework\Epicor.System\Data\DBExpressionCompiler.Generated.cs” line=“1110” /]
[stackFrame method=“Void Ice.Manager.Security.LogOn(IceContext dataContext, String userID, Guid sessionType)” module=“Epicor.Ice.dll” file=“C:_Releases\ICE\RL3.2.200.0\Source\Framework\Epicor.Ice\Manager\Security.cs” line=“504” /]
[stackFrame method=“Session Epicor.Hosting.CallContext.Create(Operation op)” module=“Epicor.Ice.dll” file=“C:_Releases\ICE\RL3.2.200.0\Source\Framework\Epicor.Ice\Hosting\CallContext.cs” line=“155” /]
[stackFrame method=“IPrincipal Ice.Security.RestApi.AuthHelper.CheckAccess(String headerScheme, String headerValue, IEnumerable1 customHeaders)" module="Epicor.Ice.dll" file="C:\_Releases\ICE\RL3.2.200.0\Source\Framework\Epicor.Ice\Security\RestAuthHelper.cs" line="47" /] [stackFrame method="IPrincipal Epicor.RESTApi.Security.IceSecurityChecker.MakeAuth(IOwinRequest request)" module="Epicor.RESTApi.dll" file="C:\_Releases\ICE\RL3.2.200.0\Source\Framework\Epicor.RESTApi\Security\CallAuth.cs" line="33" /] [stackFrame method="Task Epicor.RESTApi.ConfigureStartup+<>c__DisplayClass3_0.<ConfigureIceAuth>b__0(IOwinContext context, Func1 next)” module=“Epicor.RESTApi.dll” file=“C:_Releases\ICE\RL3.2.200.0\Source\Framework\Epicor.RESTApi\Startup.cs” line=“116” /]
[stackFrame method=“Void Microsoft.Owin.Cors.CorsMiddleware+<Invoke>d__0.MoveNext()” module=“Microsoft.Owin.Cors.dll” file="" line=“0” /]
[stackFrame method=“Void System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(TStateMachine& stateMachine)” module=“CommonLanguageRuntimeLibrary” file="" line=“0” /]
[stackFrame method=“Task Microsoft.Owin.Cors.CorsMiddleware.Invoke(IDictionary2 environment)" module="Microsoft.Owin.Cors.dll" file="" line="0" /] [stackFrame method="Void Microsoft.Owin.Mapping.MapWhenMiddleware+<Invoke>d__0.MoveNext()" module="Microsoft.Owin.dll" file="" line="0" /] [stackFrame method="Void System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(TStateMachine& stateMachine)" module="CommonLanguageRuntimeLibrary" file="" line="0" /] [stackFrame method="Task Microsoft.Owin.Mapping.MapWhenMiddleware.Invoke(IDictionary2 environment)” module=“Microsoft.Owin.dll” file="" line=“0” /]
[stackFrame method=“Void Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContextStage+<RunApp>d__5.MoveNext()” module=“Microsoft.Owin.Host.SystemWeb.dll” file="" line=“0” /]
[stackFrame method=“Void System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(TStateMachine& stateMachine)” module=“CommonLanguageRuntimeLibrary” file="" line=“0” /]
[stackFrame method=“Task Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContextStage.RunApp(Func2 entryPoint, IDictionary2 environment, TaskCompletionSource1 tcs, StageAsyncResult result)" module="Microsoft.Owin.Host.SystemWeb.dll" file="" line="0" /] [stackFrame method="IAsyncResult Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContextStage.BeginEvent(Object sender, EventArgs e, AsyncCallback cb, Object extradata)" module="Microsoft.Owin.Host.SystemWeb.dll" file="" line="0" /] [stackFrame method="Void System.Web.HttpApplication+AsyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()" module="System.Web.dll" file="" line="0" /] [stackFrame method="Void System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step)" module="System.Web.dll" file="" line="0" /] [stackFrame method="Exception System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)" module="System.Web.dll" file="" line="0" /] [stackFrame method="Void System.Web.HttpApplication+PipelineStepManager.ResumeSteps(Exception error)" module="System.Web.dll" file="" line="0" /] [stackFrame method="IAsyncResult System.Web.HttpApplication.BeginProcessRequestNotification(HttpContext context, AsyncCallback cb)" module="System.Web.dll" file="" line="0" /] [stackFrame method="RequestNotificationStatus System.Web.HttpRuntime.ProcessRequestNotificationPrivate(IIS7WorkerRequest wr, HttpContext context)" module="System.Web.dll" file="" line="0" /] [stackFrame method="Int32 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)" module="System.Web.dll" file="" line="0" /] [stackFrame method="Int32 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)" module="System.Web.dll" file="" line="0" /] [stackFrame method="Void System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr pHandler, RequestNotificationStatus& notificationStatus)" module="System.Web.dll" file="" line="0" /] [stackFrame method="Void System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr pHandler, RequestNotificationStatus& notificationStatus)" module="System.Web.dll" file="" line="0" /] [stackFrame method="Int32 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)" module="System.Web.dll" file="" line="0" /] [stackFrame method="Int32 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)" module="System.Web.dll" file="" line="0" /] [/stackTrace] [/DBStatement] [EFQueryCache count="1146" /] [DataContext msg="Enlisting in Transaction 91cd3799-de64-4984-8b7a-d0c957ca9120:465850, SPID:60" /] [EpiCommand hashCode="3820937654757427724" lockHints="UPDLOCK" queryType="SELECT" spid="60" table="[Ice].[SysUserFile]"] [parameters] [parameter name="p__linq__0" type="String"][![CDATA[username]]][/parameter] [/parameters][![CDATA[ SELECT TOP (1) [Extent1].[UserID] AS [UserID], [Extent1].[Password] AS [Password], [Extent1].[Name] AS [Name], [Extent1].[Address1] AS [Address1], [Extent1].[Address2] AS [Address2], [Extent1].[City] AS [City], [Extent1].[State] AS [State], [Extent1].[ZIP] AS [ZIP], [Extent1].[Country] AS [Country], [Extent1].[OfficePhone] AS [OfficePhone], [Extent1].[Phone] AS [Phone], [Extent1].[EMailAddress] AS [EMailAddress], [Extent1].[UserDisabled] AS [UserDisabled], [Extent1].[SecurityMgr] AS [SecurityMgr], [Extent1].[CanChangeSaveSettings] AS [CanChangeSaveSettings], [Extent1].[SaveSettings] AS [SaveSettings], [Extent1].[CurComp] AS [CurComp], [Extent1].[PwdLastChanged] AS [PwdLastChanged], [Extent1].[PwdExpiresDays] AS [PwdExpiresDays], [Extent1].[PwdExpires] AS [PwdExpires], [Extent1].[PwdGrace] AS [PwdGrace], [Extent1].[GroupList] AS [GroupList], [Extent1].[CompList] AS [CompList], [Extent1].[ViewFavoriteBar] AS [ViewFavoriteBar], [Extent1].[ViewMenuTree] AS [ViewMenuTree], [Extent1].[ViewStatusBar] AS [ViewStatusBar], [Extent1].[WinX] AS [WinX], [Extent1].[WinY] AS [WinY], [Extent1].[FavBarWidth] AS [FavBarWidth], [Extent1].[MenuTreeWidth] AS [MenuTreeWidth], [Extent1].[CurFolderSeq] AS [CurFolderSeq], [Extent1].[CurMenuID] AS [CurMenuID], [Extent1].[WinWidth] AS [WinWidth], [Extent1].[WinHeight] AS [WinHeight], [Extent1].[DispTips] AS [DispTips], [Extent1].[CanChangePassword] AS [CanChangePassword], [Extent1].[LangNameID] AS [LangNameID], [Extent1].[LastGraphType] AS [LastGraphType], [Extent1].[UseInternalWebBrowser] AS [UseInternalWebBrowser], [Extent1].[AllowMultipleSessions] AS [AllowMultipleSessions], [Extent1].[WebUser] AS [WebUser], [Extent1].[ListViewMode] AS [ListViewMode], [Extent1].[CanMaintainFavQueries] AS [CanMaintainFavQueries], [Extent1].[CanMaintainFavURLs] AS [CanMaintainFavURLs], [Extent1].[CanMaintainFavPrograms] AS [CanMaintainFavPrograms], [Extent1].[CanCustomize] AS [CanCustomize], [Extent1].[ViewTreeOnly] AS [ViewTreeOnly], [Extent1].[Timeout] AS [Timeout], [Extent1].[CanPersonalize] AS [CanPersonalize], [Extent1].[CanTranslate] AS [CanTranslate], [Extent1].[CanEditCompAnnotations] AS [CanEditCompAnnotations], [Extent1].[CanEditUserAnnotations] AS [CanEditUserAnnotations], [Extent1].[CanEditHelpLinks] AS [CanEditHelpLinks], [Extent1].[AutoStartMonitor] AS [AutoStartMonitor], [Extent1].[MonitorPollingInterval] AS [MonitorPollingInterval], [Extent1].[FormOpenMode] AS [FormOpenMode], [Extent1].[EntConType] AS [EntConType], [Extent1].[DashboardDeveloper] AS [DashboardDeveloper], [Extent1].[CanDesignQSearch] AS [CanDesignQSearch], [Extent1].[RequireSso] AS [RequireSso], [Extent1].[ViewStatusPanelUserID] AS [ViewStatusPanelUserID], [Extent1].[ViewStatusPanelLanguage] AS [ViewStatusPanelLanguage], [Extent1].[ViewStatusPanelCompany] AS [ViewStatusPanelCompany], [Extent1].[ViewStatusPanelPlant] AS [ViewStatusPanelPlant], [Extent1].[ViewStatusPanelServer] AS [ViewStatusPanelServer], [Extent1].[ViewStatusPanelWorkstationID] AS [ViewStatusPanelWorkstationID], [Extent1].[ServerNum] AS [ServerNum], [Extent1].[DomainName] AS [DomainName], [Extent1].[BPMAdvancedUser] AS [BPMAdvancedUser], [Extent1].[MaxGroupsFavorites] AS [MaxGroupsFavorites], [Extent1].[MaxGroupsSystemMenu] AS [MaxGroupsSystemMenu], [Extent1].[OSUserID] AS [OSUserID], [Extent1].[CanTheme] AS [CanTheme], [Extent1].[FormatCulture] AS [FormatCulture], [Extent1].[CanUseEntSearch] AS [CanUseEntSearch], [Extent1].[CanAccEpiEverywhere] AS [CanAccEpiEverywhere], [Extent1].[CanAcessMobile] AS [CanAcessMobile], [Extent1].[StartMenuClient] AS [StartMenuClient], [Extent1].[StartMenuEWA] AS [StartMenuEWA], [Extent1].[StartMenuMobile] AS [StartMenuMobile], [Extent1].[AdvBAQRights] AS [AdvBAQRights], [Extent1].[SecurityAccessOnly] AS [SecurityAccessOnly], [Extent1].[SolutionMgrCreate] AS [SolutionMgrCreate], [Extent1].[SolutionMgrInstall] AS [SolutionMgrInstall], [Extent1].[EntSearchURL] AS [EntSearchURL], [Extent1].[CanMaintQuickSearch] AS [CanMaintQuickSearch], [Extent1].[UseDefaultEntSearch] AS [UseDefaultEntSearch], [Extent1].[UserAccessOnly] AS [UserAccessOnly], [Extent1].[GlbCompSM] AS [GlbCompSM], [Extent1].[BAQXCompany] AS [BAQXCompany], [Extent1].[LastLogOnAttempt] AS [LastLogOnAttempt], [Extent1].[CanImpersonate] AS [CanImpersonate], [Extent1].[ViewStatusPanelSolutionID] AS [ViewStatusPanelSolutionID], [Extent1].[CanMaintPredictiveSearch] AS [CanMaintPredictiveSearch], [Extent1].[ViewESEPanel] AS [ViewESEPanel], [Extent1].[ESEUserID] AS [ESEUserID], [Extent1].[ESEPassword] AS [ESEPassword], [Extent1].[ThemeID] AS [ThemeID], [Extent1].[DisableTheming] AS [DisableTheming], [Extent1].[SysRevID] AS [SysRevID], [Extent1].[SysRowID] AS [SysRowID], [Extent1].[CanPublishLayout] AS [CanPublishLayout], [Extent1].[DefaultLayoutID] AS [DefaultLayoutID], [Extent1].[CanViewDocStar] AS [CanViewDocStar], [Extent1].[PwdChangeRequestOn] AS [PwdChangeRequestOn], [Extent1].[ExternalIdentity] AS [ExternalIdentity] FROM [Ice].[SysUserFile] AS [Extent1] WITH (UPDLOCK) WHERE [Extent1].[UserID] = @p__linq__0 ]]][/EpiCommand] [DBStatement type="SysUserFile" duration="4.7816" rowCount="1" hashCode="3820937654757427724" dbContextId="2272107c-6cec-4ad2-9732-5ec73f8dacc3"] [stackTrace] [stackFrame method="TResult Epicor.Data.DBExpressionCompiler.InvokeSingle(Expression expression, Cache currentCacheSetting, Boolean cacheQuery, TContext dataContext, Func2 getDataCacheKey, Func2 compileQuery, Func3 executeQuery)” module=“Epicor.System.dll” file=“C:_Releases\ICE\ICE3.2.200.10\Source\Framework\Epicor.System\Data\DBExpressionCompiler.cs” line=“0” /]
[stackFrame method=“TResult Epicor.Data.DBExpressionCompiler+<>c__DisplayClass33_03[TContext,TArg1,TResult].<Compile>b__0(TContext context, TArg1 arg1)" module="Epicor.System.dll" file="C:\_Releases\ICE\ICE3.2.200.10\Source\Framework\Epicor.System\Data\DBExpressionCompiler.Generated.cs" line="1082" /] [stackFrame method="Void Ice.Manager.Security.LogOn(IceContext dataContext, String userID, Guid sessionType)" module="Epicor.Ice.dll" file="C:\_Releases\ICE\RL3.2.200.0\Source\Framework\Epicor.Ice\Manager\Security.cs" line="514" /] [stackFrame method="Session Epicor.Hosting.CallContext.Create(Operation op)" module="Epicor.Ice.dll" file="C:\_Releases\ICE\RL3.2.200.0\Source\Framework\Epicor.Ice\Hosting\CallContext.cs" line="155" /] [stackFrame method="IPrincipal Ice.Security.RestApi.AuthHelper.CheckAccess(String headerScheme, String headerValue, IEnumerable1 customHeaders)” module=“Epicor.Ice.dll” file=“C:_Releases\ICE\RL3.2.200.0\Source\Framework\Epicor.Ice\Security\RestAuthHelper.cs” line=“47” /]
[stackFrame method=“IPrincipal Epicor.RESTApi.Security.IceSecurityChecker.MakeAuth(IOwinRequest request)” module=“Epicor.RESTApi.dll” file=“C:_Releases\ICE\RL3.2.200.0\Source\Framework\Epicor.RESTApi\Security\CallAuth.cs” line=“33” /]
[stackFrame method=“Task Epicor.RESTApi.ConfigureStartup+<>c__DisplayClass3_0.<ConfigureIceAuth>b__0(IOwinContext context, Func1 next)" module="Epicor.RESTApi.dll" file="C:\_Releases\ICE\RL3.2.200.0\Source\Framework\Epicor.RESTApi\Startup.cs" line="116" /] [stackFrame method="Void Microsoft.Owin.Cors.CorsMiddleware+<Invoke>d__0.MoveNext()" module="Microsoft.Owin.Cors.dll" file="" line="0" /] [stackFrame method="Void System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(TStateMachine& stateMachine)" module="CommonLanguageRuntimeLibrary" file="" line="0" /] [stackFrame method="Task Microsoft.Owin.Cors.CorsMiddleware.Invoke(IDictionary2 environment)” module=“Microsoft.Owin.Cors.dll” file="" line=“0” /]
[stackFrame method=“Void Microsoft.Owin.Mapping.MapWhenMiddleware+<Invoke>d__0.MoveNext()” module=“Microsoft.Owin.dll” file="" line=“0” /]
[stackFrame method=“Void System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(TStateMachine& stateMachine)” module=“CommonLanguageRuntimeLibrary” file="" line=“0” /]
[stackFrame method=“Task Microsoft.Owin.Mapping.MapWhenMiddleware.Invoke(IDictionary2 environment)" module="Microsoft.Owin.dll" file="" line="0" /] [stackFrame method="Void Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContextStage+<RunApp>d__5.MoveNext()" module="Microsoft.Owin.Host.SystemWeb.dll" file="" line="0" /] [stackFrame method="Void System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(TStateMachine& stateMachine)" module="CommonLanguageRuntimeLibrary" file="" line="0" /] [stackFrame method="Task Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContextStage.RunApp(Func2 entryPoint, IDictionary2 environment, TaskCompletionSource1 tcs, StageAsyncResult result)” module=“Microsoft.Owin.Host.SystemWeb.dll” file="" line=“0” /]
[stackFrame method=“IAsyncResult Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContextStage.BeginEvent(Object sender, EventArgs e, AsyncCallback cb, Object extradata)” module=“Microsoft.Owin.Host.SystemWeb.dll” file="" line=“0” /]
[stackFrame method=“Void System.Web.HttpApplication+AsyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()” module=“System.Web.dll” file="" line=“0” /]
[stackFrame method=“Void System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step)” module=“System.Web.dll” file="" line=“0” /]
[stackFrame method=“Exception System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)” module=“System.Web.dll” file="" line=“0” /]
[stackFrame method=“Void System.Web.HttpApplication+PipelineStepManager.ResumeSteps(Exception error)” module=“System.Web.dll” file="" line=“0” /]
[stackFrame method=“IAsyncResult System.Web.HttpApplication.BeginProcessRequestNotification(HttpContext context, AsyncCallback cb)” module=“System.Web.dll” file="" line=“0” /]
[stackFrame method=“RequestNotificationStatus System.Web.HttpRuntime.ProcessRequestNotificationPrivate(IIS7WorkerRequest wr, HttpContext context)” module=“System.Web.dll” file="" line=“0” /]
[stackFrame method=“Int32 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)” module=“System.Web.dll” file="" line=“0” /]
[stackFrame method=“Int32 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)” module=“System.Web.dll” file="" line=“0” /]
[stackFrame method=“Void System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr pHandler, RequestNotificationStatus& notificationStatus)” module=“System.Web.dll” file="" line=“0” /]
[stackFrame method=“Void System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr pHandler, RequestNotificationStatus& notificationStatus)” module=“System.Web.dll” file="" line=“0” /]
[stackFrame method=“Int32 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)” module=“System.Web.dll” file="" line=“0” /]
[stackFrame method=“Int32 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)” module=“System.Web.dll” file="" line=“0” /]
[/stackTrace]
[/DBStatement]
[EpiCommand queryType=“UPDATE,SELECT” spid=“60” table="[Ice].[SysUserFile],[Ice].[SysUserFile]"]
[parameters]
[parameter name="@0" type=“DateTime2”][![CDATA[8/15/2018 7:17:36 AM]]][/parameter]
[parameter name="@1" type=“Guid”][![CDATA[6867ca17-479c-49d7-8874-70d9cbb62274]]][/parameter]
[/parameters][![CDATA[
UPDATE [Ice].[SysUserFile]
SET [LastLogOnAttempt] = @0
WHERE ([SysRowID] = @1)
SELECT [SysRevID]
FROM [Ice].[SysUserFile]
WHERE @@ROWCOUNT ] 0 AND [SysRowID] = @1
]]][/EpiCommand]
[Trigger msg=“Enabling SysUserFile” /]
[EpiConnection oper=“Disposed” spid=“60” /]
[SessionSetting msg=“SessionID changed from ‘00000000-0000-0000-0000-000000000000’ to ‘c26c8243-46b2-4505-bf8e-731c06ca88d8’” /]
[Session msg=“New ErpSession created: c26c8243-46b2-4505-bf8e-731c06ca88d8 for User: in Company: " /]
[SessionSetting msg=“SessionType changed from ‘00000000-0000-0000-0000-000000000000’ to ‘00000003-b615-4300-957b-34956697f040’” /]
[SessionSetting msg=“UserID changed from ‘null’ to ‘username’” /]
[SessionSetting msg=“Timeout changed from ‘0’ to ‘900’” /]
[SessionSetting msg=“CompanyID changed from ‘null’ to ‘COMPANYNAME’” /]
[Session msg=“Changing from Company: to new Company:COMPANYNAME for Session:c26c8243-46b2-4505-bf8e-731c06ca88d8” /]
[SessionSetting msg=“CompanyName changed from ‘null’ to ‘TEST 20180802’” /]
[SessionSetting msg=“PlantID changed from ‘null’ to ‘MfgSys’” /]
[SessionSetting msg=“InstallationID changed from ‘00000000-0000-0000-0000-000000000000’ to ‘f162fb27-07a2-4a85-a0da-e739a2fe683f’” /]
[SessionSetting msg=“SolutionID changed from ‘null’ to ‘’” /]
[SessionSetting msg=“CountryCode changed from ‘null’ to ‘US’” /]
[SessionSetting msg=“CountryGroupCode changed from ‘null’ to ‘’” /]
[Session msg=“Changing from Company:COMPANYNAME to new Company:COMPANYNAME for Session:c26c8243-46b2-4505-bf8e-731c06ca88d8” /]
[SessionSetting msg=“LastAccessed changed from ‘1/1/0001 12:00:00 AM’ to ‘8/15/2018 2:17:00 PM’” /]
[Session msg=“Refreshing last accessed time on SessionID: c26c8243-46b2-4505-bf8e-731c06ca88d8. LastAccessed: 8/15/2018 2:17:00 PM” /]
[SessionSetting msg=“LicenseExpirationTime changed from ‘1/1/0001 12:00:00 AM’ to ‘8/15/2018 2:32:00 PM’” /]
[SessionSetting msg=“FormatCultureName changed from ‘null’ to ‘en-US’” /]
[DataContext msg=“New DataContext ID:35560ef4-c28b-4ae6-9732-4192e4dbba3e created on SPID:” /]
[EpiConnection oper=“Opened” spid=“60” /]
[ContextBound name=“Ice.Services.BO.DynamicQuerySvcFacade” contextid=“35560ef4-c28b-4ae6-9732-4192e4dbba3e” defaultcontext=“False” /]
[ContextBound name=“Ice.Services.BO.DynamicQuerySvc” contextid=“35560ef4-c28b-4ae6-9732-4192e4dbba3e” defaultcontext=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.0011” root=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.0378” root=“False” /]
[ContextBound name=“Ice.Services.BO.BAQDesignerSvcFacade” contextid=“35560ef4-c28b-4ae6-9732-4192e4dbba3e” defaultcontext=“False” /]
[ContextBound name=“Ice.Services.BO.BAQDesignerSvc” contextid=“35560ef4-c28b-4ae6-9732-4192e4dbba3e” defaultcontext=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.0011” root=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.0275” root=“False” /]
[Sproc name=”[Ice]._ZFW_BAQDesigner_GetByID" duration=“5.2865” /]
[TablesetEvent tsName=“BAQDesignerTableset” method=“AfterGetRows” duration=“2949.3801000000003” /]
[RowCount tableset=“BAQDesignerTableset” count=“447” /]
[ContextBound name=“Ice.Services.BO.DynamicQuerySvcFacade” contextid=“35560ef4-c28b-4ae6-9732-4192e4dbba3e” defaultcontext=“False” /]
[ContextBound name=“Ice.Services.BO.DynamicQuerySvc” contextid=“35560ef4-c28b-4ae6-9732-4192e4dbba3e” defaultcontext=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.0015” root=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.0145” root=“False” /]
[ContextBound name=“Ice.Services.BO.BAQDesignerSvcFacade” contextid=“35560ef4-c28b-4ae6-9732-4192e4dbba3e” defaultcontext=“False” /]
[ContextBound name=“Ice.Services.BO.BAQDesignerSvc” contextid=“35560ef4-c28b-4ae6-9732-4192e4dbba3e” defaultcontext=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.0007” root=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.0122” root=“False” /]
[Sproc name="[Ice]._ZFW_BAQDesigner_GetByID" duration=“10.7445” /]
[RowEvent table=“QueryFieldDesigner”
method=“AfterGetRows” rows=“72” duration=“0.0114” /]
[TablesetEvent tsName=“BAQDesignerTableset” method=“AfterGetRows” duration=“2737.0253000000002” /]
[RowCount tableset=“BAQDesignerTableset” count=“447” /]
[EpiConnection oper=“Disposed” spid=“60” /]
[DataContext msg=“New DataContext ID:824597df-1e44-4be1-85af-8cbc5f722a76 created on SPID:” /]
[EpiConnection oper=“Opened” spid=“60” /]
[ContextBound name=“Ice.Services.BO.DynamicQuerySvcFacade” contextid=“824597df-1e44-4be1-85af-8cbc5f722a76” defaultcontext=“False” /]
[ContextBound name=“Ice.Services.BO.DynamicQuerySvc” contextid=“824597df-1e44-4be1-85af-8cbc5f722a76” defaultcontext=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.0039000000000000003” root=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.076800000000000007” root=“True” /]
[ContextBound name=“Ice.Services.BO.BAQDesignerSvcFacade” contextid=“824597df-1e44-4be1-85af-8cbc5f722a76” defaultcontext=“False” /]
[ContextBound name=“Ice.Services.BO.BAQDesignerSvc” contextid=“824597df-1e44-4be1-85af-8cbc5f722a76” defaultcontext=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.0023” root=“False” /]
[Trace uri=“trace://ice/fw/perf/Initialize” duration=“0.061000000000000006” root=“False” /]
[Sproc name="[Ice]._ZFW_BAQDesigner_GetByID" duration=“12.9473” /]
[TablesetEvent tsName=“BAQDesignerTableset” method=“AfterGetRows” duration=“2790.9251” /]
[RowCount tableset=“BAQDesignerTableset” count=“447” /]
[BAQ QueryID=“BAQQueryName” /]
[BAQ Company=“COMPANYNAME” /]
[DataContext msg=“New DataContext ID:bf055cb1-e619-4ef1-8595-8d100f80d00f created on SPID:” /]
[EpiConnection oper=“Opened” spid=“164” /]
[EpiConnection oper=“Disposed” spid=“164” /]
[DataContext msg=“New DataContext ID:6385a620-5b6a-45b3-bf48-d7b1ddeeee6a created on SPID:” /]
[EpiConnection oper=“Opened” spid=“164” /]
[EpiConnection oper=“Disposed” spid=“164” /]
[DataContext msg=“New DataContext ID:4f664f39-2366-4216-8f25-3ad14f7969f3 created on SPID:” /]
[EpiConnection oper=“Opened” spid=“163” /]
[EpiConnection oper=“Disposed” spid=“163” /]
[DataContext msg=“New DataContext ID:566e4330-383b-4531-95d5-d876293dece0 created on SPID:” /]
[EpiConnection oper=“Opened” spid=“163” /]
[EpiConnection oper=“Disposed” spid=“163” /]
[DataContext msg=“New DataContext ID:f9a4b77a-da09-44ab-9211-ac640cc8819b created on SPID:” /]
[EpiConnection oper=“Opened” spid=“163” /]
[EpiConnection oper=“Disposed” spid=“163” /]
[DataContext msg=“New DataContext ID:d07f178f-5fe0-4e4a-8388-0b794798cb45 created on SPID:” /]
[EpiConnection oper=“Opened” spid=“164” /]
[EpiConnection oper=“Disposed” spid=“164” /]
[DataContext msg=“New DataContext ID:0c3529b1-e14d-4f73-b179-8d7d9f2d497d created on SPID:” /]
[EpiConnection oper=“Opened” spid=“164” /]
[EpiConnection oper=“Disposed” spid=“164” /]
[DataContext msg=“New DataContext ID:ac95d075-2f9c-4e43-96e3-038994d84f18 created on SPID:” /]
[EpiConnection oper=“Opened” spid=“163” /]
[EpiConnection oper=“Disposed” spid=“163” /]
[DataContext msg=“New DataContext ID:a2ca8e35-844d-44f4-8be5-5daadcaa473b created on SPID:” /]
[EpiConnection oper=“Opened” spid=“163” /]
[EpiConnection oper=“Disposed” spid=“163” /]
[DataContext msg=“New DataContext ID:dc8e352d-d95c-4ad5-8560-93cf4bf858c4 created on SPID:” /]
[EpiConnection oper=“Opened” spid=“163” /]
[EpiConnection oper=“Disposed” spid=“163” /]
[DataContext msg=“New DataContext ID:b2420b53-a905-4977-9d05-5fc0e4d26a53 created on SPID:” /]
[EpiConnection oper=“Opened” spid=“163” /]
[EpiConnection oper=“Disposed” spid=“163” /]
[BAQ SQLExecTime=“111.3852” /]
[BAQ DataFetchTime=“0.4277” /]
[BAQ TotalTime=“155.2636” /]
[BAQ TotalRows=“0” /]
[Session msg=“Skipping session save, no updates: c26c8243-46b2-4505-bf8e-731c06ca88d8” /]
[EpiConnection oper=“Disposed” spid=“60” /]
[Expression hc=“3820937654757427724”][![CDATA[(ctx, userID_ex) =] Queryable.FirstOrDefault(Queryable.Where(
WithExtension.With(
ctx.SysUserFile,
UpdLock
),
row =] row.UserID == userID_ex
))]]][/Expression]
[Expression hc=“4039218143737099188”][![CDATA[(ctx, company_ex, sysFunction_ex) =] Queryable.Any(Queryable.Where(
ctx.SysLock,
row =] row.Company == company_ex && row.SysFunction == sysFunction_ex
))]]][/Expression]
[/Op]
every time the BAQ is called, it first creates model to know how to process ODATA-specific settings. and then it calls query itself. That is why you see several AfterGetRows.
We cache model for services as they cannot change, but we cannot do this for BAQ, because you can go to BAQ designer and update its definition and REST won’t know about it.
That makes sense. Could you cache the BAQ model on a BAQ Update? I’m hoping to reduce the time it takes for the AfterGetRows. If I can do that, then the model caching question isn’t as relevant.
I took the generated sql from the BAQ, made a view, and created an external BAQ. Calling the external BAQ using REST takes 300 milliseconds. I can move forward with this, but it would be interesting to see why this BAQ takes so long.
Performance ticket please 
I’m seeing 2 seconds for a baqsvc GET request running on the server where IIS / app server is hosted. In BAQ designer the same query with same parameters executes in 97 ms per the execution message. It sounds like @stephen_booth directly queried the DB and went from 9 second to 300 ms…
I would think if this is the type of performance others are seeing there are probably a lot of people making direct calls to the DB(having a user wait for 2 seconds per query is a pretty poor UX). Are others seeing GET requests of baqsvc take this long?
This was an issue in an older version. It was fixed at some point. I don’t remember which version. What are you running?
Fixed as of (at least) 10.2.200.14
We’re running 10.2.400.5.
What do you see in practice(I’d hope 500ms or less for a simple BAQ)?
We’re seeing comparable performance between our direct queries and our BAQs. I’m an old time SQL Server guy (since SQL Server 6.5). When I’m dealing with queries we use in our entire ERP structure, I go with a BAQ. It’s slightly slower, naturally, but not obvious to our customers, and the slight performance hit is well worth the extra benefits Epicor brings (injection detection, data level security, etc.). We have windows services and outside web applications that query the data we have in Epicor, and we use a BAQ, instead of a direct query, to access them. So we’re sold on BAQ performance as it currently stands.
If you’re seeing a significant difference I would suggest looking at the server trace log and see exactly where it is hanging up.