Sales Order with thousands of Releases

jhecker · December 13, 2023, 3:29pm

We have a sales order with 87 Lines, and 9,706 releases spread out among all of those lines.

When we load that Sales Order in the Sales Order Entry screen, it takes between 45-55 seconds to load.

When we try to Close or Reopen a release, sometimes it works, however we are receiving this error very frequently (this pops up after the 180 second timeout period is reached):

Server Side Exception
A server error occurred. Review the server event logs for details.
Exception caught in: Epicor.ServiceModel

Error Detail 
============
Description:  A server error occurred. Review the server event logs for details.
Program:  Epicor.System.dll
Method:  ProvideFault
Line Number:  32
Column Number:  13
Server Trace Stack:     at Epicor.Hosting.Wcf.ErrorHandler.ProvideFault(Exception error, MessageVersion version, Message& fault) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Hosting\Wcf\ErrorHandler.cs:line 32
   at System.ServiceModel.Dispatcher.ErrorBehavior.ProvideFault(Exception e, FaultConverter faultConverter, ErrorHandlerFaultInfo& faultInfo)
   at System.ServiceModel.Dispatcher.ErrorBehavior.ProvideMessageFaultCore(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage8(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.MessageRpc.ProcessError(Exception e)
   at System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean isOperationContextSet)
   at System.ServiceModel.Dispatcher.ChannelHandler.DispatchAndReleasePump(RequestContext request, Boolean cleanThread, OperationContext currentOperationContext)
   at System.ServiceModel.Dispatcher.ChannelHandler.HandleRequest(RequestContext request, OperationContext currentOperationContext)
   at System.ServiceModel.Dispatcher.ChannelHandler.AsyncMessagePump(IAsyncResult result)
   at System.ServiceModel.Dispatcher.ChannelHandler.OnAsyncReceiveComplete(IAsyncResult result)
   at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
   at System.Runtime.AsyncResult.Complete(Boolean completedSynchronously)
   at System.ServiceModel.Channels.SecurityChannelListener`1.ReceiveItemAndVerifySecurityAsyncResult`2.InnerTryReceiveCompletedCallback(IAsyncResult result)
   at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
   at System.Runtime.AsyncResult.Complete(Boolean completedSynchronously)
   at System.ServiceModel.Channels.TransportDuplexSessionChannel.TryReceiveAsyncResult.OnReceive(IAsyncResult result)
   at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
   at System.Runtime.AsyncResult.Complete(Boolean completedSynchronously)
   at System.ServiceModel.Channels.SynchronizedMessageSource.ReceiveAsyncResult.OnReceiveComplete(Object state)
   at System.ServiceModel.Channels.SessionConnectionReader.OnAsyncReadComplete(Object state)
   at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
   at System.Net.LazyAsyncResult.Complete(IntPtr userToken)
   at System.Net.LazyAsyncResult.ProtectedInvokeCallback(Object result, IntPtr userToken)
   at System.Net.Security.NegotiateStream.ProcessFrameBody(Int32 readBytes, Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.NegotiateStream.ReadCallback(AsyncProtocolRequest asyncRequest)
   at System.Net.AsyncProtocolRequest.CompleteRequest(Int32 result)
   at System.Net.FixedSizeReader.CheckCompletionBeforeNextRead(Int32 bytes)
   at System.Net.FixedSizeReader.ReadCallback(IAsyncResult transportResult)
   at System.Runtime.AsyncResult.Complete(Boolean completedSynchronously)
   at System.ServiceModel.Channels.ConnectionStream.IOAsyncResult.OnAsyncIOComplete(Object state)
   at System.Net.Sockets.SocketAsyncEventArgs.OnCompleted(SocketAsyncEventArgs e)
   at System.Net.Sockets.SocketAsyncEventArgs.FinishOperationSuccess(SocketError socketError, Int32 bytesTransferred, SocketFlags flags)
   at System.Net.Sockets.SocketAsyncEventArgs.CompletionPortCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped)
   at System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pOVERLAP)


Client Stack Trace 
==================
   at Epicor.ServiceModel.Channels.ImplBase`1.ShouldRethrowNonRetryableException(Exception ex, DataSet[] dataSets)
   at Erp.Proxy.BO.SalesOrderImpl.CloseRelease(Int32 iOrderNum, Int32 iOrderLine, Int32 iOrderRelNum)
   at Erp.Adapters.SalesOrderAdapter.CloseRelease(Int32 iOrderNum, Int32 iOrderLine, Int32 iOrderRelNum)

At the same time, the following error appears in the Event Viewer under Epicor App Server:

System.Data.Entity.Core.EntityCommandExecutionException: An error occurred while reading from the store provider's data reader. See the inner exception for details. ---> System.Data.SqlClient.SqlException: Lock request time out period exceeded.
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at System.Data.SqlClient.SqlDataReader.TryHasMoreRows(Boolean& moreRows)
   at System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)
   at System.Data.SqlClient.SqlDataReader.Read()
   at System.Data.Entity.Core.Common.Internal.Materialization.Shaper`1.StoreRead()
   --- End of inner exception stack trace ---
   at System.Data.Entity.Core.Common.Internal.Materialization.Shaper`1.HandleReaderException(Exception e)
   at System.Data.Entity.Core.Common.Internal.Materialization.Shaper`1.StoreRead()
   at System.Data.Entity.Core.Common.Internal.Materialization.Shaper`1.SimpleEnumerator.MoveNext()
   at System.Linq.Enumerable.FirstOrDefault[TSource](IEnumerable`1 source)
   at System.Data.Entity.Core.Objects.CompiledQuery.ExecuteQuery[TResult](ObjectContext context, Object[] parameterValues)
   at System.Data.Entity.Core.Objects.CompiledQuery.Invoke[TArg0,TArg1,TArg2,TResult](TArg0 arg0, TArg1 arg1, TArg2 arg2)
   at Epicor.Data.DBExpressionCompiler.GetResult[TDataContext,TQuery,TResult](Func`3 executeQuery, Cache cacheSetting, TDataContext dataContext, TQuery query) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Data\DBExpressionCompiler.cs:line 445
   at Epicor.Data.DBExpressionCompiler.InvokeSingle[TDataContext,TQuery,TResult](Expression expression, Cache currentCacheSetting, Boolean cacheQuery, TDataContext dataContext, Func`2 getDataCacheKey, Func`2 compileQuery, Func`3 executeQuery) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Data\DBExpressionCompiler.cs:line 306
   at Epicor.Data.DBExpressionCompiler.<>c__DisplayClass34_0`4.<Compile>b__0(TContext context, TArg1 arg1, TArg2 arg2) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Data\DBExpressionCompiler.Generated.cs:line 1110
   at Erp.Triggers.OrderDtl.WriteTrigger.write(OrderDtl NewOrderDtl, OrderDtl OldOrderDtl) in C:\_Releases\ERP\UD10.2.400.22\Source\Server\Db\Triggers\OrderDtl\write.cs:line 202
   at Erp.Triggers.OrderDtl.WriteTrigger.Write(OrderDtl NewOrderDtl, OrderDtl OldOrderDtl) in C:\_Releases\ERP\UD10.2.400.22\Source\Server\Db\Triggers\OrderDtl\write.cs:line 189
   at Ice.DataTrigger`2.Ice.ILinqTrigger.Write(LinqRow newRecord, LinqRow oldRecord) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.Ice\Triggers\TriggerBase.cs:line 22
   at Ice.Triggers.TriggerQueue.ExecuteWriteTrigger(IceDataContext context, LinqRow modifiedRecord, LinqRow originalRecord) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 303
   at Ice.Triggers.TriggerQueue.RunWriteTriggerInNewLevel(IceDataContext context, LinqRow modifiedRecord, LinqRow originalRecord, Boolean forAddedRow) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 164
   at Ice.Triggers.TriggerQueue.<>c__DisplayClass11_0.<RunWriteTrigger>b__1() in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 155
   at Ice.Triggers.TriggerQueue.RunAtNewLevel(Func`1 buildTriggerRunState, Action action) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 508
   at Ice.Triggers.TriggerQueue.RunTriggers(IceDataContext context) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 90
   at Ice.IceDataContext.RunUntilAllTriggersHaveExecuted() in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Data\IceDataContext.cs:line 580
   at Ice.Triggers.TriggerQueue.RunAtNewLevel(Func`1 buildTriggerRunState, Action action) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 508
   at Ice.IceDataContext.Validate[TLinqRow](TLinqRow row) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Data\IceDataContext.cs:line 337
   at Ice.IceDataContext.Release[TEntity](TEntity& entity) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Data\IceDataContext.cs:line 277
   at Erp.Internal.Lib.OrderRelWrite.Write_OrderRel(OrderRel NewOrderRel, OrderRel OldOrderRel) in C:\_Releases\ERP\UD10.2.400.22\Source\Server\Internal\Lib\OrderRelShared\OrderRelWrite\OrderRelWrite.i.cs:line 1241
   at Erp.Triggers.OrderRel.WriteTrigger.Write(OrderRel OrderRel, OrderRel OldOrderRel) in C:\_Releases\ERP\ERP10.2.400.0\Source\Server\Db\Triggers\OrderRel\write.cs:line 210
   at Ice.DataTrigger`2.Ice.ILinqTrigger.Write(LinqRow newRecord, LinqRow oldRecord) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.Ice\Triggers\TriggerBase.cs:line 22
   at Ice.Triggers.TriggerQueue.ExecuteWriteTrigger(IceDataContext context, LinqRow modifiedRecord, LinqRow originalRecord) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 303
   at Ice.Triggers.TriggerQueue.RunWriteTriggerInNewLevel(IceDataContext context, LinqRow modifiedRecord, LinqRow originalRecord, Boolean forAddedRow) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 164
   at Ice.Triggers.TriggerQueue.<>c__DisplayClass11_0.<RunWriteTrigger>b__1() in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 155
   at Ice.Triggers.TriggerQueue.RunAtNewLevel(Func`1 buildTriggerRunState, Action action) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 508
   at Ice.Triggers.TriggerQueue.RunTriggers(IceDataContext context) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 90
   at Ice.IceDataContext.RunUntilAllTriggersHaveExecuted() in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Data\IceDataContext.cs:line 580
   at Ice.Triggers.TriggerQueue.RunAtNewLevel(Func`1 buildTriggerRunState, Action action) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Triggers\TriggerQueue.cs:line 508
   at Ice.IceDataContext.Validate[TLinqRow](TLinqRow row) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Data\IceDataContext.cs:line 337
   at Ice.IceDataContext.Release[TEntity](TEntity& entity) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Data\IceDataContext.cs:line 277
   at Erp.Services.BO.SalesOrderSvc.CloseRelease(Int32 iOrderNum, Int32 iOrderLine, Int32 iOrderRelNum) in C:\_Releases\ERP\UD10.2.400.22\Source\Server\Services\BO\SalesOrder\SalesOrder.cs:line 13173
   at Erp.Services.BO.SalesOrderSvcFacade.CloseRelease(Int32 iOrderNum, Int32 iOrderLine, Int32 iOrderRelNum) in C:\_Releases\ERP\UD10.2.400.22\Source\Server\Services\BO\SalesOrder\SalesOrderSvcFacade.cs:line 4680
   at SyncInvokeCloseRelease(Object , Object[] , Object[] )
   at System.ServiceModel.Dispatcher.SyncMethodInvoker.Invoke(Object instance, Object[] inputs, Object[]& outputs)
   at Epicor.Hosting.OperationBoundInvoker.InnerInvoke(Object instance, Func`2 func) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Hosting\OperationBoundInvoker.cs:line 59
   at Epicor.Hosting.OperationBoundInvoker.Invoke(Object instance, Func`2 func) in C:\_Releases\ICE\ICE3.2.400.22\Source\Framework\Epicor.System\Hosting\OperationBoundInvoker.cs:line 28

Epicor is telling us that it is the size of the Sales Order that is causing the issue, stating that 87 lines with a over 9,500 Releases is too much for Epicor to handle. Personally, I find that hard to believe. Blanket orders exist for a reason, and Epicor not being able to handle one seems a tad far-fetched.

Is anyone here able to point me in the right direction to figure out why it is taking over 3 minutes to change a release from Open to Closed for this Sales Order?

No, this does not happen on smaller Sales orders. Just the handful of really big ones we have.

timshuwy · December 13, 2023, 3:33pm

You might try this out in the latest version of Kinetic using the new browser based UI. The reason is that in Browser based, we also defer loading all records until you scroll down to get more. This MIGHT be activated in sales order releases (but I am not positive).

jhecker · December 13, 2023, 3:46pm

I don’t have access to the latest version of Kinetic at the moment. We have 10.2.400.22 on-prem. But, for grins-n-giggles I did try to load it up in a browser session, and was greeted with this when opening the SO:

timshuwy · December 13, 2023, 5:00pm

probably not the best test since that is an old version before we optimized things.

Banderson · December 13, 2023, 5:04pm

Did you try to uncheck the “Ready to process” check box? This affects the booking table, and avalara if you use it. (it won’t recalculate taxes without it). But if you don’t use those things, it might speed things up.

utaylor · December 13, 2023, 5:28pm

We have the same exact requirement @jhecker and @klincecum helped collaborate on a thread: Sales Order Testing - Adding Bulk Releases - Kinetic 202X - Epicor User Help Forum (epiusers.help)

check that out like @timshuwy had said.

I also talked to Six S and they alluded to some type of tooling created by Epicor to help with the loading of massive amounts of releases (something custom not shipped with Kinetic). Obviously it’s by their customization group so you’ll need to pay for it and it may not be exactly what you need so you’ll need to tweak it further. If you want me to connect you with the people I was talking to let me know. I never proceeded with the conversations because I got pulled away to work on something else, but we are 1000% interested in a way to do what you are doing with 1000s of releases and not see this slowness.

Shoot, if you want to split the cost between our companies so we each get a tool to load and maintain thousands of releases on an order maybe we could unite!

timshuwy · December 13, 2023, 5:45pm

I think there are two different definitions of “load” here…

Load (as in “add” is what the first post for Adding Bulk Releases"
Load (as in Recall to the screen) is what this current post seems to be referring to.

Both cases should be addressed. In the first, it is simply the amount of time to add this big of an order into the system. after each new line and new release, there is effort by the computer to update the header and detail records. In that case, turning off the “ready to calculate” made a big difference because now the system didn’t recalculate the entire order’s sales tax after every change.

in THIS question, it is about how long it takes to load the on order, 87 line items, and 9500 releases, and all the associated data (part data, customer data, shipto data, etc.
It would be interesting to run a trace on this load to find out how much data is transported when loading all this data. I would imagine it is a significant amount of data. If there is only 1k per record, that adds up to almost 10 MB, but that isnt counting all the associated data.

jhecker · December 13, 2023, 7:19pm

I ran a Trace and wrote the full datasets and response data, which comes out to 127MB. Now I am sure that the App Server is not sending 127MB as plain text over the wire to the Client, but even as serialized datasets it is probably going to be a fairly significant size.

Mark_Wonsil · December 13, 2023, 7:44pm

Try Again Are You Crazy GIF by Aurora Consulting - SBA EIDL Experts

timshuwy · December 13, 2023, 7:50pm

OK… this is a distraction… but…
My first “real” mini-computer had a 90 MB CDC Phoenix disk drive… had a blazing speed backup system that you could backup one 15 MB Platter at a time (fixed platter to removable platter), in 20 minutes IF you shut down all other applications from using the drive while the backup was in process.
Very few (if any) of the Phoenix drives exist today because of their ability to have a “Head Crash” by just looking at them funny. There were three fixed platters, and one removable platter… each time you removed the platter, you had to let it “purge” all the dust off the platter. If you didn’t the dust could cause the head crash. Since all the platters shared the same airspace, the crash on the TOP Removable platter would cause aluminum dust to spread and crash the balance of the surfaces, loosing all 90 mb of data.

Ernie · December 13, 2023, 7:57pm

… ahhh, the good old days…

jhecker · December 13, 2023, 8:04pm

No, I can’t say I am sure…I would like to think that it is serialized into some binary data which is then sent to the client…which would then deserialize it and place the data into the proper fields.

If I am wrong, then I have learned something new today

jhecker · December 13, 2023, 8:05pm

I tried that in my demo environment a few minutes ago and it did not seem to have any effect on things.

Mark_Wonsil · December 13, 2023, 8:32pm

Especially in http, I assuming that it’s using the built-in http compression. For net.tcp, there is also compression IIRC.

vingeance · December 14, 2023, 10:13pm

Just tested in a Demo environment, 2023.1.12.

Created an order. Loaded 100 lines, and 100 releases per line. A total of 10 thousand releases for the order.

In the Kinetic web Order Entry, after selecting the order, Epicor calls the v1 API SalesOrderSvc/GetByID method.

The whole SalesOrderTableset is returned and stored in dataviews.
By whole, I mean the OrderHed and all its OrderDtl, OrderRel, OrderMsc, attachments, etc.
As you can see in the screenshot below, that’s a huuge JSON response to transfer from the server and to handle by the browser.

Actually, the browser Developer Tools can’t even display the response as it is too big.
In Postman, it can display the response, but it is having a hard time doing so (+ RAM increases by a lot).

utaylor · December 15, 2023, 2:40pm

Thanks for testing Victor, and that’s what we are up against. We have this need, we need to be able to do this, but the amount of info that’s being passed back and forth slows it down so much it’s nearly unusable. so they opt to using excel sheets to ship off of and invoice off of

Huge loss for us. We literally need to load ship tos and quantity on the release, that’s it. don’t need attachments, don’t need order to touch order misc cause we aren’t adding misc charges on lines for this customer (I know order misc handles header charges too), etc.

The other caveat for us is that our customer tends to change their order quite a bit… and we need to update releases quite often. Doing that in this type of order with this much payload is so tough.

Mark_Wonsil · December 15, 2023, 2:45pm

When @Bart_Elia presented the new REST interface in his famous REST Novel Overview, he was concerned how it might be received:

Level unlocked. REST has been a HUGE addition to the Kinetic platform! It was a great evolution from the .NET Object model. The landing spot at the time was well balanced. There are now new challenges like APIs for large objects.

Microsoft has a really nice guide about API Design and in it they have this quote:

In 2008, Leonard Richardson proposed the following maturity model for web APIs:

Level 0: Define one URI, and all operations are POST requests to this URI.

Level 1: Create separate URIs for individual resources.

Level 2: Use HTTP methods to define operations on resources.

Level 3: Use hypermedia (HATEOAS, described below).

Kinetic is at level 2, as are most commercial software companies who have REST-enabled their products. It is a natural evolution and I’m not throwing shade here.

This thread is showing us why the RESTafarians would now be saying, “We told you so.” But most REST purist are such jerks, nobody would listen to them anyway.

Not a jerk (most Canadians without a puck are generally pretty nice), is a blogger/YouTuber named Derek Comartin. A few years ago, he did a series about HTTP APIs that does a really nice job explaining how to get to the next maturity level, which is HATEOAS - Hypermedia as the Engine of Application State.

This is a BIG step however. But one could imagine that the action bar (the ‘+’, and other icons) is driven by the server and not directly in a layer with rules. If an action link appears in the response, the icon appears, if not it doesn’t. (Mind you, we’re not talking security, just client behavior. All security would still be enforced at the server.) The landing pages are very well suited for HATEAOS since the action links are basically there.

For a large order, the response would have most of the header and links for options: open lines, all releases for a line, etc. Now the download size is potentially much smaller. Kinetic could certainly come up with a different UI that would allow much less data to be returned for specialized functions that manage only releases for example, but some thought is required for concurrency.

Again, this is a natural progression from a system that had all the bandwidth of a LAN and a lot of memory at the workstation to a higher latency network with the server further away and the reduced memory footprint of a browser. Epicor will evolve here too once the UI continues to settle.

utaylor · December 15, 2023, 2:48pm

Probably a lot of thought, but overall it sounds like the idea of HATEOAS would be beneficial.

utaylor · December 15, 2023, 2:49pm

Thanks for once again expanding my knowledge on all things web Mark!

Mark_Wonsil · December 15, 2023, 3:03pm

Years and years ago, I was working with an ERP system called Baan. They allowed developers to set up concurrency zones and if users were updating fields in different zones, they avoided the equivalent of “Record Modified by Another User” conditions. For example, the date of last print was in its own zone and the user wouldn’t get a sharing violation because they printed a document while updating another part of the sales order.