Profiling Plug-in Performance

Polling versus Instrumented Profiling

There are two types of profiling that may be done. One is called Polling and the other is called Instrumented.

Polling profiling requires no special compliler settings other than generating debug information (a PDB file). This works by setting up a separate thread and periodically looking at the context of the main thread. It looks at the instruction pointer to determine what instruction the CPU is at and stores this information. When finished, the stored addresses are used to report the module, source file and line number of the function (see below for the details on enabling these options).
Instrumented profiling requires a special compiler setting but provides much more accurate profiling information.

Typically both of these are used. The polling profiler is used first to get a rough idea of where the greatest amount of execution time is being spent. Then instrumented profiling is done for those time consuming areas. This allows one to get a quick overview using polling and then collect very accurate, detailed information using instrumented profiling.

Preparing For Profiling -- Compiler and Link Settings

There are several things that need to be done to get a plug-in ready for profiling. These are:

1. Generating debugging information.

2. For Instrumented Profiling Only -- Linking to the profiling LIB file.

3. For Instrumented Profiling Only -- Compiling using a special compiler flag.

These steps are outlined below:

1. You need to make sure debugging information is available. This can be turned on in the IDE using Project / Settings / C++ Tab and choosing General from the Category dropdown and choosing Program Database from the Debug info combo box. You'll also need to check the Generate Debug Info check box in the General Category of the Link Tab of the dialog. This will cause a PDB file to be written. The profiler needs the PDB file in order associate the addresses it collects as the program executes with actual entry points in the code.

2. For Instrumented Profiling Only -- You must add ACAP.LIB to the plug-ins link libraries. This is done using the Project / Add To Project / Files command from the pulldown menus. From the dialog presented choose \MAXSDK\LIB\ACAP.LIB.

3. For Instrumented Profiling Only -- to work the plug-in must be compiled with a special compiler flag: /Gh. This option isn't available through the IDE in a check box -- it must be manually typed into the Project Options list. You access this list from the IDE using Project / Settings / C++ Tab / General Category . At the beginning of the list of options add /Gh. What the /Gh option does is instruct the compiler to call a special function named penter() prior to doing anything for every procedure entry point. The penter() function is provided by the profiler and is used to collect all the profiling information.

Using the 3ds Max Profiler Plug-in

The profiler is a utility plug-in (\MAXSDK\PLUGIN\MAXPROF.DLU) with an interface in both the command panel and a small floating dialog. The command panel interface is used to indicate which type of profiling is done, which information is written to the output file, and what file name its written to. The floating dialog is used for starting, stopping, saving and clearing the profile recording.

To run the profiler select 3ds Max Profiler from the list of utility plug-ins. A smaller floating dialog appears as well as the command panel interface. Via radio buttons in the Collection area choose if you want to perform Instrumented or Polling profiling.

To collect profiling information you select the options you want to record using the check boxes in the Report area of the command panel rollup. Next choose the desired output file name, from the Output rollup. By default the output file is written to maxprof0.txt in the same directory as the currently loaded 3ds Max file.

Once these choice have been made, click on the Record button in the floating dialog. This puts the profiler in record mode -- ready for the collection of profiling information.

Next, simply use the plug-in you wish to profile. For instance, if your plug-in is a modifier, apply it to an object and adjust its settings. As you work with the plug-in, or 3ds Max calls its methods, the profiling information is collected. The floating dialog stays active even if you leave the utility branch of the command panel so you're free to use all of 3ds Max to fully test your plug-in. Note that the profiler is persistent even through a 3ds Max File / Reset operation. This allows developers to track what calls are made during a Reset as well. If you want to reset the profiling information, press the Clear button on the floating dialog.

This section list each of the controls in the command panel user interface:

Report section:

The check boxes in this section determine which portions of the output file are written. Below is a description of each of the options in this dialog. The sample output file shown later in this topic shows an example what is written for each of these.

Summary: This generates some basic information about the speed of the machine 3ds Max is running on, the amount of time spent profiling, and the number of functions that were profiled.
Module list: This generates a list of all the modules that are loaded into process memory.
M ax stack depth : This reports the maximum depth of function calls the profiler reached.

The following options are reported for every function that is called. These items appear as columns of data in a table where each row represents one function call.

Time (in msecs): This is the amount of time spent in the function in milliseconds. This is labeled SelfTime in the output table.
Time (in ticks): This is amount of time spent in the function in ticks. This is labeled SelfTicks in the output table.
Time (in percent): This is the time in a function as a percent of the overall time spent in all the functions that were profiled. This is labeled SelfPercent in the output table.
Child times: If this is checked, three new columns are added to the output table. These are labeled HierTicks, HierTime and HierPercent. These are similar to those above, but include not only the function itself, but also any functions it calls. This one is useful because you can sort the table by child times (in a spreadsheet such as Excel) and it will display the most time intensive functions first.
Recursion counts: This option is useful if you have recursive functions. It shows how many time the function calls back on itself. This is labeled Recursions in the output table.
Calling functions: This generates a multiline entry. For each function profiled, a list of all the functions, or places within a function, that called it are shown. This also lists how many times each of the functions called it.
Function addresses: This generates the address in memory for the function. This is labelled Address in the output.
Source module: This generates the name of the module (the name of the DLL that the profiled function lives in). If you are running under NT5 and have IMAGEHLP.DLL you'll get the source file name and line number. This is labelled Module in the output. The number of calls (labeled Count in the output table) is always reported. This is the number of times the function was entered.

Output section:

Output file selector button: By default, the output is written to the path where the 3ds Max file was loaded. Clicking on this button brings up the file selector dialog for choosing a new output file.

Increment after save: This check box is enabled only when the filename has a number or numbers at the end. If checked, the file name shown on the button is incremented each time the profiling information is saved. If unchecked, the file is overwritten on a save.

Clear data after save: This check box resets the profiler after each time the profiling information is saved. If this is off, profiling information continues to accumulate after a save.

Close: This closes the 3ds Max Profiler plug-in in the user interface.

This section list the controls in the floating dialog.

The floating dialog has three buttons used for starting/stopping, saving and clearing the profile recording.

Record / Stop: This button is used to start and stop the collection of profiling information.

Save: This button is used to save the collected profiling information to disk.

Clear: This button is used to reset the profiling information so new recording will start from a clear state. If you want to clear out any existing profiling information generated press this button.

Interpreting the Profiler Output File

This section presents an example of output from the profiler and describes the meaning of each section.

The summary section:

This section is written if the 'Summary' check box is checked.

Tue Jul 29 15:46:10 1997
WinNT 4.0
microSecsPerTick 0.12126

This simply gives data about the timing of the CPU. This is the number of micro seconds per tick. Tick counts are used in several places in the profiler output.

Ticks (elapsed/counted) 1860866843/305119085

This tells how many CPU ticks went by during the run of the profiler (between when the Record and Stop buttons were pressed) over how many were actually collected (counted) by the profiler.

Secs (elapsed/counted) 225.649/36.9988

This tells the same information as above, only in seconds.

Total functions 76

This is the total number of functions that were profiled.

Total calls 7493

This is the total number of calls that were found while profiling.

The module list section:

This section is written if the 'Module list' check box is checked.

module  base
3dsmax  0x400000
ntdll  0x77f60000
. . .etc. . .
GDI5  0x33600000
SZB5  0x33200000
msafd  0x77660000
wshtcpip  0x77690000

This simply lists all the modules that are loaded into process memory and the address of where they actually wound up.

Max stack depth section.

This section is written if the 'Max stack depth' check box was checked.

Max Stack Depth 8

This indicates how far into the procedure chain the profiler was used. That is, how many calls deep was the profiler involved in. This number is exclusive of recursion.

The profiling data section.

The data shown below is copied from an Excel spreadsheet to make it appear in a table format. In pure text form as output by the profiler the data is tab delimited. One can simply copy this data to the clipboard, paste it into Excel, and it fills out the spreadsheet cleanly into rows and columns. The data here is just as described above under the user interface controls. Of particular note is the list of calling functions. When that option is checked the table may contain multiple lines per function. For each function profiled, a list of all the functions, or places within a function, that called it are shown. This also lists how many times each of the functions called it. For example, in the table below, GetString() was called 13 times, 1 time by EnterMode(), 4 times by DoPoint(), 1 time by DefineStroke(), 2 times by DefineStroke() at a different address, 3 times by UpdateStrokeInfo(), and 2 times by ReviewStrokes().

Count Recursions SelfTicks SelfTicks/Call SelfTime SelfPercent HierTicks HierTime HierPercent Address Function Module

13 0 7502 577 1 0 7502 1 0 822087728 GetString stroke!E:\devel\3dswin\src\DLL\STROKE\stroke.cpp@44

1 822090354 StrokeCMode::EnterMode +32 stroke!@

4 822091673 StrokePrgm::DoPoint +69 stroke!@

1 822101165 StrokeTable::DefineStroke +60d stroke!@

2 822102498 StrokeTable::DefineStroke +b42 stroke!@

3 822103004 UpdateStrokeInfo +7c stroke!@

2 822105572 StrokeTable::ReviewStrokes +7b4 stroke!@

3 0 1050 350 0 0 1050 0 0 822087792 BuildStrokeSetPathName stroke!E:\devel\3dswin\src\DLL\STROKE\stroke.cpp@179

1 822100149 StrokeTable::DefineStroke +215 stroke!@

2 822103881 StrokeTable::ReviewStrokes +119 stroke!@

21 0 1727 82 0 0 1727 0 0 822087968 Stroke::Stroke stroke!E:\devel\3dswin\src\DLL\STROKE\stroke.cpp@424

21 822103715 StrokeTable::ReviewStrokes +73 stroke!@

144 0 885 6 0 0 885 0 0 822088224 Stroke::GetFunctionName stroke!E:\devel\3dswin\src\DLL\STROKE\stroke.cpp@447

60 822089505 StrokeTable::Sort +51 stroke!E:\devel\3dswin\src\DLL\STROKE\stroke.cpp@583

60 822089514 StrokeTable::Sort +5a stroke!E:\devel\3dswin\src\DLL\STROKE\stroke.cpp@590

1 822101304 StrokeTable::DefineStroke +698 stroke!@

20 822102448 StrokeTable::DefineStroke +b10 stroke!@

3 822102962 UpdateStrokeInfo +52 stroke!@

31 0 17268 557 2 0 17268 2 0 822088256 Stroke::Save stroke!E:\devel\3dswin\src\DLL\STROKE\stroke.cpp@451

31 822089776 StrokeTable::Save +80 stroke!@

Profiling and Processors

The profiler forces 3ds Max to run on a single processor. This provides more accurate timing results than trying to collect the data from multiple processors.