Application Profiling

QM includes a number of tools for gathering data relating to application performance. Collectively these allow detailed analysis of an application's performance, a process referred to as Application Profiling. This section summarises the profiling tools.

FSTAT

The FSTAT command gathers data on file activity (opens, reads, writes, etc) either on a global basis or on selected files. When used in the latter manner, data collected is stored in the file and will persist across application shutdowns until cleared.

As a profiling tool, FSTAT gives an overall perception of file activity but does not identify where that activity is occurring.

GLOBAL FILE STATISTICS 12:44:21

........System .........Total .............. .......Average

.........Total ......this run .......Per sec .......per sec

Period 94:05:27 00:00:04

Opens 4239 552 482 138.0

Writes 1488262 939 145 234.8

Deletes 95775 231 184 57.8

Clears 80 8 6 2.0

Selects 1220 190 171 47.5

Splits 1304 11 0 2.8

Merges 1 0 0 0.0

AK Reads 3606 730 54 182.5

AK Writes 4801 758 113 189.5

AK Deletes 72 24 12 6.0

Cache Hits 0 0 0 0.0

HSM

The Hot Spot Monitor (HSM) can be enabled on individual processes to accumulate data that helps in identifying where an application spends most of its time and hence the places worth attention when seeking to improve performance.

Calls CP time Opens Reads Writes Deletes Program

1 0.000 0 0 0 0 $INLINE

1 0.031 1 6 265 2 CONTROL

1 0.000 0 2 0 2 $DELCAT

1 0.000 1 6 2 0 VFS

152 0.953 1 536 0 0 $BCOMP

1 0.000 0 0 0 0 !TRIMS

2 0.031 0 129 43 43 *UVSUBS

3 0.078 0 233 109 218 $BASIC

1 0.000 1 2 0 0 QMCLIENT

2 0.000 4 68 31 0 $COPY

1 0.031 5 174 41 171 QUERY

129 0.000 0 0 0 0 !SMUL

25 0.000 0 0 0 0 !SSUB

220 0.375 451 13087 0 0 $QPROC

3791 0.015 0 9 0 0 $QDISP

Command Logger

The Command Logger generates a log of every command executed, including those from within Procs, paragraphs, menus, programs, etc. It can be applied on a system wide basis or within specific QM processes.

1569326162 44 DEV User start compile

1569326162 44 DEV PA start@2 CLEAR.FILE $COMO

1569326162 44 DEV PA start@3 IF "<<U,C2>>" = "COMPILE" THEN BASIC BP * NO.PAGE

1569326162 44 DEV PA start@3 IF "COMPILE" = "COMPILE" THEN BASIC BP * NO.PAGE

1569326162 44 DEV PA start@3 BASIC BP * NO.PAGE

1569326162 44 DEV Exec $BASIC@351 CATALOGUE BP CTEST.CLS CTEST.CLS

1569326163 44 DEV PA start@4 RUN START

1569326163 44 DEV Chain RUN CONTROL

The columns of the example report extract above are:

•Timestamp (as an epoch value)

•User number

•User name

•Command origin

•Command

Note that in this example, the IF command near the top of the report generates three log lines; firstly as it appears in the paragraph with the inline prompt in place, then again with the prompt expanded and finally, because the condition was true, as the actual command.

PSTAT

Not strictly a profiling tool, the PSTAT (Process Status) command shows what a QM process is currently doing. It can be used to produce a report of all logged in QM users or just one specific user. Different reporting levels allow selection of what data will be shown.

User Detail

5 Account: QM, Username: MARTIN, Pid: 4044

Command: pstat

$PSTAT 193 (20A1, EVENTS)

6 Account: QM, Username: MARTIN, Pid: 3352

Command: PTERM BREAK OFF

Waiting user input

$SED 5407 (5D3A, KEYIN)

7 Account: QM, Username: MARTIN, Pid: 13820

Command: bell off

TCL prompt waiting input

KEYCODE (398, KEYINTV)

In this example, user 6 is in the SED editor at line 5407. The hexadecimal program offset and internal opcode name are of little use to an application developer but are included for diagnostics. Where a process is waiting for external activity such as keyboard input, the PSTAT command will show this.

Lock Tracing

The Lock Tracer records every lock action across all users of the system. The gathered data is then processed by an interactive reporting tool that produces a (lengthy) report similar to the brief extract below.

Lock Trace

Time.... User Path.................. Id............ Action Program... Offset Line.

25 Sep

12:24:41 13 C:\DEV\QMSYS\$IPC M13 Rel RX $CPROC 000D20 1134

12:24:54 12 c:\temp ~QMSCRL.12 Get RU $QDISP 0004AB 389

12:24:56 12 c:\temp ~QMSCRL.12 Rel RX $QDISP 0016A7 1109

12:24:56 12 C:\DEV\QMSYS\$IPC M12 Get RU $CPROC 000CD2 1125

12:24:56 12 C:\DEV\QMSYS\$IPC M12 Rel RX $CPROC 000D20 1134

Event Profiling

The PROFILER command controls recording and display of application events that are often significant contributors to performance issues. The profiler report is an interactive display that allows the user to drill down starting with a list of logged event types and going down to subsequent screens that show qualifying information for a selected event type (e.g. file name in an OPEN), the program that generated the event and finally, so long as the program is compiled in debug mode, the line numbers within the programs. At each level, the count of events is shown alongside the other information. The brief extract below shows the names of subroutines called by the application and the number of times each was called.

Subroutine call counts

Counts Subroutine Name

>1 BARRED.COUNTRY

1 BARRED.IP

1 DIARY

7 DISPLAY.MENU

1 INIT.COMMON

1 IP.LOOKUP

1 LBSWEB

150 LINK

1 OPEN.FILES

1 S.LOGIN

4 SHOW.HTML