3

I've developed a .net 3.5 application which uses an HTTPWebRequest to fetch data from a vendors web server, this then returns an XML document. On my own workstation which is xp (32bit), it works very quickly.

On the server it is much much slower. A 16k response from the vendor takes 20-30 seconds at best whereas on my PC it takes 1 second.

The server is a virtual machine running windows server 2008 in 64 bit mode on ESX. I have internet explorer installed on the server and making the same request in IE, as opposed to my app, the page is loaded in a similar time as it is on my workstation.

The code is as follows:

private static XElement FetchXml(string uri)
{
    int retryInterval = 500;

    for (int retry = 1; retry < RETRY_MAX; ++retry)
    {
        Stopwatch stopWatch = Stopwatch.StartNew();

        try
        {
            var request = HttpWebRequest.Create(uri);

            request.Proxy = new WebProxy("<the corporate proxy>", 8080);

            // 3 minute timeout on individual web requests
            request.Timeout = 1000 * 60 * 3;

            using (var response = request.GetResponse())
            {
                using (var stream = response.GetResponseStream())
                {
                    using (var reader = new StreamReader(stream))
                    {
                        XElement xml = XElement.Load(reader);
                        //log.InfoFormat("Fetched (Uri={0}, Size={1} bytes, Elapsed={2:N2}s).", uri, xml.ToString().Length, stopWatch.Elapsed.TotalSeconds);
                        return xml;
                    }
                }
            }
        }
        catch (Exception ex)
        {
            //log.ErrorFormat("Error fetching Xml (Uri={0}) : {1}", uri, ex.Message);
        }
        //log.InfoFormat("Retrying fetch after interval (Attempt#={0}, Interval={1}s)",
        //  retry, (double)retryInterval/1000);

        System.Threading.Thread.Sleep(retryInterval);

        // Back off for next retry if it occurs.
        retryInterval *= 2;
    }

    string msg = String.Format("Error fetching Xml - exhausted maximum retries (Uri={0}, MaxRetries={1}).",
        uri,
        RETRY_MAX);     

    throw new ApplicationException(msg);
}

I have tested all of the following having spent yesterday researching the issue:

ServicePointManager.CheckCertificateRevocationList = false;
ServicePointManager.DefaultConnectionLimit = 65000;
ServicePointManager.Expect100Continue = false;

None of these helped. I've also seen it suggested that the proxy can cause these problems and can be bypassed, unfortunately not in this environment, and I don' think it can be the proxies fault as I use the same one on my workstation.

I have also grabbed some Microsoft Network Monitor traces and interestingly, the packet size on the server coming from the remote site to my app is much smaller. On my workstation they are approx 1400 bytes, whereas on the server they are more like 300 bytes, and whilst I'm not too familiar with TCP it seems there is a lot of chatter getting the http continuations to build the full message. So whereas on my workstation its about 4 inbound messages for the total payload with 3 outbound, on the server it is 19 inbound messages with similar number of outbound. This probably explains the performance problem, but I don't understand why it is happening. When I load the page in IE on the server its a small number of requests with big packet sizes.

Network Monitor on my XP Workstation:

HTTP:Request, GET http://xml.vendor.com/datapage/, Query:version=6.0
HTTP:Response, HTTP/1.1, Status: Ok, URL: http://xml.vendor.com/datapage/
HTTP:HTTP Payload, URL: http://xml.vendor.com/datapage/
 TCP:Flags=...A...., SrcPort=2192, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3206279401, Ack=33242842, Win=64512 (scale factor 0x0) = 64512
 TCP:[Continuation to #915]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=2192, PayloadLen=1360, Seq=33242842 - 33244202, Ack=3206279401, Win=65535 (scale factor 0x0) = 65535
 TCP:[Continuation to #915]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=2192, PayloadLen=1360, Seq=33244202 - 33245562, Ack=3206279401, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=2192, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3206279401, Ack=33245562, Win=64512 (scale factor 0x0) = 64512
 TCP:[Continuation to #915]Flags=...AP..., SrcPort=HTTP Alternate(8080), DstPort=2192, PayloadLen=557, Seq=33245562 - 33246119, Ack=3206279401, Win=65535 (scale factor 0x0) = 65535 
 TCP:Flags=...A...., SrcPort=2192, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3206279401, Ack=33246119, Win=63955 (scale factor 0x0) = 63955

The same code + request running on the server:

HTTP:Request, GET http://xml.vendor.com/datapage/, Query:version=6.0
HTTP:Response, HTTP/1.1, Status: Ok, URL: http://xml.vendor.com/datapage/
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24013122, Win=255 (scale factor 0x8) = 65280
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=255, Seq=24013122 - 24013377, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24013377, Win=254 (scale factor 0x8) = 65024
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=254, Seq=24013377 - 24013631, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24013631, Win=253 (scale factor 0x8) = 64768
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=253, Seq=24013631 - 24013884, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24013884, Win=252 (scale factor 0x8) = 64512
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=252, Seq=24013884 - 24014136, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24014136, Win=251 (scale factor 0x8) = 64256
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=251, Seq=24014136 - 24014387, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24014387, Win=256 (scale factor 0x8) = 65536
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=256, Seq=24014387 - 24014643, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24014643, Win=255 (scale factor 0x8) = 65280
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=255, Seq=24014643 - 24014898, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24014898, Win=254 (scale factor 0x8) = 65024
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=254, Seq=24014898 - 24015152, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24015152, Win=253 (scale factor 0x8) = 64768
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=253, Seq=24015152 - 24015405, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24015405, Win=252 (scale factor 0x8) = 64512 
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=252, Seq=24015405 - 24015657, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24015657, Win=251 (scale factor 0x8) = 64256
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=251, Seq=24015657 - 24015908, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24015908, Win=256 (scale factor 0x8) = 65536
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=256, Seq=24015908 - 24016164, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24016164, Win=255 (scale factor 0x8) = 65280
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=255, Seq=24016164 - 24016419, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24016419, Win=254 (scale factor 0x8) = 65024
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=254, Seq=24016419 - 24016673, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24016673, Win=253 (scale factor 0x8) = 64768
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=253, Seq=24016673 - 24016926, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24016926, Win=252 (scale factor 0x8) = 64512
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=252, Seq=24016926 - 24017178, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24017178, Win=251 (scale factor 0x8) = 64256
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=251, Seq=24017178 - 24017429, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24017429, Win=256 (scale factor 0x8) = 65536
 TCP:[Continuation to #192]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=256, Seq=24017429 - 24017685, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24017685, Win=255 (scale factor 0x8) = 65280
 TCP:[Continuation to #192]Flags=...AP..., SrcPort=HTTP Alternate(8080), DstPort=58401, PayloadLen=181, Seq=24017685 - 24017866, Ack=3779234716, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=58401, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=3779234716, Ack=24017866, Win=254 (scale factor 0x8) = 65024

IE on the server fetching the same page:

HTTP:Request, GET http://xml.vendor.com/datapage/, Query:version=6.0
 TCP:Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=53132, PayloadLen=0, Seq=20851875, Ack=2273238303, Win=65535 (scale factor 0x0) = 65535
HTTP:Response, HTTP/1.1, Status: Ok, URL: http://xml.vendor.com/datapage/
HTTP:HTTP Payload, URL: http://xml.vendor.com/datapage/
 TCP:[Continuation to #345]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=53132, PayloadLen=1360, Seq=20853598 - 20854958, Ack=2273238303, Win=65535 (scale factor 0x0) = 65535
 TCP:[Continuation to #345]Flags=...A...., SrcPort=HTTP Alternate(8080), DstPort=53132, PayloadLen=1360, Seq=20854958 - 20856318, Ack=2273238303, Win=65535 (scale factor 0x0) = 65535
 TCP:[Continuation to #345]Flags=...AP..., SrcPort=HTTP Alternate(8080), DstPort=53132, PayloadLen=557, Seq=20856318 - 20856875, Ack=2273238303, Win=65535 (scale factor 0x0) = 65535
 TCP:Flags=...A...., SrcPort=53132, DstPort=HTTP Alternate(8080), PayloadLen=0, Seq=2273238303, Ack=20856875, Win=16425 (scale factor 0x2) = 65700

One interesting point is that on the slow request, the trace never capture a "HTTP Payload". is there something odd going on there? Once the request finally completes on the server, the data is still well formed despite this.

DanH
  • 3,772
  • 2
  • 27
  • 31

3 Answers3

1

This answer looks like it might be relevant... perhaps .net is choking on reading the default proxy settings that you've probably set up to get IE working properly: HTTPWebResponse + StreamReader Very Slow

Seeing as you're setting the proxy in code, you can skip detection.

Community
  • 1
  • 1
spender
  • 117,338
  • 33
  • 229
  • 351
  • Hi - thanks for the suggestion. I have just tested this and no dice - I think as I was setting the proxy manually it wouldn't have tried to get the default proxy anyway. It also seems from my logs, that the initial response is a bit slow, but from then on the loading of the data is also super slow. So this would be after the proxy negotiations etc. – DanH Mar 04 '11 at 13:45
  • Have a look to see what's the difference in the route (run tracert) from the XP box to the destination, and then the server and the destination. This will reveal where your data is going through that is different. – David d C e Freitas Mar 18 '11 at 08:40
0

Looking at your capture, it seems as if your client code TCP stack is advertising a TCP window of 255 bytes to the server. That is why the destination proxy server is only sending back 255 bytes max.

Is this a console application in which you are running your code? Is it possible that some other code is changing the TCP window size?

feroze
  • 7,380
  • 7
  • 40
  • 57
0

This was resolved by disabling windows tcp autotuning which seems to have been behaving aberrantly!

Thanks,

Dan

DanH
  • 3,772
  • 2
  • 27
  • 31