Caché Monitoring Guide
Monitoring Routine Performance Using ^PROFILE
[Back] [Next]
   
Server:docs2
Instance:LATEST
User:UnknownUser
 
-
Go to:
Search:    

The ^PROFILE utility helps programmers analyze the performance of their application routines and classes. It accomplishes this task in two phases:

  1. It gathers data, sorted at the routine level, to help you identify which routines do the most “work.”
  2. It lets you select routines for which you want to gather and display data (subroutines, procedures, and individual lines) at a detail level so that you can “drill down” into the individual routines that may be causing performance issues.
By default, ^PROFILE captures metrics for up to 5000 routines; if there is not enough shared memory available for the maximum number of routines, it displays an informational message before it starts to capture the metrics, then captures metrics for as many routines as possible.
After you select the routines to monitor and the metrics to gather, if there is not enough space to collect metrics on all routines running in Caché, the utility displays a message about the number of pages of memory required to monitor this collection and the number of pages available.
This chapter includes the following sections:
Using ^PROFILE
Invoke the (^PROFILE) utility from the %SYS namespace:
%SYS> do ^PROFILE
When you are prompted to start the collection of data, press Enter.
Note:
When you are prompted for a response (other than Yes or No) you can enter ? to display online help.
By default, the profile displays a numbered list of routines with the following metrics; initially, the list is sorted by the RtnLine metrics:
Column Title (Metric) Description
RtnLine
Number of routine lines of code executed. By default, it lists the value as a percentage of all lines of code executed.
Time
Elapsed time used to execute the routine. By default, the time is listed as a percentage of the total time used by all routines.
CPU
CPU time used to execute the routine. By default, the entry is listed as a percentage of the total CPU time used by all routines.
RtnLoad
Number of times the routine is loaded. By default, the entry is listed as a percentage of all routine loads.
GloRef
Number of global references by the routine. By default, the entry is listed as a percentage of global references by all routines.
GloSet
Number of global sets by the routine. By default, the entry is listed as a percentage of global sets by all routines.
The name of the routine (INT or MVI file) and the namespace where it is executing is displayed on the second line of the entry.
Follow the instructions that are displayed in the Terminal:
^PROFILE Example
Following is an example of running the ^PROFILE utility interactively (from the %SYS namespace) in the Terminal:
  1. Enter the following command:
    DO ^PROFILE
    
  2. The following message appears.
    This routine will start a system-wide collection of data
    on routine activity and then display the results. There
    may be some overhead associated with this collection,
    but it should not significantly impact the system.
     
    Are you ready to start the collection?  Yes =>
    
  3. Press Enter to start collecting metrics. Metrics similar to the following are displayed:
    Waiting for initial data collection ...
    
          RtnLine     Time        CPU         RtnLoad     GloRef      GloSet
    1.    38.02%      0.03%       10.49%      0.83%       0.05%       0.08%
          SYS.Database.1.INT (CACHESYS)
    2.    21.00%      0.08%       49.97%      0.12%       68.73%      7.55%
          DocBook.chapter.CLS (DOCBOOK)
    3.    19.68%      0.01%       11.55%      7.16%       28.17%      88.34%
          DocBook.para.CLS (DOCBOOK)
    4.    10.93%      0.00%       1.98%       19.64%      0.00%       0.00%
          %cspParser.INT (CACHELIB)
    5.    1.99%       0.00%       2.05%       5.14%       0.07%       0.00%
          DocBook.Renderer.CLS (DOCBOOK)
    6.    1.75%       0.00%       2.53%       22.46%      0.00%       0.00%
          %CSP.TokenStream.1.INT (CACHELIB)
    7.    1.05%       0.00%       1.50%       6.00%       0.69%       0.83%
          DocBook.listitem.CLS (DOCBOOK)
    8.    0.84%       0.00%       0.00%       0.01%       0.17%       0.78%
          PROFILE.INT (CACHESYS)
    9.    0.76%       0.00%       0.48%       7.91%       0.24%       0.88%
          %Library.GlobalCharacterStream.1.INT (CACHELIB)
    10.   0.47%       0.00%       0.48%       4.78%       0.12%       0.00%
          DocBook.block.CLS (DOCBOOK)
    11.   0.33%       0.00%       0.51%       1.22%       0.15%       0.13%
          Security.Resources.1.INT (CACHESYS)
    Select routine(s) or '?' for more options  N => 
    
  4. Flag the routines you want to analyze in more detail. For example, enter 2–3,5,7,10, then enter N or B to display other pages so that you can select additional routines.
  5. After you select all the routines you want to analyze, enter Q to display a message similar to the following:
    There are 5 routines selected for detailed profiling. You may now
    end the routine level collection and start a detailed profiler collection.
     
    WARNING !!
     
    This will have each process on the system gather subroutine level and line
    level activity on these routines. Note that this part of the collection may
    have a significant effect on performance and should only be run in a test
    or development instance of Cache.
     
    Are you ready to start the detailed collection?  Yes =>
    
  6. After you press Enter, a page similar to the following is displayed:
    Stopping the routine level Profile collection ...
     
    Loading ^DocBook.chapter.1 in c:\intersystems\cache\mgr\docbook\
    Loading ^DocBook.para.1 in c:\intersystems\cache\mgr\docbook\
    Loading ^DocBook.Renderer.1 in c:\intersystems\cache\mgr\docbook\
    Loading ^DocBook.listitem.1 in c:\intersystems\cache\mgr\docbook\
    Loading ^DocBook.block.1 in c:\intersystems\cache\mgr\docbook\
     
    Detail level Profile collection started.
     
        RtnLine     Routine Name  (Database)
    1.  0%          DocBook.Renderer.CLS (DOCBOOK)
    2.  0%          DocBook.block.CLS (DOCBOOK)
    3.  0%          DocBook.chapter.CLS (DOCBOOK)
    4.  0%          DocBook.para.CLS (DOCBOOK)
    5.  0%          DocBook.listitem.CLS (DOCBOOK)
     
    Select routine to see details or '?' for more options  R =>
    
  7. After you select the routine whose code you want to analyze, a page similar to the following is displayed:
    Line  RtnLine                 Code
    1.    0          ;DocBook.chapter.1
    2.    0          ;(C)InterSystems, generated for class DocBook.chapter.  Do NOT
    3.    0          ;;0032F4FE18715E65;DocBook.chapter
    4.    0          ;
    5.    0         %1Check(id="",lockonly=0) public {
    6.    0             Set exists=($select(id="":0,(+##class(DocBook.chapter).%OnDe
    7.    0         %AcquireLock(%this,locktype="") public {
    8.    0             Quit ..%LockId(($listget($zobjval(,0,,,,3))),$s($e(locktype)
    9.    0         %BMEBuilt(bmeName)
    10.   0             Set bmeName = "$chapter"
    11.   0             Quit ''$d(^DocBook.blockI("$chapter"))
    12.   0         %BindExport(%this,dev,Seen,RegisterOref,AllowedDepth,AllowedCapa
    13.   0             i $d(Seen(""_%this)) q 1
    14.   0             Set Seen(""_%this)=%this
    15.   0             s sc = 1
    16.   0             s proporef=$PROPERTY(%this,"book")
    17.   0             s proporef=$PROPERTY(%this,"component")
    18.   0             s proporef=$PROPERTY(%this,"container")
    19.   0             d:RegisterOref InitObjVar^%SYS.BINDSRV(%this)
    20.   0             i dev'="" s t=$io u dev i $s($P(dev,":",1)="|TRM|":$$debugPu
    21.   0             i AllowedDepth>0 s AllowedDepth = AllowedDepth - 1
     
    Routine DocBook.chapter.1 in DOCBOOK - '?' for options  N =>