Hello,
I am trying to analysys the results of our Client Monitor. When we run a batch process that creates orders from EDI data, there are spots where it lags anywhere from a dozen seconds to a couple minutes on a single order (header and details). Otherwise it normally is zipping through the order creation at about one second per order.
The first question you all would probably ask is what is different about the orders where it lags. Problem is, they are not out of the ordinary, in regards to size, quantity of item rows, and such. In fact, we are quite confident that if we rerun the same batch of PO orders, the lag does not occur on the same orders. This makes me think it may be network or external access lag issue.
The database is a MS SQL server on a new beefy server hardware.
I'll post a capture (below) of the log but it may not be clear. There were TAB delimiteres but they all may be stripped out in the forum.
A question that I would like to know the answer, does the TIME column represent the time the row/function was initiated, or the TIME the row/function was completed?
Below is a paste. To reduce its size, I've edited the data to remove some columns. Also, in the interest company privacy, where any '....' occur, I removed identifying information.
If you copy the below info and paste it into a text editor, you will be able to see the full lines. The columns are TAB delimited.
Notice the time gap from entry 5133 to 5134 (8:59:21 to 9:01:48 ) ... that's over a minute lag. It's not clear to me where that time was spent. Was it spent on those activities in 5133 or 5134?
The 5133 entry contains several activities: sendmessage(), table.GET.
Or was that time spent doing the 5134 search on table 83008?
The milliseconds was cut off the TIME column, however the Elasped Time entry is blank on the 5133, and shows 15 for the 5134 entry, which is correct. But neither of them represent the 1 minute 27 second lag.
Appreciate any comments and suggestions.
Cheers,
Eric
Time Entry No. Function Param No Parameter Number Data
.....
8:59:20 AM 5132 FIND/NEXT 100 Elapsed Time (ms)
8:59:21 AM 5133 FIND/NEXT 1 Table 83010 EDI Trade Partner
8:59:21 AM 5133 FIND/NEXT 2 Search Method =
8:59:21 AM 5133 FIND/NEXT 3 Key Trade Ptnr ID='....'
8:59:21 AM 5133 FIND/NEXT 14 Source Object Codeunit 83002 EDI P.O. Import
8:59:21 AM 5133 FIND/NEXT 15 Source Trigger/Function SendMessage(TradePartner,IntDocNo,CustPO,Type)
8:59:21 AM 5133 FIND/NEXT 16 Source Line No. 2638
8:59:21 AM 5133 FIND/NEXT 17 Source Text EDITradePartner.GET(TradePartner);
8:59:21 AM 5133 FIND/NEXT 33 SQL Status Cached
8:59:21 AM 5133 FIND/NEXT 50 Search Result =
8:59:21 AM 5133 FIND/NEXT 51 Record Found Trade Ptnr ID='.....'
8:59:21 AM 5133 FIND/NEXT 100 Elapsed Time (ms)
9:01:48 AM 5134 FIND/NEXT 1 Table 83008 EDI Rec. Doc. Hdr.
9:01:48 AM 5134 FIND/NEXT 2 Search Method =
9:01:48 AM 5134 FIND/NEXT 3 Key Trade Ptnr ID='...',EDI Document='850',EDI Version='1',Internal Doc No.='....'
9:01:48 AM 5134 FIND/NEXT 14 Source Object Codeunit 83002 EDI P.O. Import
9:01:48 AM 5134 FIND/NEXT 15 Source Trigger/Function CreOrdersForPO(TrEDIRecDocHdr)
9:01:48 AM 5134 FIND/NEXT 16 Source Line No. 1522
9:01:48 AM 5134 FIND/NEXT 30 SQL Statement SELECT * FROM "....$EDI Rec_ Doc_ Hdr_" WITH (UPDLOCK, REPEATABLEREAD, ROWLOCK) ...
9:01:48 AM 5134 FIND/NEXT 31 SQL Plan Clustered Index Seek(...$EDI Rec_ Doc_ Hdr_$0)[3,1]
9:01:48 AM 5134 FIND/NEXT 32 SQL Index Trade Ptnr ID,EDI Document,EDI Version,Internal Doc No.
9:01:48 AM 5134 FIND/NEXT 33 SQL Status ID: 186;Reused: 16;Prepared;Default;UpdateNoLocks
9:01:48 AM 5134 FIND/NEXT 50 Search Result =
9:01:48 AM 5134 FIND/NEXT 51 Record Found Trade Ptnr ID='...',EDI Document='850',EDI Version='1',Internal Doc No.='...'
9:01:48 AM 5134 FIND/NEXT 55 Records Read 1
9:01:48 AM 5134 FIND/NEXT 60 Reads 3
9:01:48 AM 5134 FIND/NEXT 100 Elapsed Time (ms) 15
9:01:47 AM 5135 MODIFY 1 Table 83008 EDI Rec. Doc. Hdr.
......
0
Comments
MVP - Dynamics NAV
My BLOG
NAVERTICA a.s.