Introducing the GoLisp Profiler

24 Aug 2015

by Dave Astels

Now that GoLisp is becoming a more complete and powerful programming language, rather than a simple extension language for making DSLs, it’s time to have some real development tools for it. This post introduces the new GoLisp profiler.

How to use it

As a simple example, consider the following two definitions:

(define (foo x) (* (+ x 1) (- x 1)))
(define (bar) (map foo (interval 5)))

Now I’ll run the profiler on a call to bar;

(profile (bar) "mapping.dat")

This results in the following data being written to the file mapping.dat:

(1436892833635647215 0 enter func bar)
(1436892833635692114 1 enter prim interval)
(1436892833635698301 1 exit  prim interval)
(1436892833635701355 2 enter prim map)
(1436892833635707688 3 enter func foo)
(1436892833635721252 4 enter prim +)
(1436892833635724940 4 exit  prim +)
(1436892833635731773 5 enter prim -)
(1436892833635734948 5 exit  prim -)
(1436892833635737538 6 enter prim *)
(1436892833635740760 6 exit  prim *)
(1436892833635743281 3 exit  func foo)
(1436892833635747068 7 enter func foo)
(1436892833635757656 8 enter prim +)
(1436892833635760470 8 exit  prim +)
(1436892833635766866 9 enter prim -)
(1436892833635770315 9 exit  prim -)
(1436892833635773062 10 enter prim *)
(1436892833635775967 10 exit  prim *)
(1436892833635778426 7 exit  func foo)
(1436892833635782116 11 enter func foo)
(1436892833635792811 12 enter prim +)
(1436892833635795801 12 exit  prim +)
(1436892833635802244 13 enter prim -)
(1436892833635805127 13 exit  prim -)
(1436892833635807574 14 enter prim *)
(1436892833635810711 14 exit  prim *)
(1436892833635813093 11 exit  func foo)
(1436892833635816726 15 enter func foo)
(1436892833635827599 16 enter prim +)
(1436892833635830687 16 exit  prim +)
(1436892833635837554 17 enter prim -)
(1436892833635849926 17 exit  prim -)
(1436892833635852331 18 enter prim *)
(1436892833635854889 18 exit  prim *)
(1436892833635856973 15 exit  func foo)
(1436892833635869621 19 enter func foo)
(1436892833635889470 20 enter prim +)
(1436892833635892198 20 exit  prim +)
(1436892833635897704 21 enter prim -)
(1436892833635900296 21 exit  prim -)
(1436892833635902541 22 enter prim *)
(1436892833635907485 22 exit  prim *)
(1436892833635909595 19 exit  func foo)
(1436892833635912075 2 exit  prim map)
(1436892833635914103 0 exit  func bar)

When we load it using:

(load-profile "mapping.dat")

We can print the call tree call that shows the time spent in each invocation (and the time used by the runtime in the invocation if there are nested invocations). All times are in nanoseconds:

(print-tree)

bar (total: 266888, overhead: 49981)
  map (total: 210720, overhead: 32571)
    foo (total: 39974, overhead: 29710)
      * (total: 4944)
      - (total: 2592)
      + (total: 2728)
    foo (total: 40247, overhead: 22229)
      * (total: 2558)
      - (total: 12372)
      + (total: 3088)
    foo (total: 30977, overhead: 21967)
      * (total: 3137)
      - (total: 2883)
      + (total: 2990)
    foo (total: 31358, overhead: 22190)
      * (total: 2905)
      - (total: 3449)
      + (total: 2814)
    foo (total: 35593, overhead: 25508)
      * (total: 3222)
      - (total: 3175)
      + (total: 3688)
  interval (total: 6187)

To get the total time expended in each function we can extract data:

(by-function 'all)

This provides the following (times are in nanoseconds):

Function             | count | total time |   avg time
~~~~~~~~~~~~~~~~~~~~~+~~~~~~~+~~~~~~~~~~~~+~~~~~~~~~~~
interval             |     1 |       6187 |       6187
+                    |     5 |      15308 |       3061
*                    |     5 |      16766 |       3353
map                  |     1 |     210720 |     210720
bar                  |     1 |     266888 |     266888
foo                  |     5 |     178149 |      35629
-                    |     5 |      24471 |       4894
~~~~~~~~~~~~~~~~~~~~~+~~~~~~~+~~~~~~~~~~~~+~~~~~~~~~~~

How it works

When profiling is enabled in the runtime (this is managed by the profile form) each function, primitive function, or special form logs it’s entry and exit in the format:

(<timestamp> <GUID> <enter/exit> <func/prim/form> <name>)

Timestamp is absolute and used to calculate the time spent in a function invocation.

GUIDs are unique for a specific session of golisp. Matching entry/exit pairs will have the same GUID for the purpose of matching them during analysis.

enter/exit specifies if the record corresponds to a function entry or exit.

func/prim/form indicates what type of function invocation it is.

name is the name of the function, primitive, or form.

Notice that these records are in the form of lisp lists. This allows the analysis code to very easily read them in using the built-in read function that returns the lisp object that was represented in the input stream/file. So we can pull in the profile data simply by repeatedly reading from the file. This makes it trivial to get the data into a form that we can manipulate.

The load-profile function loads this raw entry/exit data and uses it to construct a call tree. The tree is made up of nodes (one for each invocation) that consist of name, duration, type, and children of the invocation (i.e. nested invocations). The print-tree function displays a representation of this call tree.

Another function is by-function which displays a summary table (shown above), one row per function/primitive/form that had invocations recorded in the profile data.

Something more interesting

For a more interesting example, consider a naive recursive implementation of the Fibonacci sequence:

(define (fib n)
  (if (<= n 2)
      1
      (+ (fib (- n 1)) (fib (- n 2)))))

If we profile it with:

(profile (fib 5) "fib.dat")

Then load the data and look at the call tree, we can clearly see the structure:

fib (total: 486858, overhead: 46822)
  if (total: 440036, overhead: 55401)
    + (total: 2598)
    fib (total: 118158, overhead: 14579)
      if (total: 103579, overhead: 38765)
        + (total: 2511)
        fib (total: 27975, overhead: 14868)
          if (total: 13107, overhead: 10761)
            <= (total: 2346)
        - (total: 2552)
        fib (total: 26715, overhead: 14982)
          if (total: 11733, overhead: 9411)
            <= (total: 2322)
        - (total: 2799)
        <= (total: 2262)
    - (total: 2596)
    fib (total: 252723, overhead: 26745)
      if (total: 225978, overhead: 51013)
        + (total: 2444)
        fib (total: 28312, overhead: 15979)
          if (total: 12333, overhead: 9995)
            <= (total: 2338)
        - (total: 2674)
        fib (total: 124783, overhead: 15566)
          if (total: 109217, overhead: 43663)
            + (total: 2687)
            fib (total: 26507, overhead: 14741)
              if (total: 11766, overhead: 9445)
                <= (total: 2321)
            - (total: 2921)
            fib (total: 28105, overhead: 15476)
              if (total: 12629, overhead: 10016)
                <= (total: 2613)
            - (total: 2972)
            <= (total: 2362)
        - (total: 13338)
        <= (total: 3414)
    - (total: 4349)
    <= (total: 4211)

Asking for a report by function result in:

Function             | count | total time |   avg time
~~~~~~~~~~~~~~~~~~~~~+~~~~~~~+~~~~~~~~~~~~+~~~~~~~~~~~
<=                   |     9 |      24189 |       2687
fib                  |     9 |    1120136 |     124459
+                    |     4 |      10240 |       2560
if                   |     9 |     940378 |     104486
-                    |     8 |      34201 |       4275
~~~~~~~~~~~~~~~~~~~~~+~~~~~~~+~~~~~~~~~~~~+~~~~~~~~~~~

Summary

GoLisp has a rudimentary profiler. Not only can this be used to identify functions that might benefit from some optimization, but it also can aid in analyzing the efficiency of your algorithms since you can get exact invocation counts of each function, primitive, and form.