Gerbil Scheme

Profiling

Gerbil ships with a basic profiler tool, gerbil prof or just gxprof. The tool can profile dynamically compiled executable modules, by running them with an interrupt handler that samples the current continuation on every scheduler heartbeat.

Once a profile sample file has been generated by running gxprof with your module, you can analyze the samples for some (hopefully) insightful statistics.

Invocation

$ gerbil prof -h
gxprof: The Gerbil profiler

Usage: gxprof [option ...] [<module>] <module-args> ...

Options:
 -o --output <output>             gxprof output file [default: gxprof.out]
 --heartbeat  <heartbeat>         heartbeat interval for sampling, in seconds [default: .001]
 -h --help                        display help

Arguments:
 module                           dynamic executable module to run; analyze an existing output file if omitted [default: #f]
 module-args                      arguments to pass to the executable module's main

So basically gxprof :your/executable-module arg ... will run the main function in :your/executable-module with the given arguments. The function is run to completion, at which point the profiler writes the captured continuation samples in gxprof.out in the current directory.

The contents of the file is a list of lists that contain the names of the continuation creator for each frame in the captured continuations. You can process the samples to extract detailed profiling statistics.

You can then analyze the samples by rerunning gxprof without arguments.

Example

Here is an example:

$ gxc -O json-benchmark.ss
$ gxprof :std/text/json/json-benchmark bio ~/Downloads/large-file.json
(time (std/text/json/json-benchmark#call-with-buffered-reader _file126_ std/text/json/api#read-json))
    0.595805 secs real time
    0.582223 secs cpu time (0.498561 user, 0.083662 system)
    18 collections accounting for 0.239713 secs real time (0.238992 user, 0.000703 system)
    1413985192 bytes allocated
    82594 minor faults
    no major faults
    1555767072 cpu cycles
(time (std/text/json/json-benchmark#call-with-buffered-writer _tmp130_ (lambda (_g131133_) (std/text/json/api#write-json__% _object128_ _g131133_))))
    0.246521 secs real time
    0.246516 secs cpu time (0.234621 user, 0.011895 system)
    no collections
    194321304 bytes allocated
    2964 minor faults
    no major faults
    643710478 cpu cycles

$ gxprof
... analyzing gxprof.out
Top Continuation Samples
------------------------
std/text/json/input#read-json-hash/buffer: 61 [36.970%]
std/text/json/output#write-json-string/buffer: 42 [25.455%]
std/text/json/input#read-json-hash-key/buffer: 17 [10.303%]
std/text/json/input#read-json-string/buffer: 15 [9.091%]
std/text/json/output#write-json-alist/buffer: 7 [4.242%]
std/sort#list-merge-sort: 6 [3.636%]
std/io/file#input-file-io::read: 3 [1.818%]
##table-foldl: 2 [1.212%]
std/text/json/output#write-json-list/buffer: 2 [1.212%]
std/io/file#output-file-io::write: 2 [1.212%]
##list->string: 2 [1.212%]
std/text/json/json-benchmark#benchmark-stdio-bio: 1 [0.606%]
std/text/json/input#read-json-list-next/buffer: 1 [0.606%]
std/text/json/input#read-json-object/buffer: 1 [0.606%]
std/text/json/output#write-json-hash/buffer: 1 [0.606%]
##string->number-slow-path: 1 [0.606%]
std/text/json/input#read-json-number/buffer: 1 [0.606%]

Call Graph Samples
------------------
##dynamic-wind: 392 [237.576%]
##dynamic-env-bind: 392 [237.576%]
std/text/json/input#read-json-hash/buffer: 349 [211.515%]
std/text/json/output#write-json-alist/buffer: 195 [118.182%]
##kernel-handlers: 165 [100.000%]
std/text/json/json-benchmark#benchmark-stdio-bio: 165 [100.000%]
##exec-stats: 164 [99.394%]
##time-thunk: 164 [99.394%]
std/text/json/input#read-json-list/buffer: 114 [69.091%]
std/text/json/input#read-json-list-next/buffer: 114 [69.091%]
std/text/json/json-benchmark#call-with-buffered-reader: 102 [61.818%]
std/sort#list-merge-sort: 89 [53.939%]
std/text/json/output#write-json-list/buffer: 74 [44.848%]
std/text/json/output#write-json-string/buffer: 67 [40.606%]
std/text/json/input#read-json-hash-keybuffer: 23 [13.939%]
std/text/json/input#read-json-string/buffer: 18 [10.909%]
std/text/json/output#write-json-hash/buffer: 9 [5.455%]
std/io/bio/util#&BufferedReader-read-char: 3 [1.818%]
std/io/file#input-file-io::read: 3 [1.818%]
##table-foldl: 2 [1.212%]
std/io/bio/output#bio-write-u8: 2 [1.212%]
std/io/file#output-file-io::write: 2 [1.212%]
##list->string: 2 [1.212%]
##string->number-slow-path: 2 [1.212%]
std/text/json/input#read-json-number/buffer: 2 [1.212%]
std/io/bio/util#&BufferedWriter-write-string__%: 1 [0.606%]
std/text/json/input#read-json-object/buffer: 1 [0.606%]
vyzo@dellicious:~/gerbil/src/std/text/json$

If you want to hide kernel continuations from the sample (they are not usually very intesting), you can do so with the -k analysis options:

$ gxprof -k
... analyzing gxprof.out
Top Continuation Samples
------------------------
std/text/json/input#read-json-hash/buffer: 61 [36.970%]
std/text/json/output#write-json-string/buffer: 42 [25.455%]
std/text/json/input#read-json-hash-keybuffer: 17 [10.303%]
std/text/json/input#read-json-string/buffer: 15 [9.091%]
std/text/json/output#write-json-alist/buffer: 7 [4.242%]
std/sort#list-merge-sort: 6 [3.636%]
std/io/file#input-file-io::read: 3 [1.818%]
##list->string: 2 [1.212%]
##table-foldl: 2 [1.212%]
std/text/json/output#write-json-list/buffer: 2 [1.212%]
std/io/file#output-file-io::write: 2 [1.212%]
std/text/json/input#read-json-object/buffer: 1 [0.606%]
std/text/json/input#read-json-list-next/buffer: 1 [0.606%]
std/text/json/input#read-json-number/buffer: 1 [0.606%]
##string->number-slow-path: 1 [0.606%]
std/text/json/output#write-json-hash/buffer: 1 [0.606%]
std/text/json/json-benchmark#benchmark-stdio-bio: 1 [0.606%]

Call Graph Samples
------------------
std/text/json/input#read-json-hash/buffer: 349 [211.515%]
std/text/json/output#write-json-alist/buffer: 195 [118.182%]
std/text/json/json-benchmark#benchmark-stdio-bio: 165 [100.000%]
##exec-stats: 164 [99.394%]
##time-thunk: 164 [99.394%]
std/text/json/input#read-json-list-next/buffer: 114 [69.091%]
std/text/json/input#read-json-list/buffer: 114 [69.091%]
std/text/json/json-benchmark#call-with-buffered-reader: 102 [61.818%]
std/sort#list-merge-sort: 89 [53.939%]
std/text/json/output#write-json-list/buffer: 74 [44.848%]
std/text/json/output#write-json-string/buffer: 67 [40.606%]
std/text/json/input#read-json-hash-keybuffer: 23 [13.939%]
std/text/json/input#read-json-string/buffer: 18 [10.909%]
std/text/json/output#write-json-hash/buffer: 9 [5.455%]
std/io/file#input-file-io::read: 3 [1.818%]
std/io/bio/util#&BufferedReader-read-char: 3 [1.818%]
##list->string: 2 [1.212%]
std/text/json/input#read-json-number/buffer: 2 [1.212%]
##table-foldl: 2 [1.212%]
std/io/bio/output#bio-write-u8: 2 [1.212%]
std/io/file#output-file-io::write: 2 [1.212%]
##string->number-slow-path: 2 [1.212%]
std/text/json/input#read-json-object/buffer: 1 [0.606%]
std/io/bio/util#&BufferedWriter-write-string__%: 1 [0.606%]

Also note, that in the call graph samples, some procedures may have more than 100% coverage. This is not a bug; a procedure may appear multiple times within the same continuation sample because of a recursive call.

← Optimizing Gerbil Programs→