Timing Code

Unfortunately, code sometimes runs very slowly. Sometimes this is inevitable, but sometimes it is remediable. To investigate slow-running NetLogo code, one may subjectively rank the anticipated running time of individual procedures and then examine the running time any suspect procedures. This can be a simple as add timing code around a call suspected to take too much time to run.

let _t0 timer wait 1 print (timer - _t0)

Timing Procedures

When a procedure takes a long time to execute, we may wish to refine the investigation. The same approach to timing may be applied within user-written procedures.

to doSomethingSlow wait 1 end
to go
  ;...
  let _t0 timer
  doSomethingSlow
  let _t1 timer
  print (word "doSomethingSlow took " (_t1 - _t0) " seconds.")
  ;...
end

At times, this kind of guesswork, piecemeal investigation is well-informed and can help us quickly pinpoint problems. However, profilers offer a better and more systematic approach to the problem of pinpointing code bottlenecks.

Profiler

A profiler measures how many times subroutines in your model are called and how long each call takes.

NetLogo Profiler Extension

NetLogo ships with an “experimental” profiler extension. Declare it like any extension.

extensions [profiler]

Core Primitives

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

discard all collected data.

profiler:report

Reports a string containing a breakdown of all user-defined procedure calls.

Example Use

to profile
  setup
  profiler:reset
  profiler:start
  repeat 20 [go]
  profiler:stop
  let _fname "/temp/report.txt"
  carefully [file-delete _fname] []
  file-open _fname
  file-print profiler:report
  file-close
end

Inclusive Time vs. Exclusive Time

Inclusive time is just the time it takes to run a procedure. Exclusive time tries to exclude the time taken by other called procedures.

Inclusive time

time from from entry to exit of the procedure, including time spent in other user-defined procedures that it calls.

Exclusive time

time from from entry to exit of the procedure, excluding time spent in other user-defined procedures that it calls.

profiler:exclusive-time procedure-name

Reports the exclusive time, in milliseconds, that procedure-name ran.

profiler:inclusive-time procedure-name

Reports the inclusive time, in milliseconds, that procedure-name ran.

Reports

Calls column

the number of times a user-defined procedure was called.

Incl T(ms) column

inclusive time, in milliseconds, it took for the procedure call to complete.

Excl T(ms) column

exclusive time, in milliseconds, spent in each user-defined procedure.

Excl/calls column

estimate of the exclusive time, in milliseconds, per call.

The Importance of Subroutines

The NetLogo profiler helps you see how user-written procedures are performing.

If you don't break your code up into procedures, you will not get much help from the profiler.

Example Output:

The following example is from the NetLogo documentation.

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
CALLME                                13      6.413      6.413      0.493
REPORTME                              13      0.177      0.177      0.014

Other Primitives

profiler:calls procedure-name

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