Windows Networking 5: .Net Framework 应用程序响应慢排查一则

与Java一样，.Net Framework也是基于IL解析执行的，通过Microsoft提供的 !sos debug extension，我们基本上可以把.Net Framework的应用程序看个通透。本文通过一个用户的.Net Framework应用网络问题，抛砖引玉。

问题

有用户反馈他们Windows上的应用程序访问MySQL慢，但是行为很奇怪。架构是这样的，

Client --------Internet---> Windows IIS server (.Net Framework application) ------Internet-----> MySQL server

用户反馈，

1. 客户端访问IIS server慢。
2. IIS server通过自己的公网IP访问相同的页面也比较慢 （VPC机器，EIP）。

用户怀疑是Windows访问MySQL server慢，所以做了很多IIS, MySQL的优化，但均不解决问题。同时，用户通过其他服务器访问MySQL的测试，也排除了MySQL本身性能问题。

排查

咋一看，一切的矛头都指向了Windows IIS server通过公网IP访问MySQL server慢。因此，我们收集了网络请求的瀑布图，

用户说“客户端访问IIS Server慢”，那么我们要知道到底慢了多久。

从这张图里，我们可以很容易的看到，

• 客户端的确访问IIS server慢，
• 总共慢了6秒多时间，
• 关键是每次访问GetAllCountrys的方法需要3.25s左右的时间等待服务器返回给我们第一个响应字节 (TTFB)。

是否是客户端跟服务器端的网络问题呢？通过在IIS server上获取的网络请求的瀑布图，我们可以排除这一段的链路问题，

而服务器上通过http://localhost的方式访问所收集的情况更是确认了所有组件都没有问题，

内容不变，大小差不多，响应也很正常，基本没延迟。

一般情况下分析到这里，基本上我们可以排除是产品问题。但延迟到底是怎么来的，需要进一步抓取网络数据包分析。

简单说一下发现，

1. 服务器的确是3.25s前收到了请求，但是延迟响应。
2. 服务器收到请求后，从抓包看是立即去连接了MySQL server，并很快获取了所有需要的内容，也就是Country相关的信息。这部分可以很容的通过Wireshark导出数据包内容和客户端收到的内容作对比。
3. 在服务器收到数据后一段时间，服务器没有立即返回HTTP response，而中间我们看到有ARP的请求。逻辑上，这些额外的操作跟IIS是否返回HTTP Response无关，但是通过几次的抓包，我们总是能发现类似的行为，直觉上我们认为跟3.25s的延迟有关。
4. 仔细看的话服务器的ARP请求中使用了客户端的公网IP地址。但是，这个ARP绝对不是Windows操作系统发起的。如果当时服务器端尝试跟客户端通讯的话，它应该请求Gateway的地址。因此，ARP的请求从逻辑上来说是不对的，这也间接证明ARP跟我们的延迟问题有关
5. Localhost的抓包对比看没有ARP请求，不过由于是本机的流量，抓包无法抓到也是符合逻辑的。

可惜的是，Windows并没有提供任何跟ARP有关的日志，为了获取确切的证据，我们可以考虑，

1. Process Monitor log收集应用运行过程。通过Process Monitor提供的Callstack等信息寻找蛛丝马迹。不过这类分析将会比较耗时，实在没有思路的时候可以考虑收集一下，而当前我们对这个问题的分析已经比较清晰，更关注是问题发生是 .Net程序在做什么。
2. 收集.Net Framework的Network Trace日志，这部分日志会比抓包更要详细，

   How to: Configure Network Tracing : http://msdn.microsoft.com/en-us/library/ty48b824(VS.90).aspx

3. 在3.25s 服务器没响应的中间，获取IIS server的w3wp.exe进程user dump。逻辑上，IIS没有响应一定是应用程序等在某个资源上面。只是这个dump不大好抓，但是SysInternal提供了一个比较强大的工具：Process Dump。可以使用procdump.exe等待w3wp.exe，并每1 ~ 2秒生成一个dump来获取确切发生问题时的callstack。

   https://docs.microsoft.com/en-us/sysinternals/downloads/procdump

   procdump -w -s 2 -n 10 w3wp.exe c:tempw3wp.dump

   具体的用法，参考微软文档。

w3wp.exe User Dump分析

.Net Framework的Network Trace收集相对来说比较复杂一些，另外还需要用户配合修改配置文件。因此，我们直接收集userdump进行下一步分析。对于.Net程序，我们在使用Windbg打开dump文件的时候第一时间加载SOS debugging extension。

关于SOS debugging extension的一切，可以参考：https://docs.microsoft.com/en-us/dotnet/framework/tools/sos-dll-sos-debugging-extension

通过研究w3wp.exe的线程信息，我们定位在#27线程，

  27  Id: 1b4.654 Suspend: 0 Teb: 00000078`1eca8000 Unfrozen
Child-SP  RetAddr   : Args to Child   : Call Site
00000078`1fabd668 00007ff8`45a8175e : 00000000`00000068 00000000`00000020 00000000`00000014 00000078`00000008 : ntdll!NtDeviceIoControlFile+0x14
00000078`1fabd670 00007ff8`433cf70c : 00000078`1fabd890 00000078`1fabd8ac 00000000`00000002 00000078`1fabd8ac : nsi!NsiGetAllParameters+0xfe
00000078`1fabd760 00007ff8`433def36 : 00007ff7`d82f1398 00000000`00000000 00000000`924b782a 00000000`00000000 : IPHLPAPI!ResolveIpNetEntry2+0xfc
00000078`1fabd850 00007ff7`d84ab0fb : 00000000`00000000 000001ab`927bcb48 00000078`1fabdb58 000001ab`927b4658 : IPHLPAPI!SendARP+0x86
00000078`1fabd930 00007ff7`d84a70b6 : 00000000`924b782a 00000000`00000000 00000078`1fabdb48 00000078`1fabdb40 : 0x00007ff7`d84ab0fb
00000078`1fabda30 00007ff7`d84a7d84 : 000001aa`92a02a20 00000078`1fabefe0 00000000`0000fdff 000001aa`917e9304 : 0x00007ff7`d84a70b6
00000078`1fabdb70 00007ff7`d80dffc7 : 000001ab`927bcb48 000001ab`9279da98 000001ab`927bcb90 000001aa`92541420 : 0x00007ff7`d84a7d84
00000078`1fabdcf0 00007ff7`d82e010b : 000001ab`92794d18 000001ab`9279da98 00007ff7`d8281638 00000000`00000001 : 0x00007ff7`d80dffc7
00000078`1fabddf0 00007ff7`d80df338 : 000001ab`927b4870 000001ab`92794d18 000001ab`927b4710 00000078`1fabd8a4 : 0x00007ff7`d82e010b
00000078`1fabde30 00007ff7`d80df1e3 : 000001ab`9279e1e8 000001ab`92795110 000001ab`9279f728 000001ab`9279f728 : 0x00007ff7`d80df338
00000078`1fabde80 00007ff7`d80df121 : 000001ab`92795890 000001ab`92795110 000001ab`9279e1e8 000001ab`9279f728 : 0x00007ff7`d80df1e3
00000078`1fabdec0 00007ff7`d80defda : 000001ab`927b42d8 000001ab`927b44c8 000001ab`927b443c 00000000`00000000 : 0x00007ff7`d80df121
00000078`1fabdef0 00007ff7`d80de9f0 : 000001ab`92795890 000001ab`927b43e0 000001ab`9279e1e8 00000000`00000000 : 0x00007ff7`d80defda
00000078`1fabdf20 00007ff7`d80de7ee : 000001ab`927b40c0 000001ab`927b43e0 000001ab`927b4034 00000078`1fabe2a8 : 0x00007ff7`d80de9f0
00000078`1fabdf60 00007ff7`d80de52a : 000001ab`927b42b8 000001ab`927b43e0 000001ab`927b4034 00000078`1fabe2a8 : 0x00007ff7`d80de7ee
00000078`1fabdfd0 00007ff7`d80de480 : 000001ab`92795890 000001ab`927b3fd8 000001ab`9279f5c4 00000078`1fabe2a8 : 0x00007ff7`d80de52a
00000078`1fabe000 00007ff7`d80d8757 : 000001ab`9279f6e0 000001ab`927b3fd8 000001ab`9279f5c4 00000078`1fabe2a8 : 0x00007ff7`d80de480
00000078`1fabe040 00007ff7`d80d8946 : 000001ab`9279e3e8 000001ab`927b3fd8 000001ab`9279f5c4 00000078`1fabe2a8 : 0x00007ff7`d80d8757
00000078`1fabe090 00007ff7`d80d898b : 000001ab`92795890 000001ab`9279f568 000001ab`92795c24 00000078`1fabe2a8 : 0x00007ff7`d80d8946
00000078`1fabe0c0 00007ff7`d80d8b79 : 000001ab`92795710 000001ab`9279f568 000001ab`92795c24 00000078`1fabe2a8 : 0x00007ff7`d80d898b
00000078`1fabe0f0 00007ff7`d80d89f4 : 000001ab`92739e08 000001ab`92795008 00000078`1fabe1f0 000001ac`b7af5d90 : 0x00007ff7`d80d8b79
00000078`1fabe120 00007ff7`d80d8b79 : 000001ab`92794d18 000001ab`92795bc8 000001ab`927952c4 00000078`1fabe2a8 : 0x00007ff7`d80d89f4
00000078`1fabe160 00007ff7`d80d8a76 : 000001ab`92795210 000001ab`92795bc8 000001ab`927952c4 00000078`1fabe2a8 : 0x00007ff7`d80d8b79
00000078`1fabe190 00007ff7`d80d8ae9 : 000001ab`92794d18 000001ab`92795268 000001ab`92795064 00000078`1fabe2a8 : 0x00007ff7`d80d8a76
00000078`1fabe1c0 00007ff7`d80d8b79 : 000001ab`927938c8 000001ab`92795268 000001ab`92795064 00000078`1fabe2a8 : 0x00007ff7`d80d8ae9
00000078`1fabe200 00007ff7`d80d8bc6 : 000001ab`92794fb0 000001ab`92795268 000001ab`92795064 00000078`1fabe2a8 : 0x00007ff7`d80d8b79
00000078`1fabe230 00007ff8`14ea57ba : 000001ab`92791c60 000001ab`92795008 00000078`1fabe2b0 00000078`1fabe2a8 : 0x00007ff7`d80d8bc6
00000078`1fabe260 00007ff8`15574bb3 : 000001ab`92739e08 000001ab`92739e08 00000078`1fabe470 00000078`1fabe2b0 : System_Web_ni+0x2f57ba
00000078`1fabe2f0 00007ff8`14e66590 : 000001ab`92739e08 000001ab`92739e08 00000078`1fabe470 00000078`1fabe2b0 : System_Web_ni+0x9c4bb3
00000078`1fabe330 00007ff8`14e7ac6c : 000001ab`92733810 000001ab`92739e08 00000078`1fabe470 00000000`00000000 : System_Web_ni+0x2b6590
00000078`1fabe380 00007ff8`14e67089 : 000001ab`92739a90 00007ff8`14e7a0a6 00000000`00000000 00000078`1fabe570 : System_Web_ni+0x2cac6c
00000078`1fabe4c0 00007ff8`14e7909b : 00000078`1fabe4c0 00007ff8`14ed40f5 00000078`1fabe558 00007ff8`14c0a6d0 : System_Web_ni+0x2b7089
00000078`1fabe510 00007ff8`14e681bd : 000001aa`92799ef8 000001ab`9272e020 000001ab`9272e378 00000000`00000000 : System_Web_ni+0x2c909b
00000078`1fabe590 00007ff8`14e67dc3 : 00000000`00000000 000001aa`91d2aa08 00000000`00000000 00000000`00000000 : System_Web_ni+0x2b81bd
00000078`1fabe730 00007ff8`15563592 : 000007f0`e084fce1 00000000`00000000 00007ff8`2f4c0df0 00007ff8`2f511d38 : System_Web_ni+0x2b7dc3
00000078`1fabe770 00007ff8`3758221e : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : System_Web_ni+0x9b3592
00000078`1fabe7e0 00007ff8`2f51183f : 000001aa`91d2aa08 00000078`00000000 000001aa`91d2ae38 000001aa`91d2aeb4 : clr!UMThunkStub+0x6e
00000078`1fabe870 00007ff8`2f5204ba : 00007ff8`00000000 00007ff8`2f4b3ed0 000001aa`91d2aa08 000001aa`91d2aa08 : webengine4!W3_MGD_HANDLER::ProcessNotification+0x8e
00000078`1fabe8a0 00007ff8`2f5115fb : 00007ff8`2f4b3ed0 00000000`00000080 000001aa`91d2aa08 00000000`00000000 : webengine4!W3_MGD_HANDLER::DoWork+0x3a5
00000078`1fabe910 00007ff8`2f573b21 : 00000000`00000000 00000000`00000000 0000d54a`f3ef32bb 000001aa`91d29180 : webengine4!RequestDoWork+0x3fc
00000078`1fabe9b0 00007ff8`2f4bd3d9 : 00000000`00000000 00000000`00000000 000001aa`91b1fd30 ffffffff`00000000 : webengine4!CMgdEngHttpModule::OnExecuteRequestHandler+0x21
00000078`1fabe9f0 00007ff8`2f4bcd7c : 000001aa`91b1fd30 00000078`1fabeb01 00000000`00000016 000001aa`91d29190 : iiscore!NOTIFICATION_CONTEXT::RequestDoWork+0xb9
00000078`1fabea40 00007ff8`2f4bcbc6 : 00000000`00000000 00000000`00000000 000001aa`91b1fd30 00000000`00000000 : iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+0x19c
00000078`1fabeb50 00007ff8`2f4bde08 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : iiscore!NOTIFICATION_CONTEXT::CallModules+0x36
00000078`1fabebb0 00007ff8`2f4b7956 : 00007ff8`2f4b7880 00007ff8`14f87b88 000001ac`b7af5d90 000001aa`91b1fd30 : iiscore!NOTIFICATION_MAIN::DoWork+0x3d8
00000078`1fabeed0 00007ff8`2f56f481 : 000001aa`91d29180 00007ff8`2f4b7880 00000078`1fabf060 ffffffff`fffffffe : iiscore!W3_CONTEXT_BASE::IndicateCompletion+0xd6
00000078`1fabef50 00007ff8`2f5720c2 : 00000078`1fabf1b0 00000078`1fabf1b0 00000078`1fabf500 00000000`00000000 : webengine4!W3_MGD_HANDLER::IndicateCompletion+0x5d
00000078`1fabef80 00007ff8`14ed4f9e : 00000000`00000000 00007ff8`375846d5 00000078`1fabefa0 00006202`e851b47c : webengine4!MgdIndicateCompletion+0x22
00000078`1fabefb0 00007ff8`14e68385 : 000001aa`91d2aa08 00000078`1fabf1b0 00000078`1fabf018 00000078`1fabf178 : System_Web_ni+0x324f9e
00000078`1fabf070 00007ff8`14e67dc3 : 00000000`00000000 000001aa`91d2aa08 00000078`1fabf2b0 00000000`00000000 : System_Web_ni+0x2b8385
00000078`1fabf210 00007ff8`15563592 : 000001ac`b7a94820 000001aa`91d2aa08 00000000`00000003 00000000`00000004 : System_Web_ni+0x2b7dc3
00000078`1fabf250 00007ff8`37582473 : ffffffff`ffffffff 00007ff8`00000001 000001aa`91cbb501 00007ff8`3758a528 : System_Web_ni+0x9b3592
00000078`1fabf2c0 00007ff8`3764cfba : 00460054`0045004e 00007ff8`37585b35 ffffffff`fffffffe 00007ff8`3758a270 : clr!UM2MThunk_WrapperHelper+0x43
00000078`1fabf300 00007ff8`3758a9c8 : 00000078`1fabf428 00000000`00000000 000001ac`b7af5d90 00007ff8`375866af : clr!UM2MThunk_Wrapper+0x60
00000078`1fabf350 00007ff8`3764d065 : 00000078`1fabf501 00000000`00000002 000007f0`e084ee51 00000078`1fabf560 : clr!Thread::DoADCallBack+0x13d
00000078`1fabf510 00007ff8`3758241d : 000001aa`92293c30 ffffffff`ffffffff 00000000`00000003 00000000`00000000 : clr!UM2MDoADCallBack+0xb3
00000078`1fabf590 00007ff8`2f51183f : 00000000`00000000 000001aa`91d2aa08 00000000`00000003 00000000`00000004 : clr!UMThunkStub+0x26d
00000078`1fabf620 00007ff8`2f511792 : 000001aa`00000004 000001aa`91d2aa08 00007ff8`37ec4410 00000078`1fabf800 : webengine4!W3_MGD_HANDLER::ProcessNotification+0x8e
00000078`1fabf650 00007ff8`375899e7 : 000001aa`91d2aa08 00007ff8`2f511750 00007ff8`37ec4410 000001ac`b7af5d90 : webengine4!ProcessNotificationCallback+0x42
00000078`1fabf680 00007ff8`3758819c : 00007ff8`37589a70 00000078`1fabf700 00000078`1fabf801 00000000`00bbd38e : clr!UnManagedPerAppDomainTPCount::DispatchWorkItem+0x1bc
00000078`1fabf720 00007ff8`37587f45 : 00000001`00010002 00000000`00000001 000001ac`b7af5d90 00000000`00000001 : clr!ThreadpoolMgr::ExecuteWorkRequest+0x64
00000078`1fabf750 00007ff8`37632e8f : 00000000`00000000 00000000`00000001 00000000`00000001 00000000`00000804 : clr!ThreadpoolMgr::WorkerThreadStart+0xf5
00000078`1fabf7f0 00007ff8`45878364 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : clr!Thread::intermediateThreadProc+0x86
00000078`1fabfa30 00007ff8`47967091 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0x14
00000078`1fabfa60 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x21

大家一眼可以看出 IPHLPAPI!SendARP ，从字面上看正是发送ARP请求的API。但是中间的一大串0x00007ff7`d84ab0fb的解析则需要!sos来处理，

而从stack上的.Net String object中，我们可以找到确切发送ARP的target address，

不过瘾的话，我们把IL打印出来分析一下，甚至把dll从dump中保存出来，使用Reflector来反编译

后记

从.Net的callstack，我们可以非常明确总结延迟问题发生的逻辑，

用户的 .Net应用程序 从MySQL server获取信息后还需要写回访问日志，但是程序追求收集客户端的MAC Address信息，导致系统不断往外发送ARP直至超时。这个代码在本地子网自然是没有什么问题的，但一旦跨网段后，ARP总是收不到任何响应，进而阻塞后续的响应操作，因此这种没有必要的操作是需要尽量避免的。

在后面对.Net程序的IL分析中，我们也看到了代码中GetWebClientHostname的调用，其实是调用DNS做PTR的反向查询（可以从之前的抓包中也看到DNS PTR的Query，原谅我一开始没有注意到这个）。相对于ARP，不管是否查询成功，如果DNS server alive的话，总会是有响应的，因此对延迟的影响不是很大。但这类操作对于来自公网的客户端访问可能意义并不是很大，建议使用Request.UserHostName替代，避免不必要的延迟。