Profiling Code with zeptoforth - tabemann/zeptoforth GitHub Wiki

zeptoforth includes an optional profiler in extra/common/profile.fs. This profiler counts the number of times words defined with : or :noname after it has been loaded are called. Words to be profiled can be compiled to RAM or flash; in the latter case, extra/common/profile.fs must be compiled to flash beforehand and the system must be rebooted prior to executing the profiled words.

Keeping track of the word execution counts is initialized with profile::init-profile ( entries -- ). entries is the entry count of the map used by the profiler to keep track of the execution counts of words. It is not necessary to call this word before compiling words to be profiled. Before this is called the actual execution counts of words are ignored. Note that the number of words for which profiling applies must be smaller than or equal to entries, because if it is larger than entries the execution of a profiled word not already known to the profiler will result in an infinite loop (due to there being no check in the profiler for wrapping around the hash table used for the profiler map). entries must be a power of two for performance reasons. Take care to not exhaust the RAM with profiler map entries, on the other hand; each profiler map entry takes up 8 bytes of RAM. (During development RAM was accidentally exhausted by specifying 65536 entries, forgetting that this value was an entry count rather than a byte count, resulting in allotting 512 KiB of space.)

Profiled word counts max out at 4294967295, so they do not wrap around. This prevents words that are executed very many times from appearing as if they were executed a small number of times.

The profiled word execution counts are dumped to the console with profile::dump-profile ( -- ). This lists the xt, name, and execution count of each profiled word that has been executed at least once. Note that if a profiled word does not have a name or otherwise is not known <no name> is output instead of a name.

For an example of this in use, take the following:

First compile the profiler to RAM (the output of loading is omitted here):

#include extra/common/profile.fs

Then define some words to profile:

: foo ." FOO " ;  ok
: bar foo foo ." BAR " ;  ok
: baz bar bar ." BAZ " ;  ok

Then run these words a few times:

baz FOO FOO BAR FOO FOO BAR BAZ  ok
baz FOO FOO BAR FOO FOO BAR BAZ  ok
baz FOO FOO BAR FOO FOO BAR BAZ  ok

Then dump the (uninitialized) profiler data, showing that nothing has been profiled:

profile::dump-profile  ok

Then initialize the profiler with 1024 profiler map entries:

1024 profile::init-profile  ok

Then execute the profiled words a few more times:

baz FOO FOO BAR FOO FOO BAR BAZ  ok
baz FOO FOO BAR FOO FOO BAR BAZ  ok
baz FOO FOO BAR FOO FOO BAR BAZ  ok

Now dump the profiled data again:

profile::dump-profile 
20019824 foo 12 
20019860 bar 6 
200198A4 baz 3  ok

Here we see that foo was executed 12 times, bar was executed 6 times, and baz was executed 3 times, with the executions before calling profile::init-profile being uncounted.

Now clear the profiled data and see that the profiled data is cleared:

profile::clear-profile  ok
profile::dump-profile  ok

Now execute baz again and get the execution counts:

baz FOO FOO BAR FOO FOO BAR BAZ  ok
profile::dump-profile 
20019824 foo 4 
20019860 bar 2 
200198A4 baz 1  ok

This shows that the actual counts have been reset and start again from zero.