Using Custom Profiling APIs
Like the debugging APIs that the .NET Framework supports, an interface is available that can be used to profile .NET applications. The primary documentation for the profiling interface is in the Tools Developers Guide in a file called Profiling.doc. The API consists of two COM interfaces: ICorProfilerCallback and ICorProfilerInfo. To build a profiler, the programmer must implement the methods that are part of ICorProfilerCallback. The profiler is implemented as an in-process COM DLL. This DLL implements the ICorProfilerCallback interface. ICorProfilerInfo is an interface that is implemented in the CLR and queried for during the initialization of the profiler.
The SDK ships with two sample profilers that illustrate what is involved in building a profiler for managed code. Each of the samples is included in the profiler directory because the projects have been modified so that you can use Visual Studio .NET to compile and run the profilers. A General Code Profiler can be found in the gcp_profiler directory, and a Hot Spots Tracker can be found in the hst_profiler directory. These projects have been copied into gcp and hst directories respectively, and they have been modified so that they can be compiled with Visual Studio .NET.
Each of the samples follows the same setup process. After the code has been compiled and the resulting DLL properly linked, all you need to do is run a simple batch file called EnableProfiler.bat from a Command Prompt window. This batch file registers the COM DLL and sets two environment variables:
Cor_Enable_Profiling—This environment variable is set to a non-zero value to turn on profiling.
Cor_Profiler—This environment variable is set to the CLSID or ProdID of the COM component that implements the ICorProfilerCallback interface.
Running any managed process under this environment will result in the CLR doing the equivalent of CoCreateInstance to instantiate the CoClass that implements the ICorProfilerCallback interface. After an instance of the interface has been created, the CLR calls the Initialize method of this interface. The implementation of the Initialize method is responsible for setting flags to indicate the events to receive. These flags and the implementation of the various methods in the ICorProfilerCallback are what differentiate one profiler from another. The Initialize method is also where the profiler should query for ICorProfilerInfo so that additional information can be obtained from the CLR about the profiling process. When the process is finished, the CLR will call the Shutdown method of ICorProfilerCallback.
General Code Profiler
The General Code Profiler (GCP) sets the flags for the events for which it is to listen for, as shown in Listing 20.34.
Listing 20.34. General Code Profiler Event Flags
m_dwEventMask = (DWORD) ( COR_PRF_MONITOR_CLASS_LOADS
| COR_PRF_MONITOR_MODULE_LOADS
| COR_PRF_MONITOR_ASSEMBLY_LOADS
| COR_PRF_MONITOR_APPDOMAIN_LOADS
| COR_PRF_MONITOR_JIT_COMPILATION
| COR_PRF_MONITOR_EXCEPTIONS
| COR_PRF_MONITOR_THREADS
| COR_PRF_MONITOR_CODE_TRANSITIONS
| COR_PRF_MONITOR_ENTERLEAVE
| COR_PRF_MONITOR_CACHE_SEARCHES
| COR_PRF_DISABLE_INLINING );
|
Specifically, notice that the following are not defined (refer to corprof.h and to page 58 of Profiling.doc):
COR_PRF_MONITOR_FUNCTION_UNLOADS
COR_PRF_MONITOR_GC
COR_PRF_MONITOR_OBJECT_ALLOCATED
COR_PRF_MONITOR_REMOTING
COR_PRF_MONITOR_CCW
COR_PRF_MONITOR_REMOTING_COOKIE
COR_PRF_MONITOR_REMOTING_ASYNC
COR_PRF_MONITOR_SUSPENDS
COR_PRF_MONITOR_CLR_EXCEPTIONS
COR_PRF_ENABLE_REJIT
COR_PRF_ENABLE_INPROC_DEBUGGING
COR_PRF_ENABLE_JIT_MAPS
COR_PRF_DISABLE_OPTIMIZATIONS
COR_PRF_ENABLE_OBJECT_ALLOCATED
As you can see from the previous list of options that the GCP does not use, many profiling options can be associated with a profiling application.
This sample profiler records the information as the events are called. Most functions follow the same format. Look at Listing 20.35, which illustrates the implementation of the method AppDomainCreationFinished (defined in ProfilerGCP.h, which is part of the source for this profiler).
Listing 20.35. GCP AppDomainCreationFinished Callback Implementation
HRESULT ProfilerCallback::AppDomainCreationFinished(AppDomainID appDomainID,
HRESULT hrStatus)
{
_ASSERT_( SUCCEEDED( hrStatus ) );
try
{
AddAppDomain( appDomainID );
}
catch ( BaseException *exception )
{
exception->ReportFailure();
delete exception;
Failure();
}
return S_OK;
} // ProfilerCallback::AppDomainCreationFinished
|
The way that each of the callbacks records an event is to enter it into a table. The GCP has a series of tables in ProfilerHelper.h. The tables look like Listing 20.36.
Listing 20.36. GCP Tables
// tables SList<ClassInfo *, ClassID> *m_pClassTable; SList<ThreadInfo *, ThreadID> *m_pThreadTable; SList<ModuleInfo *, ModuleID> *m_pModuleTable; SList<FunctionInfo *, FunctionID> *m_pFunctionTable; SList<AssemblyInfo *, AssemblyID> *m_pAssemblyTable; SList<AppDomainInfo *, AppDomainID> *m_pAppDomainTable; |
When the profile session is complete and the Shutdown method has been called, GCP dumps the contents of the tables in a routine DumpTables(), as shown in Listing 20.37.
Listing 20.37. DumpTables in GCP
Earlier it was said that you could invoke any managed process in the profile environment. That's not completely true. Here, due to the implementation using wprintf, only Console applications will properly display the output of the profiler. The output from a managed application looks like Listing 20.38.
Listing 20.38. Output from the GCP
This profiler builds a list based on each event called. Other than just confirming that certain classes and functions were instantiated and executed, this sample does not do much. In Listing 20.38, the profiler is used to profile some code, TraceSwitch, which was introduced in the previous chapter. As you can see from the output, the method WriteDebugOutput was called once and exited once. In addition, the address of the function is recorded. None of the other profiling tools that have been introduced thus far can give you this kind of information about a managed process. Until profilers for managed code are commercially available, these profiling APIs might be your only choice.
Windows General Code Profiler
Many of the principles that were developed in the previous section were used to create a more user-friendly profiler by providing a graphical user interface for profiling. This profiler has been named WinGCP because it takes much of the information provided by the GCP profiler presented earlier and formats it into a more presentable Windows UI.
To use the profiling API, you have to profile the .NET application completely devoid of managed code. A user interface could have been developed using MFC, but it would have been a difficult task. A method was needed to completely separate the UI from the function. One way of accomplishing this is to separate the UI and the profiler with a socket connection.
Profiling proceeds as with the GCP described earlier. When the process that is being profiled finishes, the GCP dumps all of the information out to the console or file. With WinGCP, you can dump the information in an XML format to a memory stream, open up a socket, and output the data to the UI server. Listing 20.39 captures the important points about the data transfer from the client (the profiler) to the server (the UI).
Listing 20.39. Output and Connection from WinGCP
!= 0)
{
::closesocket(socket);
socket = INVALID_SOCKET;
return;
}
// Send the date
long lTotalBytes;
long nBytes = lTotalBytes = ::send(socket,
(LPCSTR)out.str().c_str(),
out.str().length() * sizeof(wchar_t), 0);
while(lTotalBytes < out.str().length()*sizeof(wchar_t))
{
nBytes = ::send(socket,
(LPCSTR)out.str().c_str() + lTotalBytes,
(out.str().length() * sizeof(wchar_t)) - lTotalBytes, 0);
lTotalBytes += nBytes;
}
::closesocket(socket);
socket = INVALID_SOCKET;
When the managed process has exited, the information is transferred from the client (profiler) to the server (the UI). The first part of Listing 20.39 shows the beginning of formatting the output as XML. Following the dump of the profile statistics to an XML stream, the server and the server port are found using the environment variables COR_PROFILER_SERVER and COR_PROFILER_SERVER_PORT. Then a connection is created to the server, and the profile statistics are written out to the server.
Listing 20.40 shows how the server or user interface portion of WinGCP sets up and starts the client process.
Listing 20.40. WinGCP Server Setting Up and Starting the Profile Client
ProcessStartInfo psi;
if(arguments.Text.Length > 0)
psi = new ProcessStartInfo(pathToFile.Text, arguments.Text);
else
psi = new ProcessStartInfo(pathToFile.Text);
psi.EnvironmentVariables.Add("DBG_PRF_LOG", "1");
psi.EnvironmentVariables.Add("Cor_Enable_Profiling", "1");
psi.EnvironmentVariables.Add("COR_PROFILER", "{01568439-E2BA-4434-8ACC-816239E8B8B5} ");
// psi.EnvironmentVariables.Add("COR_PROFILER_SERVER_PORT", "8085");
// psi.EnvironmentVariables.Add("COR_PROFILER_SERVER", "localhost");
psi.UseShellExecute = false;
int pos = pathToFile.Text.LastIndexOf("\");
psi.WorkingDirectory = pathToFile.Text.Substring(0, pos);
Process p = Process.Start(psi);
|
Notice that this is the only part of the application that is dependent on the server and the client both residing on the same machine. With a little imagination, you could easily adapt this code using remoting so that the client profiler could run on virtually any machine. The server just listens for the results back from the client (see Listing 20.41).
Listing 20.41. WinGCP Server Listening for Results
listeningClient = new TcpListener(8085);
listeningClient.Start();
try
{
bool continueProcessing = true;
while(continueProcessing)
{
Socket s = listeningClient.AcceptSocket();
NetworkStream ns = new NetworkStream(s);
XmlTextReader channel = new XmlTextReader(ns);
profileInfoInterface.ProcessData(channel);
}
}
catch(Exception e)
{
// SocketException when listeningClient.Stop is called
// during an AcceptSocket.
// "A blocking operation was interrupted by a call to
// WSACancelBlockingCall"
Debug.WriteLine(e);
}
finally
{
listeningClient.Stop();
}
|
In this thread, the server listens for the data coming from the client, decodes the XML stream, and then displays the results to the user in the dialog box. By separating the presentation from the data, WinGCP enhances the original GCP visually. In addition, the original GCP can now can be used to profile non-console applications (Windows apps).
The cracking of the XML message and the display of the results are not shown for the purpose of keeping this presentation as compact as possible. The complete source for this application is in the WinGCP directory.
Finding Frequently Accessed Code with the Hot Spots Tracker
As a final example of using the profiling API, this section will discuss the Hot Spots Tracker (HST) that is part of the Framework SDK. You can find the original source in Program FilesMicrosoft Visual Studio .NETFrameworkSDKTool Developers GuideSamplesprofilerhst_profiler or see the slightly modified version in the hst directory of the samples for this book. This profiling tool illustrates how changing some of the events to which the profiling tool listens can greatly affect the profiler implementation.
The HST supports even fewer flags than GCP did, as evidenced in Listing 20.42.
Listing 20.42. Flags for the HST Profiler
m_dwEventMask = (DWORD)(COR_PRF_MONITOR_THREADS |
COR_PRF_DISABLE_INLINING |
COR_PRF_MONITOR_SUSPENDS |
COR_PRF_MONITOR_ENTERLEAVE |
COR_PRF_MONITOR_EXCEPTIONS |
COR_PRF_MONITOR_CODE_TRANSITIONS);
|
In many ways, this profiler provides more useful profiling information than the GCP profiler. The HST tracks the time spent in each function. When a function is entered, the Enter method is called. The Enter method looks like Listing 20.43.
Listing 20.43. HST Implementation for the Enter Method
The Enter callback method calls UpdateCallStack with a PUSH, and the Leave callback method calls UpdateCallStack with a POP. The TimerTracker simply adds a time stamp to the class so that it can be calculated later how long this function was executed.
This profiler also has a DumpTables method, which is implemented in Listing 20.44.
Listing 20.44. HST Implementation of DumpTables
This function prints a header and calls the Dump method for the Thread table, which is reproduced in Listing 20.45.
Listing 20.45. HST Implementation of Dump
The HST profiler can be used with any managed process because the output is written to a file. The LOG_TO_FILE macro determines how the profile information is output.
#define LOG_TO_FILE( message ) BASEHELPER::LogToFile message;
This function opens the file output.log.
stream = ((count == 1) ? fopen( "output.log", "w" ) :
fopen( "output.log", "a+" ));
When you use this profiler, you get output that looks like Listing 20.46.
Listing 20.46. HST Output
Because this file is neatly delimited by semi-colons, you can import it into an Excel spreadsheet and sort based on columns. This was done in Figure 20.18.
