Example: ARM Performance Macros

The following example code writes output to the SAS log. The application name is Perf_App. There are two transactions, Perf_Tran_1 and Perf_Tran_2. The performance macros are highlighted within the code.

%log4sas();
%log4sas_logger(Perf.ARM, 'level=info');
options armagent=log4sas;
%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;

The following is the SAS log output for the example code. Note the performance macros that were highlighted in the example code.

SAS Log

1    %log4sas();
2    %log4sas_logger(Perf.ARM, 'level=info');
3    options armagent=log4sas;
NOTE: INIT SAS 13eec00 I,1533837807.104000,1,0.468750,2.437500,SAS,
NOTE: REGISTER SAS 13eee58 G,1533837807.386000,1,1,SAS,MVA SAS session
NOTE: START SAS 13eee58 0 S,1533837807.386000,1,1,1,0.468750,2.437500
4    %let _armexec = 1;
5    %perfinit(appname="Perf_App");
NOTE: INIT Perf_App 13efa30
I,1533837840.315000,2,0.500000,2.484375,Perf_App,userID
6
7    %perfstrt(txnname="Perf_Tran_1");
NOTE: REGISTER Perf_Tran_1 13efc88
      G,1533837840.487000,2,2,Perf_Tran_1,,_IOCOUNT_,Count64,_MEMCURR_,
      Gauge64,_MEMHIGH_,Gauge64, THREADCURR_,Gauge32,_THREADHIGH_,Gauge32
NOTE: START Perf_Tran_1 13efc88
0
     
S,1533837840.487000,2,2,2,0.515625,2.500000,68346709,5095424,5095424,3,3
8      data x;
9      do i=1 to 10000;
10     x=i; y=0-i;
11     output;
12     end; run;

NOTE: The data set WORK.X has 10000 observations and 3 variables.
NOTE: DATA statement used (Total process time):
      real time           5.67 seconds
      cpu time            0.17 seconds


13
14     proc sort  data=x threads; by y;  run;

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: PROCEDURE SORT used (Total process time):
      real time           3.78 seconds
      cpu time            0.14 seconds


15   %perfstop;
NOTE: STOP Perf_Tran_1 13efc88 0
     
P,1533837851.224000,2,2,2,0.562500,2.812500,0,79383442,6144000,7606272,3,7
16
17   %perfstrt(txnname="Perf_Tran_2");
NOTE: REGISTER Perf_Tran_2 13f0338
      G,1533837851.239000,2,3,Perf_Tran_2,,_IOCOUNT_,Count64,_MEMCURR_,
      Gauge64,_MEMHIGH_,Gauge64,_THREADCURR_,Gauge32,_THREADHIGH_,
      Gauge32
NOTE: START Perf_Tran_2 13f0338
0
     
S,1533837851.239000,2,3,3,0.578125,2.812500,79395730,6144000,7606272,3,7
18     data x;
19     do i=1 to 10000;
20     x=i; y=0-i;
21     output;
22     end; run;

NOTE: The data set WORK.X has 10000 observations and 3 variables.
NOTE: DATA statement used (Total process time):
      real time           0.01 seconds
      cpu time            0.01 seconds


23     proc sort  data=x threads; by y;  run;

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: PROCEDURE SORT used (Total process time):
      real time           0.09 seconds
      cpu time            0.04 seconds


24   %perfstop;
NOTE: STOP Perf_Tran_2 13f0338 0
     
P,1533837851.364000,2,3,3,0.625000,2.843750,0,80203806,6144000,7606272,3,7
25
26   %perfend;
NOTE: END Perf_App 13efa30
E,1533837851.458000,2,0.625000,2.859375
27   run;