After opening your .vstrace
file, you'll be presented with a tree view of
program execution as a series of statements, some containing others. The lines
contain multiple fields, which are:
1.047970 490ms ( 1.2%) process.vs:26 <readFormVars>
|---1--| |--2-| |--3--| |-----4-----| |----5-------|
1
- The timestamp of when this statement occurred. This is
recorded from the start of the Vortex process, not the start of logging. If
logging is started after a program has been running 18 seconds, timestamps
will start with a value like 18.047970
.2
- The duration of this statement. If this is a function
call or a looping statement, it includes the time of all operations inside the
function, until the point that the function returns or the loop finishes.3
- The percentage of the parent's total time that this statement
constitutes. If <processPage>
takes 3ms and calls <readPage>
,
which takes 2ms, the latter will show as 66%
.
This allows users to quickly see which statements in a function are more responsible for the collective time of the whole function call.
4
- The Vortex source file and line number this statement came from. A
single .vstrace
log may span multiple source files if one script <use>
s
others.5
- The Vortex source at that line. Not all executed
statements exist in the source, such as implicit <return>
statements at
the end of functions.