Profiler

Using the Profiler Extension

If you’d like your model to run faster, the profiler extension may be useful to you. It includes primitives that measure how many times the procedures in your model are called during a run and how long each call takes. You can use this information to where to focus your speedup efforts.

Caution:

The profiler extension is experimental. It is not yet well tested or user friendly. Nonetheless, we think some users will find it useful.

How to use

The profiler extension comes preinstalled. To use the extension in your model, add a line to the top of your Code tab:

extensions [profiler]

If your model already uses other extensions, then it already has an extensions line in it, so just add profiler to the list.

For more information on using NetLogo extensions, see the Extensions Guide

Example

setup                  ;; set up the model
profiler:start         ;; start profiling
repeat 20 [ go ]       ;; run something you want to measure
profiler:stop          ;; stop profiling
print profiler:report  ;; view the results
profiler:reset         ;; clear the data

Another way to use the profiler is to export its raw data using the csv extension and the profiler:data primitive:

extensions [ csv profiler ]

to profile
  setup                                          ;; set up the model
  profiler:start                                 ;; start profiling
  repeat 20 [ go ]                               ;; run something you want to measure
  profiler:stop                                  ;; stop profiling
  csv:to-file "profiler_data.csv" profiler:data  ;; save the results
  profiler:reset                                 ;; clear the data
end

Running the above procedure will write a profiler_data.csv file that you can then load into your favorite data analysis program. Here is an example data file produced using the Wolf Sheep Predation model:

procedure,calls,inclusive_time,exclusive_time
EAT-SHEEP,1085,1.237283,11.637364
DISPLAY-LABELS,20,17.389512,17.389512
MOVE,3578,14.164451,14.164451
GO,20,683.414619,604.773837
GRASS,3,0.05384,0.05384
DEATH,1085,3.172517,3.172517
REPRODUCE-SHEEP,2493,10.265135,10.265135
REPRODUCE-WOLVES,1039,5.599509,5.599509

Thanks to Roger Peppe for his contributions to the code.

Primitives

Looking for the primitive reference for the Profiler extension? You can find the full reference here.

profiler:calls profiler:exclusive-time profiler:inclusive-time profiler:start profiler:stop profiler:reset profiler:report profiler:data

All Primitives

profiler:calls

profiler:calls procedure-name

Reports the number of times that procedure-name was called. If procedure-name is not defined, then reports 0.

profiler:exclusive-time

profiler:exclusive-time procedure-name

Reports the exclusive time, in milliseconds, that procedure-name was running for. Exclusive time is the time from when the procedure was entered, until it finishes, but does not include any time spent in other user-defined procedures which it calls.

If procedure-name is not defined, then reports 0.

profiler:inclusive-time

profiler:inclusive-time procedure-name

Reports the inclusive time, in milliseconds, that procedure-name was running for. Inclusive time is the time from when the procedure was entered, until it finishes.

If procedure-name is not defined, then reports 0.

profiler:start

Instructs the profiler to begin recording user-defined procedure calls.

profiler:stop

Instructs the profiler to stop recording user-defined procedure calls.

profiler:reset

Instructs the profiler to erase all collected data.

profiler:report

Reports a string containing a breakdown of all user-defined procedure calls. The Calls column contains the number of times a user-defined procedure was called. The Incl T(ms) column is the total time, in milliseconds, it took for the call to complete, including the time spent in other user-defined procedures. The Excl T(ms) column is the total time, in milliseconds, spent within that user-defined procedure, not counting other user-define procedures it called. The Excl/calls column is an estimate of the time, in milliseconds, spent in that user-defined procedure for each call.

Here is example output:

Sorted by Exclusive Time
Name                               Calls Incl T(ms) Excl T(ms) Excl/calls
CALLTHEM                              13     26.066     19.476      1.498
CALLME                                13      6.413      6.413      0.493
REPORTME                              13      0.177      0.177      0.014

Sorted by Inclusive Time
Name                               Calls Incl T(ms) Excl T(ms) Excl/calls
CALLTHEM                              13     26.066     19.476      1.498
CALLME                                13      6.413      6.413      0.493
REPORTME                              13      0.177      0.177      0.014

Sorted by Number of Calls
Name                               Calls Incl T(ms) Excl T(ms) Excl/calls
CALLTHEM                              13     26.066     19.476      1.498

profiler:data

Reports a list of lists containing the results of the profiler in a format that is suitable for exporting with the csv extension.

The first sublist contains the name of the data columns: procedure, calls, inclusive_time and exclusive_time. This is followed by one sublist containing the profiler data for each user-defined procedure. The reported times are in milliseconds.