ProcScript Profiling and Tracing

ProcScript profiling enables you to analyze performance problems by logging trigger processing time. ProcScript tracing enables you to log the ProcScript that was executed, optionally enhanced with additional information.

You can enable and disable ProcScript profiling and/or tracing for the whole application using assignment settings, or selectively in ProcScript. Setting ProcScript profiling and tracing in ProcScript enables you to limit ProcScript tracing to modules where you suspect a problem, but it is only feasible in a development or testing environment. Before deploying the application, you should remove ProcScript tracing commands from the application.

Caution: ProcScript profiling and tracing have a significant impact on performance and memory. They generate large log files and can cause an application to run out of memory. To control memory consumption you can execute the clrmess at regular intervals. However, we recommend that you use profiling and tracing only when tracing and debugging a problem, preferably in a development or test environment.

By default, ProcScript profling and tracing information is written to the Message Frame or to the message log file (Defined by $PUTMESS_LOG_FILE). To specify a different log file for ProcScript profiling and tracing, use the $PROC_LOG_FILE assignment setting,

ProcScript Profiling

ProcScript profiling records information about the processing time of each trigger and ProcScript module executed. You can use this information to analyze performance problems. The profiling information is formatted as a list, containing data that identifies each ProcScript module and its processing time. The type of information depends on the type of ProcScript module (for example whether it requires database access or not).

When profiling is enabled, profiling information is directed to the Message Frame or log file as a Uniface list. You can specify a different separator (than GOLD ;) using the $PROC_PROFILING_SEPARATOR assignment setting.

Assignment Setting	Purpose
`$PROC_PROFILING`	Enable Uniface profiling.
`$PROC_LOG_FILE`	Specify the log file in which to store profiling information.
`$PROC_PROFILING_SEPARATOR`	Specify the separator to use in separating items in the profiling information.

In ProcScript, you can use the $proc_profiling ProcScript function to switch profiling on or off, or to check whether it is already activated.

Profiling Information
Field	Meaning	Description
`REC`	Record Type
`SEQ`	Sequence number	Sequence number within the Uniface call stack
`NEST`	Nesting level	Level of the current ProcScript module within the Uniface call stack
`ELAPSTIME` `ELAPSTIME_X`	Elapsed time	Time spent executing the ProcScript module, in units of 10 microseconds (1/100,000 of a second). Because ProcScript modules nest, and there is no recording at the beginning of a module, the modules appear in reverse order in the profiling output, that is, you see the measurement for the first, outermost ProcScript module at the end of the log.
`IDLETIME`	Idle time	Time spent waiting for window manager events and user-action events, such as edit time in a non-modal form, response to `askmess`, and so on
`DBMSTIME`	DBMS time	Time spent waiting DBMS driver I/O
`NETTIME`	Network time	Time spent waiting for the network, including time for the Uniface Router/Server performing network DBMS I/O and activating distributed services over the network.
`TYPE`	Module type	Local ProcScript, global ProcScript, ProcScript in a trigger, or ProcScript in an operation
`MODID`	Module identifier
`MODNAM`	Module name	Module name and component name—the name of the ProcScript module and the component being measured, as well as additional information relating to the location of the module
`TRIG`	Trigger name
`TRIGGER`	Trigger abbreviation
`OBJTYPE`	Object type	Type of object, such as the component type, menu, global ProcScript, and so on
`APSNAM`	Application name	Name of the application for which profiling is enabled
`CPTNAM`	Component name	Name of the current component
`INSNAM`	Instance name	Name of the current component instance
`FIELD`	Field name	Name of the current component field, entity, and model for which the ProcScript module was executed
`ENTITY`	Entity name
`MODEL`	Model name

ProcScript Tracing

ProcScript tracing records the ProcScript that is executed. It can be used in combination with profiling to provide additional details about the code being executed.

For example:

(_leavefield) LFLD:1  $fieldproperties(SHOW2.COLORS) = "backcolor=%%COLORBOX.COLORS·forecolor="
(_leavefield) LFLD:2  done<end of module>

You can differentiate or enhance the information produced by tracing by specifying a string or expression to precede the tracing data using $PROC_TRACING_ADDITION or $proc_tracing_addition.

Assignment Setting	ProcScript	Purpose
`$PROC_TRACING`	$proc_tracing	Enable ProcScript tracing.
`$PROC_TRACING_ADDITION`	$proc_tracing_addition	Specify a string or expression to precede each line of ProcScript tracing
`$PROC_LOG_FILE`	—	Specify the log file in which to store profiling information.

Sample Profiling and Tracing Information

The assignment file contains the following settings to enable and configure ProcScript profiling and tracing:

$PROC_PROFILING=true
$PROC_LOG_FILE = C:\Users\joeblow\uniface 10\log\profiling.log
$PROC_PROFILING_SEPARATOR= comma

$PROC_TRACING=true
$PROC_TRACING_ADDITION = "Status:%% $status"

The loseFocus trigger of a field contains the following code:

;Leave_field (LFLD) trigger for field COLORBOX.COLORS.COLORS
$fieldproperties(SHOW2.COLORS)="backcolor=%%COLORBOX.COLORS%%%·;forecolor="

The following tracing and profile information is recorded when this trigger is executed:

"Status:0 "(_leavefield) LFLD:1  $fieldproperties(SHOW2.COLORS) = "backcolor=%%COLORBOX.COLORS·forecolor="
"Status:0 "(_leavefield) LFLD:2  done<end of module> 
REC=PROFILING,SEQ=2889,NEST=21,ELAPSTIME=1,ELAPSTIME_X=1,TYPE=TRG,MODID=t6\LFLD,MODNAM=LFLD,
TRIG=_leavefield,TRIGGER=LFLD,OBJTYPE=FRM,APSNAM=MYAPP,CPTNAM=COLORS,INSNAM=COLORS,FIELD=COLORBOX,
ENTITY=COLORS,MODEL=COLORS

When the application stops executing, the following profile information is recorded:

REC=PROFILING,SEQ=1,NEST=1,ELAPSTIME=105371576,ELAPSTIME_X=87,IDLETIME=105232056,DBMSTIME=44820,
TYPE=TRG,MODID=tAPPL,MODNAM=APPL,TRIG=_application_exec,TRIGGER=APPL,OBJTYPE=APS,APSNAM=MYAPP,CPTNAM=MYAPP

Notice that the record for the first module (starting the application) is recorded last.