Fine timing/profiling of a model's run speed

Have implemented fine timing/profiling of a model's run. The tests give
microsecond accurate measurements. These results (when enabled) appear
in the report generated by the "Show Run Profile" menu option.

The debug option "Enable Event/Routine Profiling" causes Planimate to
keep track of the count, average run time, peak run time and total run
time of:

• FEC events, the time scheduled events which initiate item movement,
  unblocking etc.
• Individual routine operations, summarised by individual operation
  type (eg: Set, Increment, Search, Dialog etc...)

These stats go a long way to identifying where a model's run time is going.

Note that enabling profiling causes a model to run at about 60% its
normal speed, this is due to the large overhead in calling the system to
fetch the fine timer count.

Profiling must be enabled BEFORE the run is started, setting the option
during the run has no effect until the run is restarted.

There is quite a bit to say about the operations and the relevance of their
times, here are some initial observations:

• the peak time for an event may be quite large. This can occur if Windows
  pre-empts Planimate to run another task, the system performs network
  activity, the event involves animation or a dialog, or data is
  swapped to and from the swap file during that event.

For meaningful results try perform profiling with a lightly loaded system,
as much free memory as possible and without animation. Use the
the "advance to time" feature to ensure as much CPU time as possible is
spent within the model you are trying to profile.

Be aware those taskbar icons, especially the "fast-starts", network
monitors, virus scanners and other "helpful" utilities all consume
system RAM and steal the processor occasionally so they can update
themselves. This can lead to huge one-off peaks for otherwise fast
operations, lasting from 10 to 500ms.

• Using "advance to time" on a panel without spatial links seems faster
  than on one with them, will have to investigate this.
• the profiler quickly identified that row inserts were taking ages (20ms
  average) compared to everything else (20us). It turned out the insert was
  on a debug table with 170000 rows and 5 columns in it, ie: a 6.8MB shuffle
  each time.

An append to a big table will be faster than an insert at row 1. Same
for row deletes, deleting from the end will be faster.

(btw:block deletion is optimised so use it instead of row by row)

• Iteration/ifs/whiles will tend to have a large time since PL is spending
  a lot of time processing within them. The results are cumulative so
  a nested iteration will lead to a large iteration total time.
• A large average time for "Set" could indicate Planimate has to swap
  to get to data (running low on memory)

---

idkbase note 9