Simple SAS Performance Profiling Macros

As the old saying goes, the first rule of performance is to measure. My team is trying to tune the performance of a rather large SAS application, but it hasn’t been as easy as I thought it would be because profiling is too hard. Here’s what I understand about what SAS offers in the way of performance profiling (my focus is on CPU time):

First: SAS prints CPU time information to the SAS Log. For example:

17         data hello_world;
18           set temp.sampledata;
19         run;

NOTE: There were 42390 observations read from the data set TEMP.SAMPLEDATA.
NOTE: The data set WORK.HELLO_WORLD has 42390 observations and 37 variables.
NOTE: DATA statement used (Total process time):
      real time           0.04 seconds
      cpu time            0.03 seconds

This is simply too low-level to be useful because I am usually interested in understanding the performance of larger components rather than a single step. (Although once a problem has been narrowed down, it is very helpful to have this information produced automatically.)

Second: SAS also provides a LOGPARSE utility that parses logs to retrieve this information and put it in a more structured format. This is a bit better, but it still does not address the problem of understanding performance at a macro (component) level. I suppose this is due in part to the nature of SAS programming, which does not reduce to a call tree in the same way as many procedural languages do. It also does not address the very real problem of wanting to profile SAS Macro execution time, as well as including the time spent my external processes (such as callouts to system utilities or non-SAS components).

Third: for SCL (SAS Component Language) programs there is the SCL Performance Analyzer, which is helpful, but only if you happen to be writing SCL – which is not usually the case. Also the output of the analyzer is a little less than what I am used to.

I am not dissing SAS – I just think I am spoiled. I am not a SAS developer by background. The past decade or so I have been doing my primary development on the .Net Framework using various versions of Visual Studio. Several editions of Visual Studio 2012 include a performance analysis feature that makes it dead simple to profile .Net code. You can access it from the Debug menu:

image

A couple of clicks through a wizard, run your program, and you get all sorts of amazing information about the performance characteristics of the program:

image

It even highlights which lines took the most time:

image

It could hardly be much easier. Perhaps you can understand why I was so disappointed with SAS’s built-in tools.

I decided to be the change I want to see in the world and write a couple of simple, self-contained macros that I could use to profile SAS code. I am not a SAS expert (yet) so it’s likely that there are things that could be improved. Please help me out by posting your comments!

I wrote three macros: one to initialize the timing infrastructure, one to start timing a labeled code block, and one to stop. I have a few guidelines:

  • The macros are self-contained and small.
  • If profiling is disabled, the overhead is as close to zero as possible.
  • If profiling is enabled and the code blocks that are being timed are nontrivial, the overhead is small.
  • Arbitrary blocks of SAS/SAS Macro can be timed.
  • Timers can be nested.
  • Timing blocks can be given sensible names.
  • The results are reported in a SAS data set.

Here is an example of how to use the library. It times a small block of SAS named “hello”:

%timer_init(Y);
** … **;

%timer_start(hello);
data hello_world;
  set temp.sampledata;
run;
%timer_stop(hello);

The results are stored in a dataset called “_profile”:

Here is the source for the macros. “timer_init” takes a yes/no argument. If profiling is enabled, it creates a dataset called _tick. _tick holds the start times for all of the active timers.

************************************************************;
** timer_init(profilingEnabled): initialize timers.       **;
**   profilingEnabled: Y means profiling is on.           **;
************************************************************;
%macro timer_init(profilingEnabled);
  %global timerEnabled;
  %let timerEnabled=&profilingEnabled;
  %if &timerEnabled=Y %then %do;
  data _tick;
    root = datetime();
  run;
  %end;
%mend;

“timer_start” starts a new timer with the specified name. We rely on the datetime() method, which determines the timer resolution. Starting a new timer just means sticking a new variable in _tick.

************************************************************;
** timer_start(desc): start timing a code block.          **;
**   desc: a description of the block.                    **;
************************************************************;

%macro timer_start(label);
  %if &timerEnabled=Y %then %do;
  data _tick;
    set _tick;
    &label = datetime();
  run;
  %end;
%mend;

“timer_start” stops a timer. It’s slightly more complicated than you might think because I want to allow for the possibility of the same block being timed more than once, for example if it appears inside a SAS Macro %for loop. I suspect a better SAS programmer could simplify this code.

************************************************************;
** timer_stop(desc): stop timing a code block.            **;
**   desc: a description of the block.                    **;
************************************************************;

%macro timer_stop(label);
  %if &timerEnabled=Y %then %do;
  data _tick;
    set _tick;
    _now = datetime();
    _duration = _now – &label;
    &label = _now;
    call symputx(‘_duration’, _duration);
    drop _now _duration;
  run;

  %if %sysfunc(exist(_profile)) %then %do;
    data _profile;
      set _profile;
      &label = sum(&label,0) + input(&_duration, best20.);
    run;
  %end;
  %else %do;
    data _profile;
      &label = input(&_duration, best20.);
    run;
  %end;
  %end;
%mend;

Enjoy!

Author: natebrix

Follow me on twitter at @natebrix.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s