/ Profiler

Code Profile

Jsi can output detailed execution profile information for functions using:

jsish -Iprofile true  SCRIPT

The following demonstrates this on unix:

jsish -Iprofile true  /tmp/while2.js   2>&1 | grep ^PROFILE: | sort -g -r -t= -k2
PROFILE: TOTAL: time=4.169039, func=3.099403, cmd=1.068323, #funcs=10003, #cmds=300001, cover=58.0%, #values=1860447, #objs=610397 
PROFILE:  self=3.000902  all=4.069200  #calls=10000     self/call=0.000300  all/call=0.000407  cover=100.0%  func=foo file=/tmp/while2.js:29 
PROFILE:  self=1.068298  all=1.068298  #calls=300000    self/call=0.000004  all/call=0.000004  cmd=Info.funcs 
PROFILE:  self=0.098484  all=4.167684  #calls=1         self/call=0.098484  all/call=4.167684  cover= 75.0%  func=bar file=/tmp/while2.js:44 
PROFILE:  self=0.000024  all=0.000024  #calls=1         self/call=0.000024  all/call=0.000024  cmd=puts 
PROFILE:  self=0.000017  all=4.167700  #calls=1         self/call=0.000017  all/call=4.167700  cover=100.0%  func=aa file=/tmp/while2.js:27 
PROFILE:  self=0.000002  all=0.000002  #calls=1         self/call=0.000002  all/call=0.000002  cover=  7.0%  func=cc file=/tmp/while2.js:7 

All times are in seconds, and output is sorted by self time (descending).

Following is a list of fields in the PROFILE: TOTAL: line:

time Total amount of CPU used by the program run
func Total mount of CPU used by functions
cmd Total mount of CPU used by commands
#funcs Total number of function calls
#cmds Total number of command calls (non-functions)
cover Total code coverage in percent (functions only)
#valuesTotal number of Jsi_Value allocations
#objsTotal number of Jsi_Obj allocations

Following is a list of fields in each PROFILE line:

self Amount of CPU used by the function
all Amount of CPU used by function and it's descendants
#calls Number of times function was called
self/callPer-call CPU used by the function
all/call Per-call CPU used by the function and it's descendants
cover Code coverage for function, in percent
funcName of the function
cmdName of the command
fileFile and line number of function

Code Coverage

In addition to the simple coverage statistics available with profile, detailed code coverage can be obtained with -Icoverage, eg:

jsish -Icoverage true  /tmp/while2.js   2>&1 | grep ^COVERAGE: | sort -g -r -t= -k4
COVERAGE: func=bar  file=/tmp/while2.js:48  cover=75.0%  hits=6,  all=8,  misses=56-57
COVERAGE: func=cc  file=/tmp/while2.js:7  cover=30.0%  hits=4,  all=13,  misses=10-13,18-22
COVERAGE: func=bb  file=/tmp/while2.js:27  cover=0%

Output is produced only for functions with less than 100% coverage. Uncalled functions are indicated by cover=0% with remaining fields omitted.

Following is a list of the COVERAGE fields:

funcName of the function
fileFile and line number for start of function
cover Code coverage in percent for the function
hits Number of distinct lines executed in the function
all Total number of executable lines in the function
misses List of line-ranges not executed

Code Tracing

Jsi provides a number of program tracing options. Perhaps the easiest to use is from the command-line with -t:

jsish -t tests/module.js
/home/user/jsi/jsi/tests/module.js:12 #1: > mod([]) 
/home/user/jsi/jsi/tests/module.js:12 #1: < mod()  <-- { process:function (a) {...}, x:1, y:2 }
/home/user/jsi/jsi/tests/module.js:22 #1: > process([ 9 ]) 
/home/user/jsi/jsi/tests/module.js:17   #2: > sub([ 10 ]) 
/home/user/jsi/jsi/tests/module.js:17   #2: < sub()  <-- 20
/home/user/jsi/jsi/tests/module.js:22 #1: < process()  <-- 20
/home/user/jsi/jsi/tests/module.js:36 #1: > fmod([]) 
/home/user/jsi/jsi/tests/module.js:36 #1: < fmod()  <-- { process:function (a) {...}, x:1, y:2 }
/home/user/jsi/jsi/tests/module.js:37 #1: > process([ 9 ]) 
/home/user/jsi/jsi/tests/module.js:31   #2: > sub([ 10 ]) 
/home/user/jsi/jsi/tests/module.js:31   #2: < sub()  <-- 20
/home/user/jsi/jsi/tests/module.js:37 #1: < process()  <-- 20

The output may seem overly verbose, but is advantageous when executed from within geany (or vim) in that we can click to navigate through the file.

If simpler traces are desired, try:

jsish -ItraceCall funcs,args tests/module.js
#1: > mod([]) in module.js:12
#1: > process([ 9 ]) in module.js:22
  #2: > sub([ 10 ]) in module.js:17
#1: > fmod([]) in module.js:36
#1: > process([ 9 ]) in module.js:37
  #2: > sub([ 10 ]) in module.js:31