locked
Tracking Data times are not correct - Response received before request was made RRS feed

  • Question

  • We are using BizTalk Server 2009 - Tracking is turned on  in production and with the following option enabled (Orchestration start and end, Message send and receive, before orchestration processing, after orchestration processing).

    We have recently started to notice that the sequence of events being tracked are not in the proper sequence according to the times being displayed. For example when reviewing the tracking data to troubleshoot transaction we are seeing more and more examples of web services responses being received before the request to the web service was made, which shouldn't be possible.  

    We also have situations were the main message received to trigger the orchestration to start, is time stamped with a time that places the receive in the middle of the events occurring.  

    This shouldn't be possible and it appears that the tracked data is being marked with in-correct times making troubleshooting very difficult.  

    Please advise of any possible causes and resolutions.  Thanks Chad

    Friday, January 10, 2014 4:10 PM

Answers

  • Thanks to all for your replies.  Problem solved!!!!!  :)

    Today I isolated the processes (as suggested) to a single server and observed the tracked data.  The tracked data looked good all in the proper sequence.  I then got our server design people involved and we were able to determine that one of the app servers was no longer synchronizing its time against the AD servers and had fallen 25 seconds behind.  We restarted and forced a sync but the times was still out by 14 seconds.  We then manually updated the time on the one server and was able to get it within 0.2 seconds of the AD server. The other 2 server date/time were already in sync with the AD.  The track data all looks good after the manual adjustment. 

    So, for the moment we have re-sync the tracked data. Time will tell if we the server date/time will remain synchronized.  

    Thanks again


    • Marked as answer by ChCraig Monday, January 13, 2014 6:08 PM
    • Edited by ChCraig Monday, January 13, 2014 6:11 PM
    Monday, January 13, 2014 6:08 PM

All replies

  • First, make sure you're comparing the correct time stamps.

    A Two Way Port operation will have 4 time stamps, 2 Receive and 2 Send, however, it's actually Receive->Send, Receive->Send, no matter which direction the message is heading relative to BizTalk.

    Why?  Because the Receive/Send is from the perspective of the Pipeline, not the MessageBox, Orchestration or anything else.  The Pipeline, Receive or Send, first Receives the Message, then Sends the Message.

    So, if you're not careful to look at the correct operation, you might be comparing the Receive Pipeline's Send to the Orchestration's Start.

    Friday, January 10, 2014 4:41 PM
    Moderator
    • Proposed as answer by Aheriz Friday, January 10, 2014 5:12 PM
    Friday, January 10, 2014 4:56 PM
  • Thanks for the reply.  

    Definitely looking at the right times as we do have situations were the tracking data is in the proper sequence and have seen a couple instances in the past that were not in sequence but these seems to be become a more frequent problem.

    Should have added to the original post but we also have orchestrations that have a negative duration which again shouldn't be possible.  

    For instance, you can see in this screen shot the 2 items in the red circle.  The receive for schema CreateJobIdocInt is the message that triggers the orchestration and the GetListJob is the first call to a web service and the ListJob is the response to this call. The tracking data however lists the Create and Get at the end of the process and the listJob as the first event, which we know isn't the case.

    The incorrect times make it look like the orchestration completed before is started.  this example has a duration of -18803.  I have many other examples of the same behavior.

     

    Negative Duration Screen Shot



    • Edited by ChCraig Friday, January 10, 2014 5:42 PM
    Friday, January 10, 2014 5:32 PM
  • Is the time synchronized on all your servers?

    Friday, January 10, 2014 6:15 PM
    Moderator
  • We have 3 application servers and a clustered SQL Server back end.  Date/Time and Time Zone have been confirmed to be the same on all servers (app and db server).  I had the same question when i first same the problem.  We also restart the host that are responsible for tracking with no improvements.

    Thanks

    Friday, January 10, 2014 6:28 PM
  • Well despite being configured in the same domain, it is possible that the servers are not running the exact time. This is because AD (as part of group policy) has a setting which defines the variance (time difference tolerance) which is permitted across the clocks across different machines.

    To rule out a server time scnchronization issue, I would try to localize all the associated host instances (send, receive, processing) and the Tracking instance to ONE Server and see if we get an occurence of the same/similar observations.

    After having localized the host instances you see similar results, then I'm inclided to go with boatsellers' explanation of comparing the correct time stamps, which can occur if in the TP the stages got mixed :)

    The other scenario is when you mix TP Event Collection and BAM API. The TP Event Collection inserts UTC Time while the BAM API does not do this and the results can be interesting depending on your timezone w.r.t GMT.

    Regards.


    • Edited by Shankycheil Saturday, January 11, 2014 7:27 AM edit
    Saturday, January 11, 2014 7:06 AM
  • Can you verify that the following SQL statement (run against your BizTalkDTADb Database) does indeed return rows:

    select * from 
    dbo.dta_ServiceInstances
    where (dtStartTime > dtEndTime)

    Morten la Cour


    • Edited by la Cour Saturday, January 11, 2014 7:23 AM
    Saturday, January 11, 2014 7:22 AM
  • I would trouble shoot this way,

    1) If you have 3 servers, stop instances for 2 of them and run only one. See if  issue still happens. This way you eliminate server sync and related issues etc.

    2) Second, I would check you are not sending multiple requests, a response of first one could appear before second request is made..

    3) Since you mentioned Orchestration, I would run Orch Debugger and check message flow + timestamps on various shapes there.. This will also tell how much time each shape takes (performance analysis)




    Sunday, January 12, 2014 9:37 AM
  • Thanks to all for your replies.  Problem solved!!!!!  :)

    Today I isolated the processes (as suggested) to a single server and observed the tracked data.  The tracked data looked good all in the proper sequence.  I then got our server design people involved and we were able to determine that one of the app servers was no longer synchronizing its time against the AD servers and had fallen 25 seconds behind.  We restarted and forced a sync but the times was still out by 14 seconds.  We then manually updated the time on the one server and was able to get it within 0.2 seconds of the AD server. The other 2 server date/time were already in sync with the AD.  The track data all looks good after the manual adjustment. 

    So, for the moment we have re-sync the tracked data. Time will tell if we the server date/time will remain synchronized.  

    Thanks again


    • Marked as answer by ChCraig Monday, January 13, 2014 6:08 PM
    • Edited by ChCraig Monday, January 13, 2014 6:11 PM
    Monday, January 13, 2014 6:08 PM