Examining Routine Performance Using ^%SYS.MONLBL
The routine ^%SYS.MONLBL provides a user interface to the Caché MONITOR facility. This utility provides a way to diagnose where time is spent executing selected code in ObjectScript and Caché Basic routines, helping to identify lines of code that are particularly resource intensive. It is an extension of the existing MONITOR utility accessed through ^PERFMON and the %Monitor.System package classes. Because these utilities share the same memory allocation, you can only run one of them at a time on a Caché instance.
This chapter contains the following sections:
Invoking the Line-by-line Monitoring Routine
If the monitor is not running when you invoke ^%SYS.MONLBL, the routine displays a warning message and gives you the option to start the monitor or to check memory requirements. For example:
%SYS>Do ^%SYS.MONLBL
WARNING ! Starting the line-by-line monitor will enable the
collection of statistics for *every* line of code executed by
the selected routines and processes. This can have a significant
impact on the performance of a system, and it is recommended
that you do this on a 'test' system.
The line-by-line monitor also allocates shared memory to track
these statistics for each line of each routine selected. This is
taken from the general shared memory already allocated by Cache and
should be considered if you are using '*' wildcards and trying to
analyze a large number of routines. If the monitor fails to start due
to a problem with memory allocation, you may need to increase the
GenericHeapSize parameter in the system configuration. You may use
the 'Memory Requirements' option to see how much memory a collection
would need (without starting the collection).
1.) Start Monitor
2.) Memory Requirements
Enter the number of your choice:
-
Enter 1 to begin the dialog to provide the appropriate information to Start Monitoring.
-
Enter 2 to calculate an estimate of how much memory a collection needs before actually starting the monitor. See the Estimate Memory Requirements section for details.
Start Monitoring
You can select which routines and processes to monitor and which metrics to collect. These characteristics of the collection remain until you stop the monitor. You provide monitoring collection information to the routine in the following order:
-
Routine Names – Enter a list of routine names to monitor. You can only select routines accessible from your current namespace. Do not use the leading ^ when entering the routine name; the names are case-sensitive. You may use asterisk (*) wild cards to select multiple routines. Press Enter twice after entering the last routine name to end the list.
-
Select Metrics to monitor – Enter the number of your choice of what type of metrics. The default is 1 for minimal metrics.
Select Metrics to monitor 1) Monitor Minimal Metrics 2) Monitor Lines (Coverage) 3) Monitor Global Metrics 4) Monitor All Metrics 5) Customize Monitor Metrics Enter the number of your choice: <1>
A description of what metrics are included for each option follows:
-
Minimal metrics — Monitors the metrics described in the following table.
Metric Description Metric#: 34 - RtnLine Number of times a routine line is executed Metric#: 51 - Time Clock time spent in executing that line Metric#: 52 - TotalTime Total clock time for that line including time spent in subroutines called by that line Note:Total Time for Recursive CodeWhen a routine contains recursive code, the TotalTime counter for the line which calls back into the same subroutine only records the time of the outermost call, which should be, in most cases, the actual time to run the recursive loop. Prior Caché releases accumulated the time for multiple iterations of the same code reporting times that may have seemed too large.
-
Lines — Monitors the number of times a routine line is executed (Metric#: 34 - RtnLine).
-
Global metrics — Monitors several global metrics (Metric# 1-26,34-36,51,52).
-
All metrics — Monitors all available metrics.
-
Customize metrics — Allows you to create a customized list of metrics to monitor. You can select any of the standard performance metrics supported by the %Monitor.System package classes. Enter a question mark (?) when prompted for the metric item number to see a list of available metrics. For example:
Enter the number of your choice: <1> 5 Enter metrics item number (press 'Enter' to terminate, ? for list) Metric#: ? 1.) GloRef: global refs 2.) GloSet: global sets . . . 34.) RtnLine: lines of Cache Object Script . . . 51.) Time: elapsed time on wall clock 52.) TotalTime: total time used (including sub-routines) Metric#:
This example does not show the full list; it is best for you to retrieve the current list when you run the routine. See the Line-by-line Monitor Programming Interface section for a method of retrieving the list.
Note:For all collections, the number of routine lines and time (minimal metrics) are always collected.
-
-
Select Processes to monitor – Enter the number of your choice as it appears in the menu. The default is 1 for all processes.
Select Processes to monitor 1.) Monitor All Processes 2.) Monitor Current Process Only 3.) Enter list of PIDs Enter the number of your choice: <1>
^%SYS.MONLBL does not currently provide a list or a way to select PIDs; however, you can use the ^%SS utility or the System > Processes page of the Management Portal to find specific process ID numbers.
Enter the number of your choice: <1> 3 Enter PID (press 'Enter' to terminate) PID: 1640 PID: 2452 PID:
Press Enter twice after entering the last process ID to end the list.
Once you provide the necessary information, ^%SYS.MONLBL allocates a special section of shared memory for counters for each line per routine, and notifies the selected processes that monitoring is activated.
Since shared counters may be updated simultaneously by multiple processes and/or running processes may not start counting at exactly the same moment, there may be a slight loss of precision in the counters, resulting in counts being lower than expected.
Monitor started.
Press RETURN to continue ...
After starting the line-by-line monitor, the routine displays a more extensive menu. The Line-by-line Monitoring Options section describes each option on this extended menu.
Estimate Memory Requirements
Before starting the monitoring process you can use this utility to estimate how much memory a collection requires. Typically, there is sufficient shared memory available for monitoring a few routines. However, if you want to monitor hundreds or more routines, use this option to help determine memory needs.
The routine and metrics prompts are identical to those for the Start Monitor choice. After you select the routines to monitor and the metrics to gather, the utility displays the number of pages of memory required to monitor this collection and the number of pages available. It also tells you to increase the size of the GenericHeapSize parameter if necessary.
You can maintain the gmheap (GenericHeapSize) setting from the System > Configuration > Advanced Memory Settings page of the Management Portal.
The following is an example that estimates the memory requirements for monitoring eight selected metrics for all routines that begin with JRN:
Enter the number of your choice: 2
Enter routine names to be monitored on a line by line basis.
Patterns using '*' are allowed.
Enter '?L' to see a list of routines already selected.
Press 'Enter' to terminate input.
Routine Name: JRN* (22 routines added to selection.)
Routine Name:
Select Metrics to monitor
1) Monitor Minimal Metrics
2) Monitor Lines (Coverage)
3) Monitor Global Metrics
4) Monitor All Metrics
5) Customize Monitor Metrics
Enter the number of your choice: <1> 5
Enter metrics item number (press 'Enter' to terminate, ? for list)
Metric#: 1 - GloRef
Metric#: 2 - GloSet
Metric#: 3 - GloKill
Metric#: 25 - JrnEntry
Metric#: 34 - RtnLine
Metric#: 35 - RtnLoad
Metric#: 51 - Time
Metric#: 52 - TotalTime
Metric#:
9 page(s) of memory required.
82 page(s) of memory available.
The GenericHeapSize parameter can be increased if more memory is needed.
Pages are each 64kb of memory.
Press RETURN to continue ...
You may adjust your memory if that is required for your selected collection and then choose to Start Monitoring from the original menu.
Line-by-line Monitoring Options
If you invoke ^%SYS.MONLBL while the monitor is running you have the following menu options:
Line-by-Line Monitor
1.) Stop Monitor
2.) Pause Monitor / Resume Monitor
3.) Clear Counters
4.) Report - Detail
5.) Report - Summary
6.) Report - Delimited (CSV) Output
7.) Report - Procedure Level
Enter the number of your choice:
The first three options are fairly self-explanatory:
-
Stop Monitor — Stops all ^%SYS.MONLBL monitoring; deallocates the counter memory and deletes collected data.
-
Pause Monitor — Pauses the collection and maintains any collected data. This may be useful when viewing collected data to ensure that counts are not changing as the report is displayed. This option only appears if the monitor is running.
Resume Monitor — Resumes collection after a pause. This option only appears if you paused the monitor.
-
Clear Counters — Clears any collected data, but continues monitoring and collecting new data.
The Report Line-by-line Statistics section explains the four report options in more detail.
Report Line-by-line Statistics
When you choose to report the statistics of the metrics that have been collecting (options 4–7), you then provide information about how you want the routine to report the statistics.
You have four types of reports to choose from:
-
Detail — Generates a report of the selected metrics for each line in the selected routines. The report accumulates and displays totals for each of the performance columns.
-
Summary — Generates a report of summary information for each selected routine including coverage and time. The report orders the routines by coverage percentage.
-
Delimited (CSV) Output — Generates the same report information as the detail report, but presents it as comma-delimited output facilitating its import into a spreadsheet.
-
Procedure Level — Generates a report of selected metrics at a subroutine level within the selected routines. Caché allows you to profile usage at the level of individual subroutines, procedures, and functions. You can quickly see which subroutines are taking up the most time to run to analyze and improve performance.
Depending on which type of report you choose, you select how you want to display the information:
-
If you choose the detail or summary report, you can also choose if you want to include a coverage analysis for the lines executed in each routine you select. For example:
Enter the number of your choice: 4 Include Coverage Analysis summary (Y/N)? y
-
Next, for all but the summary report, select one or more routines from the list of monitored routines that have statistics available; enter an asterisk (*) for all available routines. For example:
The following routines have been executed during the run, and have detail statistics available for them. 1) JRNDUMP 2) JRNOPTS 3) JRNSTART 4) JRNSWTCH 5) JRNUTIL 6) JRNUTIL2 Enter list of routines, or * for all Routine number (*=All)? * - All
-
If you are entering routine names, after entering the last routine, press Enter again to end the list. For example:
Enter list of routines, or * for all Routine number (*=All)? 1 - JRNDUMP Routine number (*=All)? 2 - JRNOPTS Routine number (*=All)? 5 - JRNUTIL Routine number (*=All)? FileName:
-
You can enter a file name for the output, or enter nothing and press Enter to display the report on your terminal. If you enter a name, the file is created in the manager’s directory. For example:
FileName: monlbl_JRN_dtl.txt
Creates a file for the report in install-dir\mgr named monlbl_JRN_dtl.txt.
-
Press Enter to initiate the reporting of the metrics you are collecting in the format you have chosen.
The Sample Line-by-line Monitor Reports section shows examples of each reporting option.
Sample Line-by-line Monitor Reports
This section contains samples of the various reports the ^%SYS.MONLBL routine generates:
Line-by-line Detail Report
The following is an example of reporting the detail of the minimal metrics of selected journal utilities including the coverage analysis. The report is sent to the monlbl_JRN_dtl.txt file, a portion of which is displayed.
Line-by-Line Monitor
1.) Stop Monitor
2.) Pause Monitor
3.) Clear Counters
4.) Report - Detail
5.) Report - Summary
6.) Report - Delimited (CSV) Output
7.) Report - Procedure Level
Enter the number of your choice: 4
Include Coverage Analysis summary (Y/N)? y
The following routines have been executed during the run,
and have detail statistics available for them.
1) JRNDUMP
2) JRNOPTS
3) JRNSTART
4) JRNSWTCH
5) JRNUTIL
6) JRNUTIL2
Enter list of routines, or * for all
Routine number (*=All)? 1 - JRNDUMP
Routine number (*=All)? 2 - JRNOPTS
Routine number (*=All)? 5 - JRNUTIL
Routine number (*=All)?
FileName: monlbl_JRN_dtl.txt
Press RETURN to continue ...
For each line of the selected routine(s), the report displays a line number, the counts for each metric, and the text of that line of code (if source code is available). If you requested coverage analysis, it displays after each selected routine.
Routine ^JRNDUMP ...
Line RtnLine Time TotalTime
1 0 0 0 JRNDUMP ;dump the contents...
2 0 0 0 /*
.
.
.
85 0 0 0 n (l,usecluster)
86 3 0.000016 0.000016 i +$g(usecluster) d showlistclu(.l) q
87 3 0.000008 0.000008 s diroff=((3+12+1)+10+1)
88 3 0.000072 0.000072 s i="" f s i=$o(l(i)) q:i="" d
89 11 0.001542 0.001542 . w /cup(i+3,1),?3,$S($F(l(i),";")...
90 11 0.028125 0.028220 . w ?(3+12+1),l(i,"info"),?diroff...
91 11 0.000378 0.000895 . w $$GJrnPrefix(l(i))
92 3 0.000027 0.000027 q
93 0 0 0 listjrn(f,list,n) ;list at most...
.
.
.
Total 582 17.258963
Total Lines = 579
Total Lines Hit = 100
Coverage Percentage = 17.27%
This is a partial display of one selected routine.
Line-by-line Summary Report
The following is an example of reporting a summary of the minimal metrics of selected journal utilities including the coverage analysis. The report is sent to the monlbl_JRN_summ.txt file, a portion of which is displayed.
Line-by-Line Monitor
1.) Stop Monitor
2.) Pause Monitor
3.) Clear Counters
4.) Report - Detail
5.) Report - Summary
6.) Report - Delimited (CSV) Output
7.) Report - Procedure Level
Enter the number of your choice: 5
Include Coverage Analysis summary (Y/N)? Y
FileName: monlbl_JRN_summ.txt
Press RETURN to continue ...
The report shows each selected routine with a summary of lines, coverage, and time. The routines with the highest coverage percentage appear first in the list.
Routine Lines LinesHit Percent RtnLine Time
JRNOPTS 109 60 55.05% 155 14.172230
JRNSWTCH 249 58 23.29% 69 0.926131
JRNDUMP 579 100 17.27% 582 17.265002
JRNSTART 393 23 5.85% 23 0.005541
JRNUTIL 872 39 4.47% 39 0.116995
JRNUTIL2 276 8 2.90% 56 0.006056
JRNCHECK 18 0 0.00%
JRNCLFOR 416 0 0.00%
JRNCLUREST 193 0 0.00%
JRNCLUREST2 229 0 0.00%
JRNINFO 263 0 0.00%
JRNMARK 195 0 0.00%
JRNRESTB 1315 0 0.00%
JRNRESTC 1245 0 0.00%
JRNRESTC2 540 0 0.00%
JRNRESTCHELP 122 0 0.00%
JRNRESTD 445 0 0.00%
JRNRESTO 859 0 0.00%
JRNROLL 827 0 0.00%
JRNSTAT 62 0 0.00%
JRNSTOP 119 0 0.00%
JRNWUTL 235 0 0.00%
TOTAL 22 rtns 9561 288 3.01% 924 31.591955
This is the complete sample report.
Line-by-line Delimited Output Report
This example reports the delimited detail of the minimal metrics of selected journal utilities. The report is sent to the monlbl_JRN_csv.txt file, a portion of which is displayed:
Line-by-Line Monitor
1.) Stop Monitor
2.) Pause Monitor
3.) Clear Counters
4.) Report - Detail
5.) Report - Summary
6.) Report - Delimited (CSV) Output
7.) Report - Procedure Level
Enter the number of your choice: 6
The following routines have been executed during the run,
and have detail statistics available for them.
1) JRNDUMP
2) JRNOPTS
3) JRNSTART
4) JRNSWTCH
5) JRNUTIL
6) JRNUTIL2
Enter list of routines, or * for all
Routine number (*=All)? * - All
FileName: monlbl_JRN_csv.txt
Press RETURN to continue ...
For each line of the selected routine(s), the report displays the routine name, line number, the counts for each metric, and the text of that line of code (if source code is available) all delimited by a comma. The source code line is contained within quotes.
Routine,Line,RtnLine,Time,TotalTime,Code
JRNDUMP,1,0,0,0,"JRNDUMP ;dump the contents of a journal file ;
,2,0,0,0," /*"
.
.
.
JRNDUMP,85,0,0,0," n (l,usecluster)"
JRNDUMP,86,3,0.000016,0.000016," i +$g(usecluster) d showlistclu(.l) q"
JRNDUMP,87,3,0.000008,0.000008," s diroff=((3+12+1)+10+1)"
JRNDUMP,88,3,0.000072,0.000072," s i="""" f s i=$o(l(i)) q:i="""" d"
JRNDUMP,89,11,0.001542,0.001542," . w /cup(i+3,1),?3,$S($F(l(i),"";""):$E(l(i),...
JRNDUMP,90,11,0.028125,0.028220," . w ?(3+12+1),l(i,""info""),?diroff...
JRNDUMP,91,11,0.000378,0.000895," . w $$GJrnPrefix(l(i))"
JRNDUMP,92,3,0.000027,0.000027," q"
JRNDUMP,93,0,0,0,"listjrn(f,list,n) ;list at most n journal files...
.
This is a partial display of one selected routine.
Line-by-line Procedure Level Report
The following is an example of reporting the detail of the minimal metrics of selected journal utilities by subroutine function. The report is sent to the monlbl_JRN_proc.txt file, a portion of which is displayed.
Line-by-Line Monitor
1.) Stop Monitor
2.) Pause Monitor
3.) Clear Counters
4.) Report - Detail
5.) Report - Summary
6.) Report - Delimited (CSV) Output
7.) Report - Procedure Level
Enter the number of your choice: 7
The following routines have been executed during the run,
and have detail statistics available for them.
1) JRNDUMP
2) JRNOPTS
3) JRNSTART
4) JRNSWTCH
5) JRNUTIL
6) JRNUTIL2
Enter list of routines, or * for all
Routine number (*=All)? * - All
FileName: monlbl_JRN_proc.txt
Press RETURN to continue ...
For each subroutine of the selected routine(s), the report displays a tag number, the counts for each metric, and the subroutine label (if source code is available).
Routine ^JRNDUMP ...
Tag RtnLine Time TotalTime
1 6 0.000154 0.000154 JRNDUMP
2 0 0 0 INT
3 0 0 0 getkey1
4 0 0 0 progress
5 6 0.000050 0.000050 listhdr
6 21 0.000240 0.000322 showlist
7 20 0.136909 0.330301 listjrn
8 7 0.188435 0.188435 getjrninfo
9 0 0 0 guijrn
.
.
.
This is a portion of the report for one selected routine.
Line-by-line Monitor Programming Interface
Programmers can also interface with the Caché MONITOR facility through the %Monitor.System.LineByLineOpens in a new tab class. Methods are provided for each menu option in ^%SYS.MONLBL. For example, start monitoring by calling:
Set status=##class(%Monitor.System.LineByLine).Start(Routine,Metric,Process)
You can select which routines and processes to monitor. You may also select any of the other standard performance metrics supported by the %Monitor.System classes. Use the Monitor.System.LineByLine.GetMetrics() method to retrieve a list of metric names:
Set metrics=##class(%Monitor.System.LineByLine).GetMetrics(3)
Selecting 3 as the parameter prints a list of all available metrics with a short description for each to the current device.
Stop monitoring by calling:
Do ##class(%Monitor.System.LineByLine).Stop()
You can retrieve the collected counts using the %Monitor.System.LineByLine:Result query, where the counters for each line are returned in $LIST format.
See the %Monitor.System.LineByLineOpens in a new tab class entry in the online InterSystems Class Reference for more details.