show-outline-profile

Arguments: &key name stream profile verbose

This function returns no value.

Called for side-effect, this function produces a raw outline view of the selected profile and prints it to the stream (defaulting to *standard-output*). The profile defaults to the current profile, and can be specified as either a profile object or the name of a named-profile.

The name keyword argument, if provided, specifies the function for which information is requested. If the name keyword argument is not specified or is specified nil, information on all functions will be printed. The value of the name keyword argument can be a symbol or a compiled function object if you want information on a Lisp function. The value can also be a string if you want information on a C function or a Lisp runtime system function. The value can also be an integer which corresponds to a sequence number as described next.

Before the first call to this function, nodes in the profile graph have identity and names, but are not sequenced. Whenever this function is called and produces an outline, the nodes are sequenced, beginning at 0 for the selected node (or a dummy node named "start" if no node is selected) and continuing downward to all selected child nodes recursively in a directed tree graph with no cycles. A node is selected based on whether its usage is above the prof:*significance-threshold* or not - if the node falls below that threshold, it is not selected nor is it counted.

The outline is printed one node per line, in an indented format that makes it easy to see the node hierarchy. The indentation mostly consists of spaces, to keep the clutter down, but is punctuated with vertical bars, slashes, plus signs, and backslashes to form a visual bracketing mechanism that allows human readability of the hierarchy. There is a complete example here in runtime-analyzer.htm. We repeat just the outline output so we can discuss what is displayed.

cl-user(6): (prof:show-outline-profile)

100.00 "start" 0
 100.00 "cont_setstack" 1
  100.00 "startup_lisp" 2
   100.00 "start_reborn_lisp" 3
    100.00 "first_lisp_thread" 4
     100.00 excl::lisp-thread-start 5
      100.00 excl::run-initial-thread 6
       100.00 excl::setup-required-thread-bindings 7
        100.00 excl::thread-reset-catcher 8
         100.00 excl::thread-bind-and-call 9
          100.00 #<Runtime Function Object (:runsys "lisp_apply")> 10
           100.00 excl::start-lisp-execution 11
            100.00 tpl:start-interactive-top-level 12
             100.00 #<Runtime Function Object (:runsys "lisp_apply")> 13
              100.00 tpl:top-level-read-eval-print-loop 14
               100.00 tpl::top-level-read-eval-print-loop1 15
                100.00 excl::read-eval-print-loop 16
                 100.00 tpl::read-eval-print-one-command 17
                  100.00 eval 18
                   100.00 (:anonymous-lambda 17) 19
                    100.00 prof::prof-a-funcall 20
                     100.00 (:internal (:anonymous-lambda 17) 0) 21
                      100.00 foo 22
                      /37.10 bam 23
                      | 17.76 excl::*_2op 24
                      +27.69 #<Runtime Function Object (:runsys "lisp_apply")> 25
                      |/9.78 bar 26
                      || 6.55 excl::*_2op 27
                      |\1.35 "funcall_check" 28
                      \20.62 bas 29
                        11.89 excl::*_2op 30

On each line three fields are printed:

1. The total weight of this node. Note that this is not the same as the total weight of all nodes with this same function, but is instead the total weight (including children) of this particular instance of the function within the profile tree. The weight of the node will always include all time spent in a single invocation of the node's function, but it may also include time spent in multiple calls to the same function, if at the time of the hit the stack looks the same to the profiler (there is no way to tell the difference in this case).
2. The node's name. It may be a function spec (a symbol or a list) which represents the name of the function, or a string, which represents a C or runsys entry point. The printing of the name is controlled by *print-escape* - when true, package names are printed for fspecs and strings are delimited with double-quotes, and when nil space is saved by not printing package names or string quotes.
3. The sequence number. This is a temporary integer assigned to the node in ascending order (after the children in the tree are sorted in descending order of weight), and this integer can be used to identify the node in any functions that accept a name argument (e.g. this function itself, prof:show-call-graph, disassemble, prof:disassemble-profile, and print-function-meta-info). Note that whenever this function is called the tree graph is re-sequenced, so if the name argument is specified with any non-zero positive integer, its node will become the new root of the outline and will start at 0. See the end of the example here in runtime-analyzer.htm where it shows how using a stale sequence number results in an error.

Not all nodes are necessarily printed. If the hierarchy goes too deep, and the columns extend too far to the right, some nodes (lines) will be elided, and a message will be printed to that effect. The maximum number of columns indented is controlled by the variable prof:*outline-max-indentation* - if a line must be indented farther than that value it is elided. Note that the indentation limit does not control the maximum line length directly; names are never cut off and thus may run arbitrarily long in the outline output.

See runtime-analyzer.htm for general information on the runtime analyzer.

Copyright (c) 1998-2022, Franz Inc. Lafayette, CA., USA. All rights reserved.
This page is new in the 10.1 release.
Created 2019.8.20.