locked
Hanging Classic ASP calls in IIS7 on Win 2008 Server x64 RRS feed

  • Question

  • User-1511395129 posted

    We're hosting a number of sites on a Windows 2008 Server x64 platform with IIS7. Most of these sites are low in traffic and a few quite frequently accessed.

    Most of the sites are Classic ASP sites and we're using ISAPIRewriteModule from Helicon as an ISAPI filter to process URLs.

     Most of the time, all is well with our hosting situation, but we've as of lately seen a weird situation that we can't understand. The thing is that random (or seemingly so) requests seems to be hanging and doing nothing for hours on end (or until we restart the application pool). When we run the command

    appcmd.exe list requests | find /c "ISAPI"

    on a hanging application pool, we can get an answer that looks like the following:

    -------------------------------------------------------------------------------

    REQUEST "f5000082800038d7" (url:GET /listSentLetters.asp, time:5498146 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "8f0000038000246c" (url:GET /picrasp/small/2A368A078FD84AFCB3CBA788125B166B/thumb/small.gif, time:5333394 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "e400004180000221" (url:GET /cInc/xhtml/formValidator.js, time:5156520 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "fe000080800031c7" (url:GET /picrasp/small/036994F554CC4625B83C54B589E9DB08/thumb/small.gif, time:4987446 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "6800000280005b6d" (url:GET /picrasp/small/3A307BC4B95848CD817172C11D893DEA/thumb/small.gif, time:4923142 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "940000408000625b" (url:GET /picrasp/small/A89413A39F7045FC9B0064E8F2707377/thumb/small.gif, time:4818856 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "810000008000183c" (url:GET /addNewLetter.asp?letterID=1163F10520614A6B9508FC37F8005A3C, time:4785066 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "c100004080004920" (url:GET /picrasp/small/868FCBE8DF9742FCBFAC47EA7349AABD/thumb/small.gif, time:4784738 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "c500004080005ed4" (url:GET /picrasp/small/47BF537208C44D0AA71406C24C02328B/thumb/small.gif, time:4756175 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "f000000280002188" (url:GET /listSentLetters.asp, time:4756128 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "e1000043800023fc" (url:GET /addNewLetter.asp?letterID=1163F10520614A6B9508FC37F8005A3C, time:4700529 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "2d00004280000a08" (url:GET /, time:4691496 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "1d00004180003920" (url:GET /picrasp/small/63801EB0AD6A4A3EA14BFBD68AF6CDE0/thumb/small.gif, time:4549380 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "d2000042800015da" (url:GET /picrasp/small/36B2FF9A388A4419B9831B49D14F0FDE/thumb/small.gif, time:4501331 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "3f00000380002115" (url:GET /picrasp/small/0169225BABA44DCEBBA9306569ADF510/thumb/small.gif, time:4375594 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "0d000001800031ac" (url:GET /picrasp/small/7557DFC337DA4810ABC3CE02F473B44A/thumb/small.gif, time:4263804 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "d4000000800057cd" (url:GET /picrasp/small/06210AF1F8D54F0691F32A61BB1DBFD1/thumb/small.gif, time:4190234 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "1d00000380002ec2" (url:GET /picrasp/small/6396A4A4D09740AB803DD5D96BAC36F3/thumb/small.gif, time:4069427 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "bf00004380001474" (url:POST /saveUserInfo.asp, time:3892943 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "df000002800069d3" (url:GET /, time:3547229 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "7300000080003316" (url:GET /picrasp/small/A4684E3E068F4E2CB4153E93EAE54EE9/thumb/small.gif, time:3474907 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "5900004280004089" (url:GET /, time:2651269 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "ab00000380005c06" (url:GET /info.asp?id=7010&subCat=Stuga%2fL%e4genhet&objID=69685, time:1404 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "0400004080001015" (url:GET /info.asp?id=1015&subCat=Natur&objID=28203&lang=1033, time:1264 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)
    REQUEST "3c0000028000204b" (url:GET /skickatips.asp/parentPage/info.asp/lang/1053/id/7045, time:234 msec, client:XXX.XXX.XXX.XXX, stage:ExecuteRequestHandler, module:IsapiModule)

    -------------------------------------------------------------------------------

    As you can see, some of the requests have been running for 5498 second (90 min)  and more, which should really be impossible given the IIS7 settings. The weird thing is that these requests don't show up in the Failed Request Tracing (when the only criteria for logging is "taken more than 20 seconds") and the script time-out is set top 90 seconds. The behaviour is also hard to recreate, and we don't have any real insight as to when it happens, but when it does start, it appears to "pollute" an entire application pool, resulting in thousands of hanging requests that fires an application pool recycling.

    Now to my questions:
    1. Has anyone seen this behaviour somewhere else, and how was the issue resolved?
    2. Is there a way to locate what the hanging requests are actually doing? As it seems, they're doing nothing since CPU usage is low, and there are no database locks etc.

    Kind regards / Martin

    Tuesday, December 8, 2009 9:54 AM

All replies

  • User10285400 posted

    All of these request are in the IsapiModule ... so I would ask the ISAPI vendor to have a look at what might be causing their code to hang on you.  It's interesting that the timeout semantic didn't kill off those long-running requests; it could be this is one place where we aren't diligent in watching the time ... I'll see if we can repro this in house. 

    Dave

    Tuesday, December 8, 2009 6:33 PM
  • User-1511395129 posted

     Tank you for the quick reply Dave!

     We'll be sure to contact the ISAPI vendor in this matter if we can get som emore information about what's actually going on. These hangings only seem to happen in the case of files actually being processed by the ASP engine. Other file types (such as images etc.) never end up in this state, even though they are processed by the same ISAPI filter. We aslo often find requests in "couples" where the first request is the one being passed in to the IIS server from an end client and the second one being what the ISAP Rewrite filter passes on to be processed. This leads us to think that there is something going wrong in the plumbing between the ISAPI filter and the ASP engine during certain "unknown" circumstanses.

    Is there any tool or other means by which I can get more information about these hanging requests?

     

    Wednesday, December 9, 2009 4:24 AM
  • User10285400 posted

    I would temporarily turn on Failed Request Tracing for all requests to see if you can catch more details about where the requests are hanging ... it sounds like you're already trying to do that, so you're on the right track.  The tracing files should help clarify the largest areas by time-taken (to confirm if it's ASP or the ISAPI filter) ... this will also help track down the "kind" of URL that is causing problems ... it could be that there's something about those URL's that are causing the ISAPI filter problems. 

    Dave

    Wednesday, December 9, 2009 1:28 PM
  • User10285400 posted

    BTW, you might consider using our URL Rewrite module if you get totally stuck.

    http://www.iis.net/expand/URLRewrite 

    Wednesday, December 9, 2009 1:30 PM
  • User-1511395129 posted

     Hi Dave,

    the problem is that we don't exactly know when it happens, and it can happen during certain periods and then stop for a while and so on.

    Also, doesn't FRT only write to disk after the request has finished (given that the timeout is not set, in which case it SHOULD - all be it it doesn't - write what it has executed thus far) which would mean that these requests won't show up even if we turn the tracing on always?

    We're a bit reluctant in doing this since the traffic can be quite high and the overhead could slow the applications down.

    Friday, December 11, 2009 4:55 AM
  • User-1931101754 posted

    Hi Martin

    We have exactly the same problem and while searching on the I have come accross your post. Did you find any solutions to the problem? I am still investigating.

    Many Thanks

    Tuna Celik

    Tuesday, August 24, 2010 8:39 AM