Analyzing Performance Profiling Reports

Performance profiling is applied to a user-selected set of components (ChorusOS operating system kernel, supervisor actors). The result of the performance profiling consists of a set of reports, one per profiled component.

A performance profiling report consists of two parts:

• A global report that provides general information about the profiling session, including clock attributes, CPU attributes, and the distribution of CPU time between idle threads, user actors, non-profiled supervisor components, and each of the profiled supervisor components.

• A component-based function table that indicates the distribution of CPU time inside the profiled component.

For each function, the performance profile report displays the following information:

• Function header.

  • Function number. This field indicates the function number in the current report. It is provided in order to facilitate study of the report using a text editor.

  • Function name. This field indicates the name of the function.

  • Size. This field indicates the size of the function in bytes.

  • Time spent in function. This field indicates the flat time spent in the body of the function (the number of profiling ticks that occurred while an instruction was executed within the function). This value is followed by the percentage of the total component time it represents. This is the most valuable information and the report can be sorted by this key if desired.

  • Total time spent in function. This field indicates the aggregated-time spent within the function and called functions. The value is given as a percentage of total actor time. By default, the report generator sorts the table by this key. This field is computed by the report generator, and assumes that each call to a given routine lasts the same amount of time. This information is only provided in the full profiling form. In the simple form, this information is the same as the flat-time information.

  • Recursion indicator. This field indicates that the procedure was found in a recursive loop. As the profiling system is not fully set up for multithreading, this indicator might be erroneously set. This information is only provided in the full profiling form.

• Call graph description.

  • List of callers. This field details a list of the functions calling the profiled function. For each caller, the report provides:

    • the caller's function number

    • the number of calls

    • the caller's name and the offset of the call in the caller's body. When a function calls another function from several locations, several entries are made in the list of callers

  • List of called functions. For each called function, the report provides:

    • the callee's function number

    • the number of calls

    • the percentage of the total function time that is charged to the callee

    • the name of the function

Shown below is an example of a profiling report.

  overhead=2.468
  memcpy 4 K=18.834
  memcpy 16 K=51.936
  memcpy 64 K=185.579
  memcpy 256 K=801.300
  sysTime=2.576
  threadSelf=2.210
  thread switch=5.777
  threadCreate (active)=8.062
  threadCreate (active, preempt)=10.071
  threadPriority (self)=3.789
  threadPriority (self, high)=3.195
  threadResume (preempt)=6.999
  threadResume (awake)=4.014
 ...
  ipcCall (null, timeout)=35.732
  ipcSend (null, funcmode)=7.723
  ipcCall (null, funcmode)=31.762
  ipcSend (null, funcumode)=7.924
  ipcCall (null, funcumode)=31.864
  ipcSend (annex)=8.294
  ipcReceive (annex)=7.086
  ipcCall (annex)=33.708
  ipcSend (body 4b)=8.020
  ipcReceive (body 4b)=6.822
  ipcCall (body 4b)=32.558
  ipcSend (annex, body 4b)=8.684
  ipcReceive (annex, body 4b)=7.495
  ipcCall (annex, body 4b)=34.849