Compartir a través de

WCF service startup too slow? Have you thought to CRL check?

  • Artículo

A customer of mine was experiencing an annoying delay when calling a WCF service hosted in IIS6. He provided the following elements with the issue description:

"The delay only occurs when calling the WCF service the first time. The following calls were executed in a reasonable time. It was enough to restart the client application to reproduce the delay on the first call."

"As many assembly references the service includes, the longer the time spent to execute the first call."

To be honest the customer solution was rather complex, including several WCF services calling each other, and Sharepoint as well, but this is not fundamental to our purpose.
When looking at the WCF traces, I couldn't notice any meaningful delay: looked like the service started receiving network data after the delay was spent.
The client appeared stuck during wait on service reply. What was happening?

I thought to ask for network traces on the server, and suddenly noticed something interesting: there were several DNS requests to a host named "crl.microsoft.com". In that case the DNS request kept failing, I guess that had been increasing the delay. I filtered traffic on HTTP and DNS protocols, and found something like that:

    1: 1275   66.940689     {HTTP:35, TCP:34, IPv4:33} 10.15.0.2     10.15.2.64    HTTP   HTTP: Request, POST /NetSourcingServices/UserManagementService.svc 

    2: 1277   67.056225     {HTTP:35, TCP:34, IPv4:33} 10.15.2.64    10.15.0.2     HTTP   HTTP: Response, HTTP/1.1, Status Code = 100

    3: 1278   67.056580     {HTTP:35, TCP:34, IPv4:33} 10.15.0.2     10.15.2.64    HTTP   HTTP: HTTP Payload

    4: 1284   67.294377     {DNS:38, UDP:37, IPv4:36}  10.15.2.64    CSDC001              DNS    DNS: QueryId = 0xB1D2, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

    5: 1295   68.293987     {DNS:40, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xB1D2, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

    6: 1312   69.293905     {DNS:40, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xB1D2, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

    7: 1344   71.293828     {DNS:38, UDP:37, IPv4:36}  10.15.2.64    CSDC001              DNS    DNS: QueryId = 0xB1D2, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

    8: 1345   71.293841     {DNS:40, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xB1D2, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   10: 1425   75.293731     {DNS:40, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xB1D2, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   11: 1522   79.340669     {DNS:41, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0x5AD3, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   12: 1537   80.340345     {DNS:42, UDP:37, IPv4:36}  10.15.2.64    CSDC001              DNS    DNS: QueryId = 0x5AD3, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   13: 1554   81.340301     {DNS:41, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0x5AD3, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   14: 1570   82.458183     {DNS:38, UDP:37, IPv4:36}  CSDC001              10.15.2.64    DNS    DNS: QueryId = 0xB1D2, QUERY (Standard query), Response - Server failure 

   15: 1586   83.449603     {DNS:42, UDP:37, IPv4:36}  10.15.2.64    CSDC001              DNS    DNS: QueryId = 0x5AD3, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   16: 1587   83.449618     {DNS:41, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0x5AD3, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   17: 1598   84.160484     {DNS:40, UDP:39, IPv4:19}  CSDC002              10.15.2.64    DNS    DNS: QueryId = 0xB1D2, QUERY (Standard query), Response - Server failure 

   18: 1651   87.152577     {DNS:42, UDP:37, IPv4:36}  10.15.2.64    CSDC001              DNS    DNS: QueryId = 0x5AD3, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   19: 1652   87.152592     {DNS:41, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0x5AD3, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   20: 1728   91.777601     {DNS:46, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xC575, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   21: 1746   92.777358     {DNS:47, UDP:37, IPv4:36}  10.15.2.64    CSDC001              DNS    DNS: QueryId = 0xC575, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   22: 1780   93.777342     {DNS:46, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xC575, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   23: 1815   95.159803     {DNS:41, UDP:39, IPv4:19}  CSDC002              10.15.2.64    DNS    DNS: QueryId = 0x5AD3, QUERY (Standard query), Response - Server failure 

   24: 1818   95.457228     {DNS:42, UDP:37, IPv4:36}  CSDC001              10.15.2.64    DNS    DNS: QueryId = 0x5AD3, QUERY (Standard query), Response - Server failure 

   25: 1832   96.449083     {DNS:47, UDP:37, IPv4:36}  10.15.2.64    CSDC001              DNS    DNS: QueryId = 0xC575, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   26: 1833   96.449096     {DNS:46, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xC575, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   27: 1894   100.448957    {DNS:47, UDP:37, IPv4:36}  10.15.2.64    CSDC001              DNS    DNS: QueryId = 0xC575, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   28: 1895   100.448970    {DNS:46, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xC575, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   29: 1972   104.511458    {DNS:48, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xA60E, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   30: 2003   105.511227    {DNS:49, UDP:37, IPv4:36}  10.15.2.64    CSDC001              DNS    DNS: QueryId = 0xA60E, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   31: 2042   106.511190    {DNS:48, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xA60E, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   32: 2070   107.159070    {DNS:46, UDP:39, IPv4:19}  CSDC002              10.15.2.64    DNS    DNS: QueryId = 0xC575, QUERY (Standard query), Response - Server failure 

   33: 2086   108.456693    {DNS:47, UDP:37, IPv4:36}  CSDC001              10.15.2.64    DNS    DNS: QueryId = 0xC575, QUERY (Standard query), Response - Server failure 

   34: 2105   109.448570    {DNS:49, UDP:37, IPv4:36}  10.15.2.64    CSDC001              DNS    DNS: QueryId = 0xA60E, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   35: 2106   109.448584    {DNS:48, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xA60E, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   36: 2210   113.448417    {DNS:49, UDP:37, IPv4:36}  10.15.2.64    CSDC001              DNS    DNS: QueryId = 0xA60E, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   37: 2211   113.448431    {DNS:48, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0xA60E, QUERY (Standard query), Query  for  crl.microsoft.com of type Host Addr on class Internet

   38: 2337   118.079858    {DNS:68, UDP:39, IPv4:19}  10.15.2.64    CSDC002              DNS    DNS: QueryId = 0x4B05, QUERY (Standard query), Query  for  cssqlvs01.csf.lan of type Host Addr on class Internet

   39: 2338   118.080052    {DNS:68, UDP:39, IPv4:19}  CSDC002              10.15.2.64    DNS    DNS: QueryId = 0x4B05, QUERY (Standard query), Response - Success 

   40: 2397   118.268103    {HTTP:35, TCP:34, IPv4:33} 10.15.2.64    10.15.0.2     HTTP   HTTP: Response, HTTP/1.1, Status Code = 200

The customer declared the delay was a bit more than 50 seconds: please have a look at the time between the POST and the response.. are you able to notice anything?
There are about 50 seconds between them, and a lot of DNS queries in the middle.

What is crl.microsoft.com? The CRL acronym stands for "Certificate Revocation List". The Certificate Revocation List (CRL) is a document maintained and published by a certification authority (CA) that lists certificates issued by the CA that are no longer valid. Each signed assembly was checked against the CRL before being loaded and, as you can see in the network traces, because of the network configuration the DNS wasn't able to resolve "crl.microsoft.com".

Please have a look at this article: https://support.microsoft.com/default.aspx/kb/936707 (FIX: A .NET Framework 2.0 managed application that has an Authenticode signature takes longer than usual to start): "When you start a Microsoft .NET Framework 2.0 managed application that has a Microsoft Authenticode signature, the .NET Framework 2.0 managed application takes longer than usual to start."; "This problem occurs because a .NET Framework 2.0 managed assembly that has an Authenticode signature takes longer than usual to load. The signature is always verified when the .NET Framework 2.0 managed assembly that has an Authenticode signature is loaded."

Since you’re using .NET 3.*, you could simply add the entry below to both the application config files:

    2: <configuration>

    3:     <runtime>

    4:          <generatePublisherEvidence enabled="false"/>

    5:     </runtime>

    6: </configuration>

    7: 

So if you observe a strange delay during your application start up, just check if you're trying to load Authenticode signed assembly in your application, and introduce the configuration entry above as a double check.
Cheers,

Andrea

Comments