Documentation Center

  • Trial Software
  • Product Updates

prog::profile

Display timing data of nested function calls

Use only in the MuPAD Notebook Interface.

This functionality does not run in MATLAB.

Syntax

prog::profile(stmt)

Description

prog::profile(stmt) evaluates the MuPAD® statement stmt and displays timing data of all nested function calls, additionally a graph with the calling structure.

prog::profile measures and displays the time usage of library functions. Kernel functions are not measured. For every function called during the evaluation of stmt, prog::profile prints the time spent in this function and the number of calls.

prog::profile can be helpful in finding time critical functions and unnecessary nested function calls.

stmt could be reading a whole test file, too.

A trick to observe also kernel functions is to call prog::trace with the kernel function as argument. prog::trace takes a library wrapper procedure around the kernel function, that has the same name and can be found in the output of prog::profile, when the kernel function is used during the evaluation of stmt. The time use of the wrapper function is nearly zero.

The first part of the output is a table with the timing values for each procedure, the second part is a graph, that presents information about the dependences between all measured functions, when stmt is evaluated.

The table contains several columns that are described below.

Each row shows all data of one function (called "the function"), that was measured by prog::profile. There is one special entry: The first entry is called procedure entry point. It shows the sum of all functions and reperesents the evaluation of stmt.

  • "percent usage of all"

    the time spent in the function with respect to the whole time used for the evaluation of stmt (in percent)

  • "time self per single call"

    the value "time self" divided by the sum of all calls of the function (in milli seconds)

  • "time self"

    the whole time spent in the body of the function, i.e., the sum of all calls, without the time, used by all other measured functions called by the function (in milli seconds)

  • "time children per single call"

    the value "time children" divided by the sum of all calls of the function (in milli seconds)

  • "time children"

    the sum of all time (self and children) spent in all functions that are called by the function directly

  • "calls/normal exit"

    number of all calls of the function that leave the function without errors

  • "calls/remember exit"

    number of all calls of the function that return a remembered value by the kernel remember mechanism (and does not call the function body)

  • "calls/errors"

    number of all calls of the function that leave the function with an error

  • ["[index] function name"]

    the index of the function (assigned by prog::profile) and the name of the function

An index is assigned to each function, in descending order of time usage, to identify and find the function in the call graph that is described now.

The second part of the output of prog::profile is a dependence graph. It shows each function, their parents (functions that call the function directly), and their children (functions that are called from the function directly), together with timing information and the number of calls.

Each part of the graph that is separated by horizontal lines of minus chars, belongs to one function. It contains several columns:

  • "index"

    the index, assigned unique to the function

  • "%time"

    the percentage of the function on the whole run time

  • "self"

    the sum of all times used by the function (in milli seconds)

  • "children"

    the sum of all times used by the children of the function (in milli seconds)

  • "called"

    the number of all calls of the function

  • ["[index] name"]

    the index and the name of the function

    There are two kinds of entries: the function that belongs to the part has its index in the first column of the part, and in this column, only their name is printed.

    All other functions (parents and children of the function) are only printed in this column with their index and name together, with small indentation for highlighting the function that belongs to the part.

    The parents are located above the function itself, all children are written below the line with the function, the part belongs to.

    For a more detailed explanation of the lines in a graph part see the first example.

Examples

Example 1

We define three functions f, g and h. prog::profile displays the time spent in each function and the number of calls to it:

f := proc()
       local t;
     begin
       t := time();
       while time() < 10 + t do nothing end_while
     end_proc:
g := proc()
       local t;
     begin
       f();
       t := time();
       while time() < 10 + t do nothing end_while;
       f()
     end_proc:
h := proc() begin g(), f(), g() end_proc:
prog::profile(h()):
  percent usage of all     |    time self per
single call     |      |    time self     |      |      |    time
children per single call     |      |      |      |    time children
    |      |      |      |      |   calls/normal exit     |      |
     |      |      |   |  calls/remember exit     |      |      |
     |      |   |  |  calls/errors     |      |      |      |    
 |   |  |  |  [index] funct. name -----------------------------------------------------------------
 100.0   70.0   70.0     .      .   1  .  .  [0]  proc. entry pt.
-----------------------------------------------------------------
  71.4   10.0   50.0     .      .   5  .  .  [1]  f   28.6   10.0
  20.0   20.0   40.0  2  .  .  [2]  g     .      .      .    70.0
  70.0  1  .  .  [3]  h -----------------------------------------------------------------
  index     %time      self  children     called  [index] name -----------------------------------------------------------------
  [0]     100.0        70         0          1  proc. entry point
                        0        70          1      [3]  h -----------------------------------------------------------------
                       40         0          4      [2]  g       
                10         0          1      [3]  h   [1]      71.4
       50         0          5  f -----------------------------------------------------------------
                       20        40          2      [3]  h   [2] 
    28.6        20        40          2  g                       
40         0          4      [1]  f -----------------------------------------------------------------
  [3]       0.0         0        70          1  h                
       10         0          1      [1]  f                       
20        40          2      [2]  g -----------------------------------------------------------------
  Time sum: 70 ms 

(The output is shortened slightly, because the page is too small.)

The lines of the table above are described following:

  percent usage of all     |    time self per
single call     |      |    time self     |      |      |    time
children per single call     |      |      |      |    time children
    |      |      |      |      |   calls/normal exit     |      |
     |      |      |   |  calls/remember exit     |      |      |
     |      |   |  |  calls/errors     |      |      |      |    
 |   |  |  |  [index] funct. name -----------------------------------------------------------------
 100.0   70.0   70.0     .      .   1  .  .  [0]  proc. entry pt.
----------------------------------------------------------------- 

The whole function call takes 100 percent of the time (certainly), 70.0 milli seconds and is called once (the evaluation of stmt), without an error.

  71.4   10.0   50.0     .      .   5  .  .
 [1]  f 

Function f takes 71.4 percent of all evaluation time in its body. It uses 10.0 milli seconds per call on the average (in this case exactly), their children (if existing) uses no time measurable (because it has no children), and it is called 5 times and returns without errors. f has the index 1.

  28.6   10.0   20.0   20.0   40.0  2  .  .
 [2]  g 

Function g takes 28.6 percent of the whole time that are 20.0 milli seconds, and 10.0 milli seconds on the average per call. Their children uses 20.0 milli seconds pre call on the average and 40.0 total, and g is called twice and returns without errors. g gets the index 2.

    .      .      .    70.0   70.0  1  .  .
 [3]  h 

Function h uses nearly no evaluation time, their children uses 70.0 milli seconds on the average and 70.0 total, and h is called once and finished without errors. h gets the index 3.

The parts of the graph above are described following:

index     %time      self  children     called
 [index] name -----------------------------------------------------------------
  [0]     100.0        70         0          1  proc entry point 
                       0        70          1      [3]  h ----------------------------------------------------------------- 

The whole function call takes 100 percent of the evaluation time (by definition), that are 70.0 milli seconds, and it is called once.

It calls once the function h with index [3] (as argument of prog::profile), and h uses 70.0 milli seconds of the time that are spent in the children of h, not in the body.

index     %time      self  children     called
 [index] name -----------------------------------------------------------------
                       40         0          4      [2]  g       
                10         0          1      [3]  h   [1]      71.4
       50         0          5  f ----------------------------------------------------------------- 

Function f spends 71.4 percent of the whole evaluation time. It uses 50.0 milli seconds, their children uses no time measurable, and it is called 5 times.

f has two parents and no children.

f is called by its parent g4 times and by h once.

f spends 40 milli seconds by itself (in its body), when it is called from g (the first line in the part of f), and f spends 10 milli seconds in its body, when it is called from h (the second line).

index     %time      self  children     called
 [index] name -----------------------------------------------------------------
                       20        40          2      [3]  h   [2] 
    28.6        20        40          2  g                       
40         0          4      [1]  f ----------------------------------------------------------------- 

Function g takes 28.6 percent of the whole time, 20 milli seconds in its body, and their children take 40 milli seconds. g is called twice.

g is called from h twice, and spends 20 ms in its body and 40 ms in its children.

g calls the function f four times, and f spend 40 ms in its body, when it is called from g.

index     %time      self  children     called
 [index] name -----------------------------------------------------------------
  [3]       0.0         0        70          1  h                
       10         0          1      [1]  f                       
20        40          2      [2]  g ----------------------------------------------------------------- 

Function h takes nearly no evaluation time, their children spends 70.0 milli seconds, and h is called once.

h calls the functions f and g directly, f once and g twice.

f uses 10 ms in its body, when it is called from h, and g uses 20 ms in its body and 40 ms in its children.

Parameters

stmt

A MuPAD statement

Return Values

Result of stmt

Algorithms

The timings displayed by prog::profile are generated by the kernel.

The evaluation of stmt inside prog::profile takes partly substantially longer than evaluating stmt directly. This extra time does not influence the validity of the timings, i.e., if prog::profile reports f taking three times as long as g, then this is also the case when evaluating stmt directly.

See Also

MuPAD Functions

Was this topic helpful?