July, 2008

  • Never doubt thy debugger

    LogParser did it again: application pool recycle

    • 1 Comments

    This started as a “standard” w3wp.exe crash, but this time IIS was also randomly disabling one of the application pools on the server. This is a protection mechanism we have since IIS 6 called Rapid Fail Protection that disables ad application pool (for security and stability reasons) if it fails (encounters severe errors) too often: how often and how much time it’s configurable (see Configuring Rapid-Fail Protection in IIS 6.0), the default is 5 failures in 5 minutes.

    Looking at the System event log there were plenty of messages like:

    A worker process with process id of 'xxx' serving application pool 'MyAppPool' has requested a recycle because it reached its virtual memory limit.

    And also:

    A process serving application pool 'MyAppPool' exceeded time limits during shut down. The process id was 'xxx'.

    How often? As usual, LogParser comes at hand.

    logparser 
        "select quantize(TimeGenerated, 300) as TimeGen, count(*) as NumberOfrecycles
        into memory_limit_recycles.log from system.evt 
        where EventID = 1077 and Message like '%\'MyAppPool%' group by TimeGen order by TimeGen" 
        -i:evt -o:nat -rtp:-1

    Note the “quantize” function: LogParser help states “Truncates a value to the nearest multiple of another value”; what it actually does in the command above is count the number of recurrences of a certain event in “blocks” of 5 minutes (300 seconds in my sample).

    The output is something like:

    Generated           NumberOfRecycles 
    ------------------- ----------------
    2008-07-06 21:55:00 5
    2008-07-06 22:00:00 5
    2008-07-06 22:05:00 5
    2008-07-06 22:10:00 4
    2008-07-06 22:15:00 4
    2008-07-06 22:20:00 3
    2008-07-06 22:25:00 1
    2008-07-06 22:30:00 2
    2008-07-06 22:35:00 1
    2008-07-06 22:40:00 2
    2008-07-06 22:45:00 1
    2008-07-06 22:50:00 2
    2008-07-06 22:55:00 1
    2008-07-06 23:00:00 2
    2008-07-06 23:05:00 1
    2008-07-06 23:10:00 2
    2008-07-06 23:15:00 1
    2008-07-06 23:20:00 2
    2008-07-06 23:25:00 1
    2008-07-06 23:30:00 2
    2008-07-06 23:35:00 3
    [...]

    As you can see the pool is recycled quite often, event 4-5 times every 5 minutes, exactly the default limit configured for pool heal checking in IIS… Moreover we don’t have to forget about the second error message:

    logparser 
        "select quantize(TimeGenerated, 300) as TimeGen, count(*) as ShutDownLimit into ShutDownLimit.log 
        from system.evt where Message like '%\'MyAppPool%' and Message like '%exceeded time limits during shut down%' 
        group by TimeGen order by TimeGen" -i:evt -o:nat -rtp:-1

    And the output is:

    TimeGen             ShutDownLimit 
    ------------------- -----
    2008-07-09 09:05:00 3
    2008-07-09 10:00:00 5
    2008-07-11 14:40:00 3
    2008-07-15 10:50:00 5
    2008-07-15 11:30:00 3
    2008-07-15 13:00:00 3
    2008-07-15 14:45:00 3
    2008-07-15 14:50:00 4
    2008-07-15 14:55:00 3
    2008-07-15 16:15:00 3
    2008-07-15 16:20:00 4
    2008-07-15 16:40:00 3
    2008-07-15 16:45:00 3
    2008-07-15 17:00:00 3
    2008-07-15 17:25:00 3
    2008-07-15 17:30:00 3
    2008-07-15 17:40:00 3
    2008-07-15 17:45:00 3
    2008-07-15 17:55:00 3
    2008-07-15 18:00:00 4

    Sometimes we’re clearly exceeding the configured pool health checking so really no surprise IIS disables it.

    But why the pool is recycled so often? Well, we found a mistake in customer’s configuration: the application pool was configured to be recycled when the virtual memory reached 50 Mb, definitely a value too low. Increasing it to resolved also this problem: no more pool recycles and as obvious side effect the users noticed an increased stability and performance when working with the application.

     

    Carlo

    Quote of the day:
    A wise man gets more use from his enemies than a fool from his friends. - Baltasar Gracian
  • Never doubt thy debugger

    Time-taken and LogParser for web site statistics

    • 2 Comments

    The time-taken field is quite handy if your web application or IIS web server is performing poorly (or slower that you expect) or even for simple statistics and monitoring purposes, if you want to keep under how long it takes every web request to be processed and the page sent back to the client.

    In earlier versions of IIS the time-taken field was not selected by default so I often had to request customers to first enable it, wait some more time for the problem to reoccur (to give IIS the change to create a significant amount of logs with the new value) before being able to start troubleshooting. Well, at least before being able to extract some statistics involving the duration of web requests.

    Time Taken logging property in IIS 6

    Luckily in IIS 7 time-taken is now selected by default so we already it logged and ready to use.

    Taken from the IIS online docs, here is the meaning each field in IISW3C logs:

    Date (date) Logs the date on which the request occurred. Selected by default
    Time (time) Logs the time, in Coordinated Universal Time (UTC), at which the request occurred. Selected by default

    Client IP Address (c-ip)

    Logs the IP address of the client that made the request. Selected by default.
    User Name (cs-username) Logs the name of the authenticated user who accessed the server. Anonymous users are indicated by a hyphen. Selected by default.
    Service Name (s-sitename) Logs the Internet service name and instance number that was running on the client at the time that the incident was logged.
    Server Name (s-computername) Logs the name of the server on which the log file entry was generated.
    Server IP Address (s-ip) Logs the IP address of the server on which the log file entry was generated. Selected by default.
    Server Port (s-port) Logs the server port number that is configured for the service. Selected by default.
    Method (cs-method) Logs the HTTP method, such as GET, that is used in the request. Selected by default.
    URI Stem (cs-uri-stem) Logs the Uniform Resource Identifier (URI) that is the target of the action, such as Default.htm. Selected by default.
    URI Query (cs-uri-query) Logs the query, if any, that the client was trying to perform. A URI query is necessary only for dynamic pages. Selected by default.
    Protocol Status (sc-status) Logs the HTTP status code. Selected by default.
    Protocol Substatus (sc-substatus) Logs the HTTP substatus code. Selected by default.
    Win32 Status (sc-win32-status) Logs the Windows status code. Selected by default.
    Bytes Sent (sc-bytes) Logs the number of bytes that the server sent.
    Bytes Received (cs-bytes) Logs the number of bytes that the server received.
    Time Taken (time-taken) Logs the length of time that the action took in milliseconds. Selected by default.
    Protocol Version (cs-version) Logs the protocol version, HTTP or FTP, that the client used.
    Host (cs-host) Logs the host header name, if any.

    Note:
    The host name that you configure for your Web site might appear differently in the log files because HTTP.sys logs host names by using the punycode-encoded format.

    User Agent (cs(User-Agent)) Logs the browser from which the request came. Selected by default.
    Cookie (cs(Cookie)) Logs the content of the cookie sent or received, if any.
    Referer (cs(Referer) ) Logs the site that the user last visited. This site provided a link to the current site.


    What does time-taken actually measures? It measures the length of time that it takes for a request to be processed. The client-request time stamp is initialized when HTTP.sys receives the first byte of the request. HTTP.sys is the kernel-mode component that is responsible for HTTP logging for IIS activity. The client-request time stamp is initialized before HTTP.sys begins parsing the request. The client-request time stamp is stopped when the last IIS response send completion occurs. Beginning in IIS 6.0, the time-taken field typically includes network time. Before HTTP.sys logs the value in the time-taken field, HTTP.sys usually waits for the client to acknowledge the last response packet send operation or HTTP.sys waits for the client to reset the underlying TCP connection. Therefore, when a large response or large responses are sent to a client over a slow network connection, the value of the time-taken field may be more than expected.

    A few samples

    If you are either troubleshooting or just monitoring your site/IIS, LogParser can be extremely useful to elaborate statistics and charts out of your IIS logs, find average and peak execution time for your pages and web services etc…


    For example if you want to get the average execution time for your .aspx (or .asmx) pages/services you can run something like:

    logparser 
        "SELECT AVG(time-taken) As AverageTimeTaken, MAX(time-taken) As MaxTimeTaken, COUNT(*) As Hits, TO_LOWERCASE(cs-uri-stem) As Uri
        INTO average_uri_execution_time.log FROM ex*.log 
        WHERE EXTRACT_EXTENSION(TO_LOWERCASE(cs-uri-stem)) = %1
        GROUP BY TO_LOWERCASE(cs-uri-stem) 
        ORDER BY AverageTimeTaken DESC"  
        -i:IISW3C -o:TSV

    Note: the command must be placed on a single line, I split it here just to be easier to read

    Using the IISW3C input format, if you have your logs organized in subfolders you can parse them all at once appending “-recurse:-1” to the command above.


    Here you can get the top n slowest pages to complete:

    logparser 
        "SELECT TOP 100 time-taken, cs-uri-stem 
        INTO top_time_taken.log FROM ex*.log 
        WHERE extract_extension(to_lowercase(cs-uri-stem)) = 'aspx' 
        ORDER BY time-taken DESC" 
        -i:iisw3c -o:tsv


    If you are interested only on a specific timeframe (say you had a load pick and want to know more) you can take the cue from here:

    logparser 
        "SELECT AVG(time-taken) As AverageTimeTaken, MAX(time-taken) As MaxTimeTaken, COUNT(*) As Hits, TO_LOWERCASE(cs-uri-stem) As Uri 
        INTO date_range.txt FROM *.log 
        WHERE TO_TIMESTAMP(date,time) BETWEEN TIMESTAMP('2008/05/27 10:11:00', 'yyyy/MM/dd hh:mm:ss') AND TIMESTAMP('2008/05/27 10:13:00', 'yyyy/MM/dd hh:mm:ss') 
        GROUP BY TO_LOWERCASE(cs-uri-stem)" 
        -i:IISW3C -RECURSE:-1 -o:NAT -RTP:-1


    If you want an overview of resource types served by your IIS (with resource I mean every file extension IIS logs) you can use something like this:

    logparser 
        "select to_lowercase(extract_extension(cs-uri-stem))as ResourceType, MIN(time-taken) as MinTimeTaken, MAX(time-taken) as MaxTimeTaken, AVG(time-taken) as AvgTimeTaken, COUNT(*) as Hits 
        INTO timers.txt FROM time-taken.log GROUP BY ResourceType" 
        -i:IISW3C -o:NAT -RTP:-1

    A few words about the load you add on the serve enabling additional fields for IIS logs: the default files are essentially the same in IIS 6 and 7 except for time-taken which is now enabled by default on IIS 7. This suggests the load you’ll add to the server is negligible, but as always is really depends on your server and application; to stay on the safe side you can add fixed-size fields, for example handle with case the cookie field, enable it if you need to troubleshoot specific problems involving cookies (session mixed-up etc…), otherwise just leave it off.

     

    Carlo

    Quote of the day:
    Art is science made clear. - Jean Cocteau
  • Never doubt thy debugger

    Visual Studio 2008 crashes in “split view”

    • 14 Comments

    “Split view” is one of the new features in Visual Studio 2008 web designer: this is the possibility to have Design View and Source View of your page at the same time (see What's New in ASP.NET and Web Development, “Visual Web Developer Enhancements” paragraph). A few days ago a customer called in to report a problem with his Visual Studio and split view: when trying to view a file (even a new one) in split view or design view the IDE either crashed or frozen.

    As you can imagine we took a crash dump with adplus, but a first look at the threads, stack, exceptions etc… (the usual stuff) did not show anything interesting. Then I thought to some external process (like an antivirus, third parties add-ons etc…) that might meddle in and had a look at the list of modules loaded within the process with lmf (list loaded modules with full path). There where only a couple of odd dlls loaded, from Office 2003:

    33f20000 34118000   FPCUTL     (deferred)             
        Image path: C:\Program Files\Microsoft Office\OFFICE11\FPCUTL.DLL 
        Image name: FPCUTL.DLL 
        Timestamp:        Wed Jun 06 19:44:55 2007 (4666F297) 
        CheckSum:         001EC356 
        ImageSize:        001F8000 
        File version:     11.0.8170.0 
        Product version:  11.0.8170.0 
        File flags:       0 (Mask 3F) 
        File OS:          40004 NT Win32 
        File type:        2.0 Dll 
        File date:        00000000.00000000 
        Translations:     0409.04e4 
        CompanyName:      Microsoft Corporation 
        ProductName:      Microsoft Office 2003 
        InternalName:     FP40CUTL 
        OriginalFilename: FP40CUTL.DLL 
        ProductVersion:   11.0.8170 
        FileVersion:      11.0.8170 
        FileDescription:  Microsoft Office FrontPage Client Utility Library 
        LegalCopyright:   Copyright © 1995-2003 Microsoft Corporation.  All rights reserved. 
    
    
    37050000 37157000   OMFC       (deferred)             
        Image path: C:\Program Files\Microsoft Office\OFFICE11\OMFC.DLL 
        Image name: OMFC.DLL 
        Timestamp:        Fri Apr 13 21:43:21 2007 (461FDD59) 
        CheckSum:         0010A869 
        ImageSize:        00107000 
        File version:     11.0.8164.0 
        Product version:  11.0.8164.0 
        File flags:       0 (Mask 3F) 
        File OS:          40004 NT Win32 
        File type:        2.0 Dll 
        File date:        00000000.00000000 
        Translations:     0000.04e4 
        CompanyName:      Microsoft Corporation 
        ProductName:      Microsoft Office 2003 
        InternalName:     OMFC.DLL 
        OriginalFilename: OMFC.DLL 
        ProductVersion:   11.0.8164 
        FileVersion:      11.0.8164 
        FileDescription:  Microsoft Office MFC 
        LegalCopyright:   Copyright © 1993-2003 Microsoft Corporation.  All rights reserved. 

    That rang a bell, especially about fpcutl.dll… This dll comes with both Visual Studio and Office 2003 but the two versions are incompatible: Visual Studio in this case was loading the wrong one. Why?

    Well, it happens that Visual Studio looks at the system PATH to load this (and other) component, while Office doesn’t… Here is the PATH value from the dump (use !procinfo and then check the path value):

    C:\WINDOWS\system32;
    C:\WINDOWS;
    C:\WINDOWS\System32\Wbem;
    C:\Program Files\Microsoft SQL Server\90\Tools\binn\;
    C:\Program Files\Microsoft SQL Server\90\DTS\Binn\;
    C:\Program Files\Microsoft SQL Server\90\Tools\Binn\VSShell\Common7\IDE\;
    C:\Program Files\Microsoft Visual Studio 8\Common7\IDE\PrivateAssemblies\;
    C:\PROGRA~1\MICROS~2\OFFICE11

    The Office 11 entry is the last one… but there is something wrong anyway, who spots it? smile_regular

    We have an entry for Visual Studio 8 (Visual Studio 2005), but where is the entry for Visual Studio 9 (VS 2008)? smile_nerd

    For some reason the PATH value has not been updated (or maybe it has modified after the setup) and we don’t know exactly why; the point is that we need to fix it. A quick search on the machine found three copies of fpcutl.dll:

    fpcutil paths

    System Path

    We added the missing folders at the beginning of the PATH string which now reads as:

    C:\Program Files\Microsoft Web Designer Tools\VWD;
    C:\Program Files\Microsoft Visual Studio 9.0\Common7\IDE;
    C:\Program Files\Microsoft Visual Studio 9.0\VC\BIN;
    C:\Program Files\Microsoft Visual Studio 9.0\Common7\Tools;
    C:\Windows\Microsoft.NET\Framework\v3.5;
    C:\Windows\Microsoft.NET\Framework\v2.0.50727;
    C:\Program Files\Microsoft Visual Studio 9.0\VC\VCPackages;
    C:\WINDOWS\system32;
    C:\WINDOWS;
    C:\WINDOWS\System32\Wbem;
    C:\Program Files\Microsoft SQL Server\90\Tools\binn\;
    C:\Program Files\Microsoft SQL Server\90\DTS\Binn\;
    C:\Program Files\Microsoft SQL Server\90\Tools\Binn\VSShell\Common7\IDE\;
    C:\Program Files\Microsoft Visual Studio 8\Common7\IDE\PrivateAssemblies\;
    C:\PROGRA~1\MICROS~2\OFFICE11

    The most important one on this case is “C:\Program Files\Microsoft Web Designer Tools\VWD”: Visual Studio will look into this folder to load the right version of fpcutl.dll (PATH is a first in – first serve list of folders, the first match will be the one we use) and Office continues working happily anyway. smile_nerd

    Carlo

     

    Quote of the day:
    Any sufficiently advanced technology is indistinguishable from magic. - Arthur C. Clarke
Page 1 of 1 (3 items)