Skip to main content

Examining Routine Performance Using ^%SYS.MONLBL

The routine ^%SYS.MONLBL provides a user interface to the InterSystems IRIS® data platform MONITOR facility. This utility provides a way to diagnose where time is spent executing selected code in 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 an InterSystems IRIS instance.

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 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
  Generic Memory Heap (gmheap) 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 Estimate Memory Requirements for details.

  • Press the Enter key to exit the routine.

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:

  1. 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.

  2. 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

      The time metrics are clock time and are measured in seconds.

      Note:
      Total Time for Recursive Code

      When 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 InterSystems IRIS 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 ObjectScript
      .
      .
      .
      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 Line-by-line Monitor Programming Interface for a method of retrieving the list.

      Note:

      For all collections, the number of routine lines and time (minimal metrics) are always collected.

  3. 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 Processes page of the Management Portal (System Operation > Processes) 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.

Note:

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. Line-by-line Monitoring Options 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 generic memory heap parameter if necessary.

You can maintain the gmheap (generic memory heap) setting from the Advanced Memory Settings page of the Management Portal (System Administration > Configuration > Additional Settings > Advanced Memory).

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 following subsections explain the four report options.

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. InterSystems IRIS 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:

  1. 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
    
    
  2. 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
    
    
  3. 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:
    
    
  4. You can enter a file name or a full directory path for the output. You can instead enter nothing and press Enter to display the report on your terminal.

    If you enter a file name but not a path, %SYS.MONLBL creates the file in the directory of the current namespace’s default database for globals. For example, if running %SYS.MONLBL in the USER namespace:

    FileName: monlbl_JRN_dtl.txt
    
    

    Creates a file for the report in install-dir\mgr\user named monlbl_JRN_dtl.txt.

  5. Press Enter to initiate the reporting of the metrics you are collecting in the format you have chosen.

Sample 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.

Sample 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.

Sample 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 row, 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.

Row,Routine,Line,RtnLine,Time,TotalTime,Code
1,JRNDUMP,1,0,0,0,"JRNDUMP ;dump the contents of a journal file ; 
,2,0,0,0," /*"
.
.
.
85,JRNDUMP,85,0,0,0," n (l,usecluster)"
86,JRNDUMP,86,3,0.000016,0.000016," i +$g(usecluster) d showlistclu(.l) q"
87,JRNDUMP,87,3,0.000008,0.000008," s diroff=((3+12+1)+10+1)"
88,JRNDUMP,88,3,0.000072,0.000072," s i="""" f  s i=$o(l(i)) q:i=""""  d"
89,JRNDUMP,89,11,0.001542,0.001542," . w /cup(i+3,1),?3,$S($F(l(i),"";""):$E(l(i),...
90,JRNDUMP,90,11,0.028125,0.028220," . w ?(3+12+1),l(i,""info""),?diroff...
91,JRNDUMP,91,11,0.000378,0.000895," . w $$GJrnPrefix(l(i))"
92,JRNDUMP,92,3,0.000027,0.000027," q"
93,JRNDUMP,93,0,0,0,"listjrn(f,list,n) ;list at most n journal files...
.

This is a partial display of one selected routine.

Sample 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.

Metrics Shown in These Reports

These reports show the following metrics:

  • GloRef — global references

  • GloSet — global sets

  • GloKill — global kills

  • DirBlkRd — directory block reads

  • UpntBlkRd — upper pointer block reads

  • BpntBlkRd — bottom pointer block reads

  • DataBlkRd — data block reads

  • BdataBlkRd — big data block reads

  • MapBlkRd — map block reads

  • OthBlkRd — other block reads

  • DirBlkWt — directory block writes

  • UpntBlkWt — upper pointer block writes

  • BpntBlkWt — bottom pointer block write

  • DataBlkWt — data block writes

  • BdataBlkWt — big data block writes

  • MapBlkWt — map block writes

  • OthBlkWt — other block writes

  • DirBlkBuf — directory block requests satisfied from a global

  • UpntBlkBuf — upper pointer block requests satisfied from a global buffer

  • BpntBlkBuf — bottom pointer block requests satisfied from a global buffer

  • DataBlkBuf — data block requests satisfied from a global buffer

  • BdataBlkBuf — big data block requests satisfied from a global buffer

  • MapBlkBuf — map block requests satisfied from a global buffer

  • OthBlkBuf — other block requests satisfied from a global buffer

  • JrnEntry — journal entries

  • BlkAlloc — blocks allocated

  • NetGloRef — network global refs

  • NetGloSet — network sets

  • NetGloKill — network kills

  • NetReqSent — network requests sent

  • NCacheHit — network cache hits

  • NCacheMiss — network cache misses

  • NetLock — network locks

  • RtnLine — lines of ObjectScript

  • RtnLoad — routine loads

  • RtnFetch — routine fetches

  • LockCom — lock commands

  • LockSucc — successful lock commands

  • LockFail — failed lock commands

  • TermRead — terminal reads

  • TermWrite — terminal writes

  • TermChRd — terminal read chars

  • TermChWrt — terminal write chars

  • SeqRead — sequential reads

  • SeqWrt — sequential writes

  • IJCMsgRd — local interjob communication (IJC) messages read

  • IJCMsgWt — local IJC messages written

  • IJCNetMsg — network IJC messages written

  • Retransmit — network retransmits

  • BuffSent — network buffers sent

  • Time — elapsed time (sum of each time it is hit)

  • TotalTime — total time used (including subroutines)

Line-by-line Monitor Programming Interface

Programmers can also interface with the InterSystems IRIS 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 %Monitor.System.LineByLineOpens in a new tab for more details.

FeedbackOpens in a new tab