Dr. Dobb's Journal July 2002
Accurately measuring the performance characteristics of web applications under realistic loads is a difficult task. Many web applications are designed for hundreds or thousands of concurrent users, but it's not always possible to simulate this level of use before a system goes into production. Subsequently, performance measurement is often ignored until the site is deployed and users complain that it's "too slow."
Making the task harder, the architecture of modern web applications is complex and can involve multiple underlying technologies. A typical site might use Microsoft's IIS web server, dozens or hundreds of ASP pages coded in VBScript or JScript, a middle tier of COM+ objects implemented in C++ or Visual Basic (perhaps using some third-party libraries), and a database tier accessed via ADO or ODBC. Where do you begin to look for performance problems? What you need is a way to profile the running system so you can gather quantitative data.
The structure of a web application provides an opportunity to centralize performance monitoring since every client request must pass through the web server. Therefore, if you can extend the web server to monitor performance, you can identify the worst-performing resource requests. Luckily, many commercial web servers do offer hooks for extending functionality. In this article, I present an Internet Server API (ISAPI) filter for Microsoft IIS that does just this. The complete source code and related files for this filter are available electronically; see "Resource Center," page 5.
MonitorIsapiFilter is an ISAPI filter that watches all requests sent to IIS, then maintains statistics for each unique resource. Over time, these statistics reveal the true run-time characteristics of the web application. Statistics the filter tracks include:
You can view the current performance data by requesting a special URI. The filter dumps data out in a tab-delimited format, and if you have Microsoft Excel installed, it opens in the browser window displaying the data, as in Figure 1 (collected while using the IIS Administration site on my machine). The filter persists its data across server restarts so you can collect data over long periods of time.
The advantages of monitoring performance with MonitorIsapiFilter include:
ISAPI extensions, functionally equivalent to in-process CGIs, are plug-ins requested like other server resources — via specific URIs. IIS responds to the request by making a function call into your ISAPI extension DLL, which does some work and writes data back to the client.
However, MonitorIsapiFilter is implemented using a lower level plug-in type called an "ISAPI filter," which is not requested directly, but is registered with IIS to receive specific event notifications on every HTTP request and response. This ability to see and respond to every HTTP request that crosses the server lets you implement a global performance monitor for all requested resources.
Like every ISAPI filter, MonitorIsapiFilter is a standard Win32 DLL that exports three functions. IIS calls the first function, GetFilterVersion(), once when the service starts up. The filter sets the dwFlags field in pVer to indicate the events for which it would like to receive callback notifications.
BOOL WINAPI GetFilterVersion(
PHTTP_FILTER_VERSION pVer
);
HttpFilterProc() is the function IIS calls whenever one of the registered events occurs. The pfc structure is essentially a wrapper around the socket connection between the client and server. The filter uses this to query HTTP request headers, read IIS server variables, and write data back to the client. pvNotification contains extra information specific to the callback. Depending on the value of notificationType, the filter implementation must cast pvNotification to a pointer to one of several structure types. IIS may call HttpFilterProc() several times during the lifetime of a single HTTP request, depending on the notifications the filter registered to receive.
DWORD WINAPI HttpFilterProc(
PHTTP_FILTER_CONTEXT pfc,
DWORD notificationType,
LPVOID pvNotification
);
The last filter function, TerminateFilter(), is called once by IIS when it is shutdown in an orderly fashion. This gives the filter a chance to free resources before being unloaded from memory.
BOOL WINAPI TerminateFilter(
DWORD dwFlags
);
To implement performance monitoring, MonitorIsapiFilter needs to know when a resource request begins, how many bytes the server sends to the client for the requested resource, and when the resource request ends. This requires the following notifications, defined in the ISAPI header file httpfilt.h:
In MonitorIsapiFilter, HttpFilterProc() delegates work to several helper functions based on notification type, casting the pvNotification pointer to the appropriate type for that notification. OnNotifyUrlMap() (Listing One) handles the SF_NOTIFY_URL_MAP callback, and is the first notification of a new HTTP request. If the request is not for an internal command (a command that dumps the dataset or resets counters), I find an available ContextInfo structure and set its start time to the current time. ContextInfo structures are stored in a structure called ContextMap, which is actually a fixed-length array of size MAX_CONCURRENT_REQUESTS. I wanted to avoid allocating memory for a ContextInfo structure on each request because access to the global heap is serialized and dynamic memory allocation is relatively slow. This can cause a severe performance bottleneck in a busy server processing hundreds of concurrent requests. Since I want to ensure the performance monitoring code doesn't introduce additional performance problems, I quickly scan the small ContextMap array to find an available ContextInfo structure (Listing Two). If none are available, I skip logging performance info for the request. To identify subsequent event notifications for the same request, I cast the HTTP_FILTER_CONTEXT pointer to a DWORD and store this key in the ContextInfo structure.
OnSendRawData() handles the SF_NOTIFY_SEND_RAW_DATA notification. All that is required is to look up the ContextInfo structure for the request and increment the number of bytes sent so far. This event notification can occur many times for requests that generate a lot of data.
OnEndOfRequest() (Listing Three) is where most of the work happens. At this point, the request has been serviced and IIS is ready to accept another request or drop the connection. Again, I look up the ContextInfo structure, then calculate the elapsed duration for the request by subtracting the current time from the start time stored in OnNotifyUrlMap(). The filter uses Windows's high-resolution timer API function QueryPerformanceCounter() to achieve submicrosecond resolution (the standard timer API, GetTickCount(), only has 10-ms resolution on NT 3.5+, 55 ms on Windows 95/98).
The next step involves PageMap, a standard STL map that associates string URIs with PageInfo pointers. For this data structure, I used dynamic memory allocation for two reasons:
The PageInfo structures store cumulative stats for each resource request, including the total number of requests, min/max/avg bytes, and min/max/avg duration. At the end of OnEndOfRequest(), the filter dumps statistics for the request to any attached debugger via the Win32 call OutputDebugString(). Rather than run IIS under a debugger, I usually use the excellent DebugView utility (http://www.sysinternals.com/ntw2k/freeware/debugview.shtml); see Figure 2.
Again, the filter allocates memory when it encounters a unique URI. This should raise a red flag because it opens a potential denial of service attack. If attackers knew a web site was using MonitorIsapiFilter, they could continually request random URIs, causing the filter to allocate memory without bound. To avoid this, I trap the SF_NOTIFY_SEND_RESPONSE event in OnNotifySendResponse() (Listing Four). If the URI request results in a "404 Not Found" error, I skip performance monitoring for the request. URIs are also stripped of any querystring parameters before being added to the PageMap. This avoids a proliferation of URIs being stored for the same resource.
Internal commands are handled by OnInternalRequest. Here I check the client's IP to make sure it's in one of the nonroutable address ranges (for example, 172.16.0.0-172.31.255.255; see RFC 1597). This prevents random clients on the Internet from issuing commands to reset the performance monitor or dump its current dataset. This minimal authentication scheme could be enhanced to require user names and passwords to access performance data.
When authorized clients request a dump of the dataset, DumpProfileData (Listing Five) renders the dataset into a tab-delimited text stream and writes the data back to the client. The trick here is setting the HTTP Content-Type header to application/vnd.ms-excel. If Excel is installed and you are using Internet Explorer, Excel loads the data directly and displays it in the browser window.
MonitorIsapiFilter can be installed either at the server or web-site level. If you install it at the server level, it sees all requests for all active web sites on the server. To install the filter, open the Internet Services Manager and edit the properties for the server or site. Click on the IIS Filters tab and add MonitorIsapiFilter.dll to the list.
If you use a cluster of load-balanced web servers, it's a good idea to initially install MonitorIsapiFilter on all the web servers. The first time I tried this in production at my current place of employment, I immediately saw a load-balancing problem that was resulting in three times as much traffic sent to one server than the others. If all your web servers are running identical hardware/software and load balancing is working properly, you can choose to run MonitorIsapiFilter on a single web server, since data collected there is representative of any machine in the cluster.
You can control MonitorIsapiFilter with special URI commands starting with the characters "monitor-isapi-filter." Type an address like http://www.myserver.com/monitor-isapi-filter in your browser to invoke the command. Table 1 lists the supported commands.
You can turn the filter on/off without having to shutdown IIS and uninstall the filter. When the filter is off, overhead is on the order to 10 microseconds per request. When the filter is on, performance monitoring is active and the overhead is on the order of 0.5 milliseconds per request.
When you issue the reset command, the filter saves its current dataset to a file of format c:\mif-data-YYYYMMDD-HHMMSS.txt, using the current date and time for the last part of the filename. If you cycle IIS, the filter saves its current dataset in a file called c:\mif-data.txt. reset must be issued via HTTP POST instead of GET. This makes it harder to accidentally reset the counters.
Before trying to interpret the performance data MonitorIsapiFilter gathers, let it run long enough to track hundreds or thousands of requests. That way, the data will better reflect average behavior and won't be thrown off by a few requests that had very high latency (or returned an unusually large amount of data). Once you have a statistically significant sample, you can start to draw some conclusions about how your web application performs:
These are just a few of the issues to consider when viewing statistics collected by MonitorIsapiFilter. Time and experience will show other ways to gain insight from the information. After identifying problem resources, you can use finer grained instrumentation to discover the underlying causes. This instrumentation will necessarily be specific to your site.
DDJ
// Handler for SF_NOTIFY_URL_MAP notification
DWORD OnNotifyUrlMap(
PHTTP_FILTER_CONTEXT pfc,
HTTP_FILTER_URL_MAP* pUrlMap
)
{
// If this is an internal request, handle it now
if( strstr( pUrlMap->pszURL, "monitor-isapi-filter" ) ) {
return OnInternalRequest( pfc, pUrlMap );
} else if( !bOn ) {
// Otherwise, if turned off, disable notifications & exit
DisableNotifications(pfc);
return SF_STATUS_REQ_NEXT_NOTIFICATION;
} // if
// Get context data structure for this request
ContextInfo* pContextInfo=contextMap.GetOrCreateContextInfo( (DWORD) pfc );
if( pContextInfo ) {
// No need to lock pContextInfo; it can only be active in
// one invocation of HttpFilterProc at a time
pContextInfo->start = StartTiming();
pContextInfo->bytes = 0;
} else {
TRACE0("[MIF] INFO: failed to create context info in OnNotifyUrlMap\n");
} // else
return SF_STATUS_REQ_NEXT_NOTIFICATION;
}
// Fetches ContextInfo pointer from list, assigns a new
// slot for it if it doesn't already exist
inline ContextInfo* ContextMap::GetOrCreateContextInfo(
DWORD dwKey
)
{
int slot=0;
CritSectLock lock(&cs); // lock list
ContextInfo* pInfo = internalGetContextInfo( dwKey, &slot );
if( (pInfo == NULL) && slot>0 ) {
// We didn't find it, but there is a slot available
pInfo = &(info[slot]);
pInfo->Clear();
pInfo->key = dwKey;
} // if
return pInfo;
}
// Fetches ContextInfo pointer from map if available. While scanning list,
// keep track if you've found any empty slots. If return value is NULL,
// then pnAvailSlot may point to a nonzero available slot number if a slot was
// available. NOTE: caller must synchronize access to the info data structure
inline ContextInfo* ContextMap::internalGetContextInfo(
DWORD dwKey,
int* pnAvailSlot
)
{
for( int i=0; i<MAX_CONCURRENT_REQUESTS; i++ ) {
ContextInfo* pInfo = &(info[i]);
if( pInfo->key == dwKey ) {
return pInfo;
} else if( pInfo->key == 0 ) {
*pnAvailSlot = i;
} // else
} // for
return NULL;
}
// Handler for SF_NOTIFY_END_OF_REQUEST notification
DWORD OnEndOfRequest(
PHTTP_FILTER_CONTEXT pfc
)
{
// Get context data structure for this request
ContextInfo* pContextInfo = contextMap.GetContextInfo( (DWORD) pfc );
if( pContextInfo ) {
// NOTE: no need to lock pContextInfo since it can only
// be active in one invocation of HttpFilterProc at a time
// Get URL of request
char szPageName[MAX_URL_LEN];
GetRequestUrl( pfc, szPageName, MAX_URL_LEN );
// Get or create data structure for this page
PageInfo* pPageInfo = pageMap.GetOrCreatePageInfo( szPageName );
if( pPageInfo ) {
CritSectLock lock(&(pPageInfo->cs)); // lock PageInfo structure
DWORD dwDuration = (DWORD) EndTiming( pContextInfo->start );
// If duration is truncated to 0, bump it to min resolution of 1ms
if( dwDuration == 0 ) {
dwDuration = 1;
} // if
DWORD dwBytes = pContextInfo->bytes;
pPageInfo->numcalls++;
pPageInfo->duration.Update(dwDuration);
pPageInfo->bytes.Update(dwBytes);
// Make copies of pPageInfo data so we can exit critsect before
// expensive sprintf/trace calls
long numcalls = pPageInfo->numcalls;
Counter duration = pPageInfo->duration;
Counter bytes = pPageInfo->bytes;
// Release page and context info, unblocking waiting threads
lock.Unlock();
contextMap.FreeContextInfo(pContextInfo);
TRACE10( "[MIF] %s: calls=%lu, time=%lu (min=%lu, max=%lu,
avg=%lu), bytes=%lu (min=%lu, max=%lu, avg=%lu)\n", szPageName,
numcalls, dwDuration, duration.dMin, duration.dMax,
duration.Average(numcalls), dwBytes, bytes.dMin, bytes.dMax,
bytes.Average(numcalls));
} else {
TRACE0( "[MIF] INFO: failed to get or create
page info in OnEndOfRequest\n" );
} // else
} else {
TRACE0("[MIF] INFO: failed to get context info in OnEndOfRequest\n");
} // else
return SF_STATUS_REQ_NEXT_NOTIFICATION;
}
// Handler for SF_NOTIFY_SEND_RESPONSE
DWORD OnSendResponse(
PHTTP_FILTER_CONTEXT pfc,
HTTP_FILTER_SEND_RESPONSE* pfsr
)
{
// The monitor SF_NOTIFY_SEND_RESPONSE to avoid a possible DoS attack
// Since we allocate memory on each unique URI served, malicious attackers
// could hit server with random URIs, filling our memory. Therefore if we
// see that this request resulted in a 404 Not Found error, we skip
// logging for this request
if( pfsr->HttpStatus == 404 ) {
ContextInfo* pContextInfo = contextMap.GetContextInfo( (DWORD) pfc );
if( pContextInfo ) {
contextMap.FreeContextInfo( pContextInfo );
} // if
DisableNotifications( pfc );
} // if
return SF_STATUS_REQ_NEXT_NOTIFICATION;
}
// Dumps profile data in tab-delimited format to the browser.
DWORD DumpProfileData(
PHTTP_FILTER_CONTEXT pfc
)
{
LPCSTR FIRSTLINE =
"PageName\tNumCalls\tMinDuration\tMaxDuration\tAccumDuration\tAvgDuration\t"
"MinBytes\tMaxBytes\tAccumBytes\tAvgBytes\tAvgBytesPerSec\n";
LPCSTR HEADERS = "HTTP/1.0 200 OK\r\n"
"Content-Type: application/vnd.ms-excel\r\n"
"Cache-Control: no-cache\r\n"
"Expires: Mon, 09 Oct 2000 16:00:00 GMT\r\n"
"Pragma: no-cache\r\n"
"\r\n";
DWORD dwLen = strlen(HEADERS);
pfc->WriteClient( pfc, (LPVOID)HEADERS, &dwLen, 0);
dwLen = strlen(FIRSTLINE);
pfc->WriteClient( pfc, (LPVOID)FIRSTLINE, &dwLen, 0);
strstream stream;
pageMap.Dump(stream);
dwLen = stream.pcount();
pfc->WriteClient( pfc, stream.str(), &dwLen, 0);
return SF_STATUS_REQ_FINISHED;
}