Code analysis and testing

KCML includes built-in support for performance analysis of KCML programs. It also includes the ability to record cumulative code coverage statistics of successive KCML sessions.

Profiling

This measures the frequency and duration of function calls. It can be activated in two ways. Either through the command line upon starting a program or via an built-in function calls while the program is running. In each case the results are written out to the specified file in HTML.

kcml -Q results.html program.src

'KCML_PerfStats_Start("results.html")
'profilethiscode()
'KCML_PerfStats_End()

Profiling can use a lot of memory. This is separate from application memory and can be controlled by the KCML_LOG_SIZE environment variable

Coverage

This measures the frequency each statement is executed. It requires that the libraries are built in a special way. The kc6 program will produce the library file as well as a file to hold the statistics. The KCML session is started as normal.

kc6 -p -o library.kbin library.src

set the CodeCoverage flag in build.xml for kmake.

The example above will produce a library.kbin and a library.kbin.coverage. The data in the coverage file is stored in a binary format. It can be enumerated by built-in function calls.

'KCML_Coverage_EnumerateLibrary("library.kbin.coverage", SYM('print))
DEFSUB 'print(sEntry$_KCML_COVERAGE_ENTRY)
ENDSUB

From KCML 7.19.00.24209 the coverage files can be located in a different directory using the $KCML_COVERAGE_DIR environment variable.

Call stats (Linux only)

This measures the frequency of function calls. It requires that an option be specified at library build time. The kc6 program will produce the library file as normal and will also produce a file to hold the statistics. Updating of statistics must be enabled at runtime.

kc6 -f callstats -o library.kbin library.src

set the callstats flag in build.xml for kmake.

The example above will produce a library.kbin and a library.kbin.callstats. The library file is not instrumented and will be exactly the same as if the callstats flag had not been specified. The data in the callstats file is stored as an array of records which can be mapped into memory. The statistics persist across sessions and library rebuilds.

From KCML 7.19.00.24209 the callstats files can be located in a different directory using the $KCML_CALLSTAT_DIR environment variable.

Consider the following library fib:

 00010 $COMPLIANCE 3
     : 
     : PUBLIC DEFSUB 'fib_print_table(min, max)
     :     LOCAL DIM i
     :     FOR i = min TO max
     :         PRINT $PRINTF("fib %2d = %d", i, 'fib(i))
     :         END FOR
     : END SUB
     : 
     : PRIVATE DEFSUB 'add(a, b)
     :     RETURN a + b
     : END SUB
     : 
     : PUBLIC DEFSUB 'fib(n)
     :     LOCAL DIM result
     :     
     :     SELECT CASE n
     :         CASE 0
     :         result = 1
     :         CASE 1
     :         result = 1
     :         CASE ELSE
     :         result = 'add('fib(n - 1), 'fib(n - 2))
     :         END SELECT
     :     
     :     RETURN result
     : END SUB

When built with callstats enabled, statistics can be gathered as follows:

 00010 $COMPLIANCE 3
     : LIBRARY ADD "fib" = "fib.kbin"
     : 'main()
     : END
     : 
     : DEFSUB 'main()
     :     LOCAL DIM x$(0)_KCML_CallStat
     :     LOCAL DIM i AS Integer
     :     LOCAL DIM max AS Integer
     :     
     :     'KCML_Debug_EnableCallStats(TRUE)
     :     'fib_print_table(1, 10)
     :     'KCML_Debug_EnableCallStats(FALSE)
     :     
     :     'KCML_Map_FileArray(BYREF x$(), "/path/to/fib.kbin.callstats", _MAPFILE_READONLY + _MAPFILE_OPEN)
     :     
     :     max = DIM(x$(), 1)
     :     FOR i = 1 TO max
     :         IF (FLD(x$(i).kcml_callstat_count) > 0)
     :             PRINT $PRINTF("%6d : %s", FLD(x$(i).kcml_callstat_count), FLD(x$(i).kcml_callstat_name$))
     :         END IF
     :         END FOR
     :     
     : END SUB

fib  1 = 1
fib  2 = 2
fib  3 = 3
fib  4 = 5
fib  5 = 8
fib  6 = 13
fib  7 = 21
fib  8 = 34
fib  9 = 55
fib 10 = 89
     1 : 'fib_print_table
   452 : 'fib
   221 : 'add

It is safe to enable callstats on multiple processes simultaneously, and to view the statistics in the file while they are being updated, as in the following:

 00010 $COMPLIANCE 3
     : LIBRARY ADD "fib" = "fib.kbin"
     : 'main()
     : END
     : 
     : DEFSUB 'main()
     :     LOCAL DIM x$(0)_KCML_CallStat
     :     LOCAL DIM i AS Integer
     :     LOCAL DIM n AS Integer
     :     LOCAL DIM fib_idx AS Integer
     :     LOCAL DIM last_count AS Integer
     :     LOCAL DIM max AS Integer
     :     
     :     'KCML_Map_FileArray(BYREF x$(), "/path/to/fib.kbin.callstats", _MAPFILE_READONLY + _MAPFILE_OPEN)
     :     
     :     // find 'fib()'s entry in the array
     :     max = DIM(x$(), 1)
     :     FOR i = 1 TO max
     :         IF (FLD(x$(i).kcml_callstat_name$) == "'fib")
     :             fib_idx = i
     :             BREAK
     :         END IF
     :         END FOR
     :     
     :     // show how many recursive 'fib() calls are used calculating the n'th fibonacci number
     :     'KCML_Debug_EnableCallStats(TRUE)
     :     FOR i = 1 TO 10
     :         last_count = FLD(x$(fib_idx).kcml_callstat_count)
     :         n = 'fib(i)
     :         PRINT $PRINTF("The %dth fibonacci number is %d. 'fib() was called %d times.\n", i, n, FLD(x$(fib_idx).kcml_callstat_count) - last_count)
     :         END FOR
     :     'KCML_Debug_EnableCallStats(FALSE)
     : END SUB

The 1th fibonacci number is 1. 'fib() was called 1 times.
The 2th fibonacci number is 2. 'fib() was called 3 times.
The 3th fibonacci number is 3. 'fib() was called 5 times.
The 4th fibonacci number is 5. 'fib() was called 9 times.
The 5th fibonacci number is 8. 'fib() was called 15 times.
The 6th fibonacci number is 13. 'fib() was called 25 times.
The 7th fibonacci number is 21. 'fib() was called 41 times.
The 8th fibonacci number is 34. 'fib() was called 67 times.
The 9th fibonacci number is 55. 'fib() was called 109 times.
The 10th fibonacci number is 89. 'fib() was called 177 times.