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
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
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
.vstracelog may span multiple source files if one script
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.