(This post follows on from last week's post Web Services and the 15 Second Delay).
Having accounted for 15 secs of the 45 secs latency I'd been observing in my BizTalk application, I started looking at where the additional 30 secs was coming from.
When I looked at my log files, I noticed the entire process from start to end (including calling external Web Services) was now taking just over three seconds. However, when invoking the BizTalk Web Service from a test client, the measured latency was still over 30 seconds. Something wasn't right…
I put logging code in the BizTalk Web Service around the ServerProxy.Invoke() call (the method call the submits the received SOAP message to BizTalk).
In my BizTalk application, the BizTalk Web Service is used to submit a message to the MessageBox, via the SOAP Adapter and a static request-response Receive Port using the PassThru pipeline. There is an Orchestration which subscribes to messages coming from this receive port, processes them, and then returns a response back to the receive port (and therefore the Web Service). My logging code logged the time at which the orchestration received a request message, and the time at which it sent a response message.
What I saw in my log files was that there was a 15 sec delay between calling ServerProxy.Invoke(), and the orchestration logging that it had received a request, and then another 15 sec delay between the orchestration sending a response, and the return from ServerProxy.Invoke() in the WebService.
Our BizTalk Load Test environment is composed of a single BizTalk 2006 Server, a single SQL Server, and SAN disk storage. Given that everything that happens between ServerProxy.Invoke() and an orchestration instance being started is non-user code (i.e. not my code!!), the problem was most likely environmental i.e. network, disk, database, security or "other".
So my first step was to attach SQL Server Profiler and log all the database calls going between the BizTalk Server and SQL Server.
If you haven't used Profiler before, be aware that it captures a huge amount of data – going through its logs can be very very painful.
However, in this case we're only interested in calls that have originated from BizTalk – specifically, calls which have originated from one of the Service Accounts that BizTalk runs under. In this case, the service account that the Isolated host instance runs under, and the account that my Orchestration Host's host instance runs under.
Why these two? The SOAP adapter runs under the Isolated host, which means that it'll be this Isolated host instance that will be putting the request into the MessageBox. And the Orchestration Host's host instance will be the one which picks up the request from the MessageBox, and then writes the response back the MessageBox.
For the Orchestration Host's host instance, finding out the service account name is easy – just look in the Services console, find the service named something like BizTalk Service BizTalk Group : <host name>, and then note the value in the Log On As column.
For the Isolated Host's host instance, we need to check the identity account for the Application Pool under which the BizTalk Web Service is running (if you're using IIS 6 – if you're using IIS 5, you'd use the service account for IIS itself, usually the ASPNET account).
So all we have to do is look for entries in the Profile log file which have a LoginName property equal to one of these two account names. Fortunately, you can setup a filter in Profiler quite easily – either before you run the trace (so that only events you're interested in are captured) or after.
I chose to capture all events and then filtered on entries which had an EntryClass of RPC:Completed, and a LoginName value of the Isolated host account name.
(Note: because I'm only interested in the SQL statements being executed by BizTalk to call Stored Procedures, I only need to see RPC events – none of the other events are relevant here as they pertain to Audit events, Keep-Alive requests, or Transaction statements).
Running through the filtered log means I only have to trawl through 300 odd lines, rather than 10,000…!
What I'm looking for is the time at which the Isolated host submitted the SOAP request to the MessageBox, so I'm looking for a call to Stored Procedure (SPROC) called bts_InsertMessage:
(Note: You'll notice in the above image that just before bts_InsertMessage is called, there are calls to bts_InsertPredicate_<hostname> and bts_InsertProperty followed by a call to bts_FindSubscription.
InsertPredicate and InsertProperty populate the MessageProps table, and FindSubscription checks whether the combination of these predicates and properties match a current subscription – if so, bts_InsertMessage is called; if not, a "subscription not found" exception is raised).
So now I know at what time the SOAP request was placed in the MessageBox: 17 seconds after ServerProxy.Invoke() was called. Now I need to check what time the message was picked up by my Orchestration Host's host instance.
To do this, I filter the Profiler log on the service account name used by the host instance.
However, this time I'm looking for a call to bts_DeQueueMessages_<hostname> which did some work – that is, a call which has a higher duration than the others:
However, this doesn't clear up the mystery – this just shows that the message was picked up by the Orchestration Host's host instance 4 secs after being inserted by the Isolated host instance.
And then something hits me: what if this related to the problems I was having earlier, with the Web Service and the CRL?
What if "17 seconds" is really "15 seconds plus some BizTalk processing time"?
I started up TCP View, passed a test message through – and sure enough, there was a CRL call with a SYN_SENT state.
Only this time, the TCP connection was to http://crl.microsoft.com/.
What are the chances that the BizTalk assemblies are digitally signed? Specifically Microsoft.BizTalk.WebServices.ServerProxy.dll, the assembly used by BizTalk Web Services.
Let's have a look:
And if we drill down into the Certificate Details, and look at the CRL Distribution point we see:
So there we are – because the code is hosted in IIS, and is digitally signed, IIS will attempt to validate the certificate, which involves attempting to download the CRL for the certificate.
Unlike my Web Service, I don't think I'd have much luck in convincing Microsoft to *not* digitally sign the BizTalk assemblies…
So, we set the default proxy on the BizTalk server (using the proxycfg command line tool discussed in the previous post).
And sure enough, the delay in the BizTalk Web Service went away.
The 45 secs latency dropped to 2 secs… and then dropped to 0.5 secs once I did some low-latency tuning.
So there we go. Now the only reason my client has this issue is because they don't want to have separate BizTalk servers which just run the BizTalk Web Services (i.e. dedicated BizTalk Servers, most likely in a DMZ, which don't do anything but put received SOAP messages in the MessageBox – all the other BizTalk servers would be behind the firewalls and in the secure portion of the network – this is Microsoft's recommended way of doing it, but is costlier in terms of licensing).
We decided we could live with the Load Test server having access to the internet via a proxy server, so applied this change to all our BizTalk servers (both Live and Test).