Previous section   Next section

Monitoring Routine Performance Using ^PROFILE

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:
  • When the list of routines is displayed at the profile level, you can specify any of the following:
    Option Description
    #
    Flag the specified line(s) for detailed profile-level data collection.
    Note:
    On each displayed page, you can enter single line numbers (#), a comma-separated list (#,#,#), a range (#-#), or a combination (#-#,#,#-#,#).
    After you select the routines on any page, you can move to the next or previous page to select other routines. After you select all the routines you want to analyze, enter Q to start the detail level profile collection.
    B
    Display the previous page of the list.
    E
    Export the displayed collection of metrics.
    N
    Display the next page of the list.
    O
    Re-sort the page based on different metrics (the selected metric is displayed in the first column).
    Q
    Exit from the ^PROFILE utility.
    Note:
    If you flagged routines that you want to analyze, this option lets you choose between collecting subroutine- and line-level metrics or exiting.
    R
    Refresh the list with the most recent metrics.
    X
    Clear all flags of selected routines (including those selected on other pages) and refresh the collection of metrics.
  • When the list of routines is displayed at the detailed profiling level, you can specify any of the following:
    Option Description
    #
    The line number of the routine you want to analyze in more detail. After you press Enter, the subroutine labels in then selected routine is displayed.
    B
    Display the previous page of the list.
    N
    Display the next page of the list.
    O
    Re-sort the page based on different metrics (the selected metric is displayed in the first column).
    Q
    Exit from the ^PROFILE utility.
    R
    Refresh the list with the most recent metrics.
  • When the list of subroutine labels (and metrics for each label) are displayed, you can specify any of the following:
    Option Description
    #
    The line number of the subroutine label (in the code) you want to analyze in more detail. After you press Enter, the code for the specified label is displayed.
    B
    Display the previous page of the list.
    L
    Switch to the line level display of the subroutine.
    N
    Display the next page of the list.
    Q
    Exit the list, return to the previous level.
    R
    Refresh the list with the most recent metrics.
    Note:
    If
    *Unknown*
    is displayed in the listing, enter R.
  • When lines of code are displayed, you are prompted to specify what you want to do next. Your options are:
    Option Description
    #
    The line number in the code you want to analyze in more detail. After you press Enter, the code for the specified label is displayed.
    B
    Display the previous page of the list.
    C
    Switch code display between source code and intermediate (INT/MVI) code.
    M
    Change the page margin and length.
    N
    Display the next page of the list.
    O
    Re-sort the page based on different metrics.
    Q
    Exit the list, returning to the previous level.
    R
    Refresh the list with the most recent metrics.
    S
    Switch to the subroutine level display of the routine.

^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 =>
    
    
Previous section   Next section