locked
Handler Mapping Delay RRS feed

  • Question

  • User-1049198391 posted

    We have an issue with a .net2 asmx web service running on Windows 2008 R2 SP1, IIS7.5, x64.

    Calls to the web service take 15-17 seconds to complete for EACH AND EVERY request.  In test the same calls take 1-2 seconds.  When called from localhost the web service returns in 1-2 seconds.

    Network and SQL trace captures appear to have ruled out these as the cause and a data collector set that is tracing the asp.net events appears to be  backing this up indicating that the delay is incurred during the mapping of the handler and then again during the execution of the handler.

    The exact same symptoms are present for all instances of the web services on the machine.

     

    Here are the results of a SOAP POST to the .asmx captured in a Data Collector Set that is tracing asp.net events.  See delay in mapping the handler.  I removed some class identifiers:

    Step Name Elapsed (millisecs) Duration (millisecs)
    Create App Domain 0 0.13
    Enter App Domain: /LM/W3SVC/1/ROOT/xxxxxxxxxx-1-130431422522900584 0.2 0
    xxxxxxxxxx.xxxxxxxxxx.Global 0.5 0.01
    System.Web.Security.WindowsAuthenticationModule 0.52 0.06
    System.Web.Security.PassportAuthenticationModule 0.59 0.01
    xxxxxxxxxx.Security.WebSecurityModule 0.61 37.88
    System.Web.Handlers.ScriptModule 38.5 0.01
    xxxxxxxxxx.xxxxxxxxxxService.Global 38.51 0
    System.Web.Security.DefaultAuthenticationModule 38.52 0
    System.ServiceModel.Activation.HttpModule 38.52 0.01
    System.Web.Security.UrlAuthorizationModule 38.53 0.02
    System.Web.Security.FileAuthorizationModule 38.56 0
    System.Web.Caching.OutputCacheModule 38.56 0
    ASP.NET Map Handler 38.57 8,987.16
    System.Web.SessionState.SessionStateModule 9,025.75 0.02
    System.Web.Profile.ProfileModule 9,025.77 0.01
    System.Web.Handlers.ScriptModule 9,025.79 0.01
    ASP.NET Execute Handler 9,025.80 6,515.30
    xxxxxxxxxx.Security.WebSecurityModule 15,541.12 0.01
    System.Web.SessionState.SessionStateModule 15,541.14 0.01
    System.Web.Caching.OutputCacheModule 15,541.15 0.01
    System.Web.SessionState.SessionStateModule 15,541.16 0
    System.Web.Security.PassportAuthenticationModule 15,541.17 0
    System.Web.Profile.ProfileModule 15,541.18 0
    xxxxxxxxxx.Security.WebSecurityModule 15,541.19 0
    System.Web.Handlers.ScriptModule 15,541.20 0.01 <div></div> <div></div>

     

    A very similar delay is experienced on each and every visit to the .asmx page through a browser too.  I set up a test virtual dir on the same box and enabled tracing (localOnly=false) and this is what it is capturing (on every request):

    Trace Information

    Category Message From First(s) From Last(s)
    aspx.page Begin PreInit
    aspx.page End PreInit 6.73269926764435E-05 0.000067
    aspx.page Begin Init 9.27492181268848E-05 0.000025
    aspx.page End Init 0.000132419064434167 0.000040
    aspx.page Begin InitComplete 0.000151695257358128 0.000019
    aspx.page End InitComplete 0.000169853989822729 0.000018
    aspx.page Begin PreLoad 0.00018689526182797 0.000017
    aspx.page End PreLoad 0.000211479391933891 0.000025
    aspx.page Begin Load 0.000230476219743012 0.000019
    aspx.page End Load 0.00274224796726958 0.002512
    aspx.page Begin LoadComplete 0.00278191781357687 0.000040
    aspx.page End LoadComplete 0.00280035591115631 0.000018
    aspx.page Begin PreRender 0.00281767654827639 0.000017
    aspx.page End PreRender 0.00284561305976039 0.000028
    aspx.page Begin PreRenderComplete 0.00286656544337339 0.000021
    aspx.page End PreRenderComplete 0.00288332735026379 0.000017
    aspx.page Begin SaveState 0.00582420391418462 0.002941
    aspx.page End SaveState 0.00585744836285059 0.000033
    aspx.page Begin SaveStateComplete 0.00587840074646359 0.000021
    aspx.page End SaveStateComplete 0.00589572138358367 0.000017
    aspx.page Begin Render 0.00591220392535923 0.000016
    aspx.page End Render 0.00682572785088608 0.000914

    and here is the Data Collector Trace for the GET request through a browser which shows delays at the same events but also a little more information in teh Execution event, although the delay has already occurred at that point:

    <div expandable="1">Step Name</div> Elapsed (millisecs) Duration (millisecs)
    Request Starts 0 0
    Create App Domain 0 0.04
    Enter App Domain: /LM/W3SVC/1/ROOT/xxxxxxxTest-2-130432366474863084 0.08 0
    xxxxxxx.xxxxxxxService.Global 1.02 0
    System.Web.Security.WindowsAuthenticationModule 1.03 0.04
    System.Web.Security.PassportAuthenticationModule 1.08 0
    xxxxxxx.Security.WebSecurityModule 1.08 25.22
    System.Web.Handlers.ScriptModule 26.32 0.01
    xxxxxxx.xxxxxxxService.Global 26.33 0
    System.Web.Security.DefaultAuthenticationModule 26.34 0.01
    System.ServiceModel.Activation.HttpModule 26.35 0.02
    System.Web.Security.UrlAuthorizationModule 26.37 0.02
    System.Web.Security.FileAuthorizationModule 26.4 0
    System.Web.Caching.OutputCacheModule 26.4 0
    ASP.NET Map Handler 26.41 4,538.89
    System.Web.SessionState.SessionStateModule 4,565.32 0.01
    System.Web.Profile.ProfileModule 4,565.34 0.01
    System.Web.Handlers.ScriptModule 4,565.35 0
    Bitmap
    ASP.NET Execute Handler
    4,565.35 4,514.08
         
    <div expandable="1"><form> <div expandable="1">Step Name</div> </form></div> Elapsed (millisecs) Duration (millisecs)
    Page PreInit 9,065.92 0
    Page Init 9,065.98 0.02
    Page Load 9,066.14 2.56
    Page PreRender 9,068.81 0.01
    Page Save Viewstate 9,072.04 0
    Page Render 9,072.13 0.94
       
    xxxxxxx.Security.WebSecurityModule 9,079.45 0.01
    System.Web.SessionState.SessionStateModule 9,079.46 0
    System.Web.Caching.OutputCacheModule 9,079.47 0
    System.Web.SessionState.SessionStateModule 9,079.48 0
    System.Web.Security.PassportAuthenticationModule 9,079.48 0.06
    System.Web.Profile.ProfileModule 9,079.56 0
    xxxxxxx.Security.WebSecurityModule 9,079.56 0
    System.Web.Handlers.ScriptModule 9,079.57 0 <div></div> <div></div>

     

    Could anyone suggest a configuration setting that could be causing this delay?  Such as caching or recompile? 

    Are there any counters or other data collector event traces that would shed light?

     

    Thanks

    C

    Tuesday, April 29, 2014 10:34 AM

All replies