The case of the slow WebRequest GetResponse under SYSTEM

As you probably know by now, I work with Garrett Serack on the CoApp project when time permits. In our adventures to bring open-source software to Windows, we constantly fall into deep pits that require quite the climb back out. In this case, Garrett had a simple piece of code that was making a HTTP HEAD request. While this code executed swiftly in his user account’s context, it was taking ages when running as SYSTEM.

I created a small repro. executable to validate his issue and used psexec –s –I –d cmd.exe to launch an instance of the Command Prompt, in the SYSTEM context.

Stopwatch w = new Stopwatch();w.Start();

try
{
    var req = WebRequest.Create("http://coapp.org/foo");
    req.Method = "HEAD";
    var res = rq.GetResponse();
}
catch (Exception e)
{
    w.Stop();
}

Console.WriteLine(w.ElapsedMilliseconds);

Sure enough, it was slow. At this point, I knew I needed to profile this code but with the unmanaged/managed boundaries, I didn’t feel like messing around with that. So, instead I did some research on System.Net and debug facilities. It turns out, System.Net is packed full of diagnostics including a Network Tracing feature. Cool!

Following the directions, I enabled Network Tracing for my small test program, gave it another whirl (again, in the SYSTEM context), and dug out the trace log.

System.Net Verbose: 0 : [6932] WebRequest::Create(http://coapp.org/foo)
    DateTime=2011-09-23T01:38:05.2033494Z
System.Net Verbose: 0 : [6932] HttpWebRequest#21454193::HttpWebRequest(http://coapp.org/foo#960239574)
    DateTime=2011-09-23T01:38:05.2033494Z
System.Net Information: 0 : [6932] Current OS installation type is 'Client'.
    DateTime=2011-09-23T01:38:05.2053495Z
System.Net Information: 0 : [6932] RAS supported: True
    DateTime=2011-09-23T01:38:05.2063496Z
System.Net Verbose: 0 : [6932] Exiting HttpWebRequest#21454193::HttpWebRequest() 
    DateTime=2011-09-23T01:38:05.2243506Z
System.Net Verbose: 0 : [6932] Exiting WebRequest::Create() 	-> HttpWebRequest#21454193
    DateTime=2011-09-23T01:38:05.2243506Z
System.Net Verbose: 0 : [6932] HttpWebRequest#21454193::GetResponse()
    DateTime=2011-09-23T01:38:05.2243506Z
System.Net Error: 0 : [6932] Can't retrieve proxy settings for Uri 'http://coapp.org/foo'. Error code: 12180.
    DateTime=2011-09-23T01:38:18.7941268Z
[...]

I snipped the output for brevity, but the important line here is the last one. I looked up that 12180 error code and it resolved to ERROR_WINHTTP_AUTODETECTION_FAILED – an error code returned by WinHttpDetectAutoProxyConfigUrl.

 

A thread stack with the culprit function highlighted (Process Explorer).

To verify this function was the culprit, I fired up Process Explorer then started the repro. executable. As soon as it appeared in the process tree, I right-clicked it and clicked Suspend. I then double-clicked it, navigated to the Threads tab, and checked out the stack for each thread. Bingo. The main thread, in my case, was invoking WinHttpDetectAutoProxyConfig and taking forever.

At this point, I started thinking – where have I seen automatic proxy configuration before? Oh, that’s right. Internet Explorer.

Since the Bronze Age, Internet Explorer has had the option of controlling whether or not your system automatically detected your proxy settings via Web Proxy Auto Discovery (WPAD) (which works over both DNS and DHCP). That means when this automatic detection occurs, you’re making DNS and/or DHCP requests, hence the slow down.

 

“Automatically detect settings” option present in Internet Explorer

While Internet Explorer had this feature disabled in my user’s context, I suspected it was enabled in the SYSTEM context. Using psexec again I launched Internet Explorer (psexec -s -i -d "%ProgramFiles%\Internet Explorer\iexplore.exe") and navigated to Tools –> Internet Options. Sure enough, it was checked. Blasted!

Unchecking this option took effect immediately and dropped the delay in my repro. executable. Problem solved, at least on my machine.

Unresolved issues/comments

• If I enable this option in both SYSTEM and user contexts, why does this detection take longer in SYSTEM? Winsock initialization?
• We’re looking to move this web request logic back into the user’s context, to take advantage of the auto detection cache. (Users typically run more than one Internet-aware application which means this cache will be primed/valid more often than in the SYSTEM context.)