Using Performance Macros

When you use the performance macros, you do not need to define user metrics. There are default user metrics within the %PERFSTRT and %PERFSTOP macros. The default user metrics simplify performance tracking. To compare the features of performance macros and ARM macros, see Comparing the SAS 9.1 ARM Interface with the SAS 9.3 ARM Interface. There are four performance macros:

%PERFINIT

names the application instance and initializes the ARM interface. Typically, you insert this macro in your code once. See %PERFINIT Macro.

%PERFSTRT

specifies the start of an instance of a transaction. Insert the %PERFSTRT macro before each transaction that you want to log. See %PERFSTRT Macro.

%PERFSTOP

ends an instance of a transaction. Insert the %PERFSTOP macro where the transaction is known to be completed. See%PERFSTOP Macro.

%PERFEND

signals the termination of the application. See %PERFEND Macro.

The %PERFSTRT and %PERFSTOP macros contain default user metrics, which alleviates defining and adding user-metric definitions, types, and values to the macros.

The following program uses the performance macros:

%log4sas();
%log4sas_logger(Perf.ARM, 'level=info');
options armagent=log4sas;
options armsubsys=(arm_proc);
%let _armexec = 1;
%perfinit(appname="Perf_App");

%perfstrt(txnname="Perf_Tran_1");
  data x;
  do i=1 to 10000;
  x=i; y=0-i;
  output;
  end; run;

  proc sort  data=x threads; by y;  run;
%perfstop;

%perfstrt(txnname="Perf_Tran_2");
  data x;
  do i=1 to 10000;
  x=i; y=0-i;
  output;
  end;
  run;

 proc sort  data=x threads; by y;  run;
%perfstop;

%perfend;
run;

Here is the output to the SAS log:

39   %log4sas();
40   %log4sas_logger(Perf.ARM, 'level=info');
41   options armagent=log4sas;
42   options armsubsys=(arm_proc);
43   %let _armexec = 1;
44   %perfinit(appname="Perf_App");
NOTE: INIT Perf_App 13f01e0
I,1533752349.599000,3,2.093750,8.437500,Perf_App,userid
45
46   %perfstrt(txnname="Perf_Tran_1");
NOTE: REGISTER Perf_Tran_1
13f0438
      G,1533752349.599000,3,5,Perf_Tran_1,,_IOCOUNT_,Count64,_MEMCURR_,
      Gauge64,_MEMHIGH_,Gauge64,_THREADCURR_,Gauge32,_THREADHIGH_,
      Gauge32NOTE: START
Perf_Tran_1 13f0438 0
     
S,1533752349.599000,3,5,8,2.093750,8.437500,266202463,13754368,15114240,3,7
47     data x;
NOTE: START PROCEDURE 13ef148 0 S,1533752349.614000,1,2,9,2.125000,8.437500,
               DATASTEP,0,0,
48     do i=1 to 10000;
49     x=i; y=0-i;
50     output;
51     end; run;

NOTE: The data set WORK.X has 10000 observations and 3 variables.
NOTE: STOP PROCEDURE 13ef148 0
      P,1533752349.630000,1,2,9,2.125000,8.453125,0,DATASTEP,278854,164944,
NOTE: DATA statement used (Total process time):
      real time           0.01 seconds
      cpu time            0.01 seconds


52
53     proc sort  data=x threads; by y;  run;
NOTE: START PROCEDURE 13ef148 0 S,1533752349.630000,1,2,10,2.125000,8.453125,
                SORT    ,0,0,

NOTE: There were 10000 observations read from the data set WORK.X.
NOTE: The data set WORK.X has 10000 observations and 3 variables.
NOTE: STOP PROCEDURE 13ef148 0
P,1533752358.681000,1,2,10,2.171875,8.453125,0,SORT
      ,524967,1989360,
NOTE: PROCEDURE SORT used (Total process time):
      real time           9.05 seconds
      cpu time            0.04 seconds


54   %perfstop;
NOTE: STOP Perf_Tran_1 13f0438 0
     
P,1533752358.697000,3,5,8,2.171875,8.468750,0,267014988,13754368,15114240,3,7
5556  
%perfstrt(txnname="Perf_Tran_2");
NOTE: REGISTER Perf_Tran_2
13f0b68
      G,1533752358.697000,3,6,Perf_Tran_2,,_IOCOUNT_,Count64,_MEMCURR_,
     
Gauge64,_MEMHIGH_,Gauge64,_THREADCURR_,Gauge32,_THREADHIGH_,Gauge32
NOTE: START Perf_Tran_2 13f0b68 0
     
S,1533752358.697000,3,6,11,2.171875,8.468750,267019084,13754368,15114240,3,7
57     data x;
NOTE: START PROCEDURE 13ef148 0 S,1533752358.712000,1,2,12,2.187500,8.468750,
               DATASTEP,0,0,
58     do i=1 to 10000;
59     x=i; y=0-i;
60     output;
61     end;
62     run;

NOTE: The data set WORK.X has 10000 observations and 3 variables.
NOTE: STOP PROCEDURE 13ef148 0
      P,1533752358.728000,1,2,12,2.187500,8.484375,0,DATASTEP,278854,164944,
NOTE: DATA statement used (Total process time):
      real time           0.01 seconds
      cpu time            0.01 seconds


63
64    proc sort  data=x threads; by y;  run;
NOTE: START PROCEDURE 13ef148 0 S,1533752358.728000,1,2,13,2.187500,8.484375,
                SORT    ,0,0,

NOTE: There were 10000 observations read from the data set WORK.X.
NOTE: The data set WORK.X has 10000 observations and 3 variables.
NOTE: STOP PROCEDURE 13ef148 0
P,1533752358.822000,1,2,13,2.234375,8.484375,0,SORT
      ,524614,1989840,
NOTE: PROCEDURE SORT used (Total process time):
      real time           0.07 seconds
      cpu time            0.04 seconds


65   %perfstop;
NOTE: STOP Perf_Tran_2 13f0b68 0
     
P,1533752358.837000,3,6,11,2.250000,8.484375,0,267835352,13754368,15114240,3,7
66
67   %perfend;
NOTE: END Perf_App 13f01e0
E,1533752358.837000,3,2.250000,8.484375
68   run;