Profiling Examples Copyright (c) 1993 SAS Institute, Inc, Cary, NC, USA All Rights Reserved =================== This directory contains a test program which is built two ways - one suitable for profiling with SPROF, one suitable for profiling with LPROF. SPROF and LPROF both try to give you information you need to determine where your code is spending most of its time, but they do it in slightly different ways. Before trying to use the profilers, build the test programs by typing "smake" in the Shell or double-clicking the Build icon from Workbench. Two different executables are built from the same source file. "stest" is compiled with the PROFILE compiler option and is therefore suitable for use with SPROF. "ltest" is compiled normally and is suitable for use with LPROF. ============= RUNNING SPROF ============= To run SPROF from the Workbench, double-click on the SPROF icon in the SC:C drawer, then double-click on the STEST program, or click on SPROF and then hold the SHIFT key and double-click on STEST. To run SPROF from the Shell, enter the following command line: sprof stest The program will take anywhere from a few seconds to a few minutes depending on the speed of your Amiga. When it finishes running, SPROF will generate a report like this: SPROF Report Status: Complete Name Count ITime ETime Pct \test.c\f100b\32 3000 5596 5596 72.8 \test.c\f100c\38 300 569 569 7.4 \test.c\f300\50 300 561 561 7.3 \test.c\f200\44 200 376 376 4.9 \test.c\f100\26 100 189 189 2.5 \test.c\f100static\20 100 186 186 2.4 \test.c\f30x100\56 30 5748 152 2.0 \test.c\main\85 1 7686 40 0.5 \test.c\f100x3\63 100 586 17 0.2 ----- ----- 7686 100.0 The "Name" field gives the function name in the format "\file\func\line". The "Count" field tells you how many times the function was called. The "ITime" field tells you how many microseconds the function was on the stack - i.e. how much time was spent in the function Including any subroutines called by the function. The "ETime" field tells you how many microseconds were spent executing the function, Excluding time spent in subroutines. The "Pct" field tells you the percentage of the total time spent in the program that was spent in the listed function. The percentage is calculated by dividing the ETime for this function by the sum of all ETime values for all functions in the program. ***** You don't have to wait until the program finishes to get a report. SPROF has the capability of producing intermediate reports. To see an intermediate report, re-run SPROF from a Shell window. Then, while the program is running, type a CTRL-F character in the Shell. SPROF will produce a report the next time any function in your program is entered or returns, or the next time a PROFILE_ON() or PROFILE_OFF() macro is called. There is no easy way to duplicate this feature when running from the WorkBench. ***** From either the Shell or the WorkBench, however, you can get continual reports by using the REPORT option on SPROF. From the Shell, type sprof report 5 test From the WorkBench, click on the SPROF icon, then select "Info" from the WorkBench menu. Add the following line to the ToolTypes array for SPROF: report=5 The next time you run SPROF, it will automatically produce a report every 5 seconds. ***** A very useful feature of SPROF is that you can choose to exclude certain sections of your program if you like. If you've looked at the source code to the test program (in "test.c") you will notice that if you provide a parameter, the program asks you to hit RETURN and waits until you do. We don't want to count the time spent waiting, so the PROFILE_OFF and PROFILE_ON macros (defined in ) were added to surround the call to getch(). Try it by entering the following command from a Shell: sprof stest 10 10 is a "delay factor" which determines how long the program will run. The default is also 10, so we should see no results in our profiling between the two runs. The program will print the following lines: Using delay factor of 10 Hit RETURN to continue: Wait about 10 seconds, then hit RETURN. When the report is generated, note that the total ETime value is very close to the one generated when no getch() was executed. Time spent in getch() doesn't count against your program. ***** SPROF can be used to profile shared libraries, devices, tasks created by your tasks, and other hard-to-get-to tasks or processes. The task to be profiled must execute one of the SAS/C provided startup modules so the SPROF autoinit/autoterm code is executed. You should start SPROF running with no program name first, then start your task. From the Shell, type this: sprof From WorkBench, double-click on the SProf icon in SC:C. Next, start your task. Only one task in the system can be profiled at any one time. For an example of profiling a shared library, see the directory SC:EXAMPLES/RESLIB. ============= RUNNING LPROF ============= To run the LPROF profiler, you must be in a Shell. Lprof doesn't work from WorkBench. Enter the following command: lprof ltest A data file called "prof.out" is produced. Run the LSTAT program on it: lstat ltest Lstat automatically opens "prof.out" and uses the data in the executable "ltest" to associate the profiling data with filenames and line numbers. Lstat generates a report like this: SAS AMIGA 68000 Profile Analyzer V6.50 Copyright © 1992-1993 SAS Institute Inc. All Rights Reserved. Profile Statistics for ltest 217 run + 4 ready + 0 wait = 221 98.190% run, 1.8010% ready, 0.000% wait 0.460% samples (1) out of profile range counted = 216, RUN - NonTable 1 Routine % Total % Offset Hits Label 74.5371% 74.5371% 2a8 161 @f100b [lines 25-31 in Work:sc/examples/profile/test.c] Most hits - 74.5371% (161) on line 30 7.8703% 82.4075% 314 17 @f300 [lines 43-49 in Work:sc/examples/profile/test.c] Most hits - 5.5556% (12) on line 48 7.4075% 89.8148% 2cc 16 @f100c [lines 31-37 in Work:sc/examples/profile/test.c] Most hits - 4.6297% (10) on line 36 5.0925% 94.9075% 2f0 11 @f200 [lines 37-43 in Work:sc/examples/profile/test.c] Most hits - 3.7037% (8) on line 42 2.3148% 97.2222% 1c6 5 @_XCEXIT [lines 3-19 in c] Most hits - 2.3148% (5) on line 18 2.3148% 99.5371% 284 5 @f100 [lines 19-25 in Work:sc/examples/profile/test.c] Most hits - 1.3889% (3) on line 24 0.4629% 100.0000% 10cc 1 @__chkabort [lines 2-3 in _chkabort.c] Most hits - 0.4629% (1) on line 2 This report gives you actual line numbers that received the most hits, and it also includes link library functions in the profiling. The results are very similar to SPROF's, as expected.