Building a SAS Stored Process Log

This post was kindly contributed by BI Notes for SAS® Users - go there to comment and to read the full post.

As a SAS stored process developer, a question sometimes pokes its way into my head: “Are people using the stored processes I write?”  In fact, really I have four questions:

• What stored processes are being used? 
• Who is using them?
• When are they being used?
• How are they using them?

I realized what I’ve been missing.  I need a SAS stored process log.

If It Works for a Macro…

As a macro programmer learning to develop stored processes, I’ve been happy to find that many of the lessons I learned for macro development also apply in stored process land.  A few months ago I was browsing through user groups papers, and came across a  2012 WUSS paper by Richard Koopman, Jr on tracking the use of autocall macros.  He writes macros for a shared macro library, and in order to track who is using those macros (and how often each is being used) he adds some code to each macro definition so that every time the macro is invoked, it writes a record to a log data set.   And I thought “yep, that  approach should work nicely for stored processes too!”

The Approach

The key realization as I read Richard’s paper was that at the time a stored process runs, it has all the information I want for my log.  The name of the stored process (WHAT) and the name of the person who called the stored process (WHO) are available in macro variables.  The time the stored process executes (WHEN) is available via Peter Crawford’s %NOW macro.  The prompt values passed by a user (HOW)  are also available as macro variables.

So for my logging, all I need to do is add some code to a stored process definition so that every time a user runs the stored process it collects the data for the log into a one-record data set, and then PROC APPENDS that record to a permanent log data set.  And of course since I’m a macro programmer, I’ll wrap this all in a macro, so that in order to turn on logging for a stored process, I can just  add a call  to %InsertSTPLogRecord().

The Macro: %InsertSTPLogRecord

Here is the macro:

%macro InsertSTPLogRecord
  (mvar=  
  ,dir=/SomeLocation 
  )
;

%local locked idnum rc ;

libname __logdir "&dir";

%*Build the log record;
data __LogRecord;
  length 
    Program         $50
    MetaPath        $200
    MetaPerson      $50
    MetaUser        $50
    Mvar            $200
  ;

  Program=    "%scan(&_program,-1,/\)" ;
  MetaPath=   "&_Program" ;      
  RunDate=    %now(fmt=16.2) ;
  MetaPerson= "&_MetaPerson" ;
  MetaUser=   "&_MetaUser" ;
  Mvar=       "&mvar" ;

  format
    RunDate datetime20.
  ;
run;

%*If STPlog permanent data set exists, need to get a lock on it ;
%*(to avoid conflict of two stored processes trying to write to it at same time );
%if %sysfunc(exist(__logdir.STPlog)) %then %do ;
  %let idnum = %sysfunc(open(__logdir.STPlog)) ;

  %*if open succeeded, can now lock the dataset ;
  %if &idnum ne 0 %then %do ;
    lock __logdir.STPlog ;
    %let locked=1 ;
    %let rc = %sysfunc(close(&idnum)) ; 
  %end ;

  %*if open failed, someone else has it locked ;
  %else %if &idnum=0 %then %do ;
    %put INFO: Could not insert record into STPlog because file is locked by another user. ; 
    %put macro &sysmacroname aborting. ;
    %goto mexit ;
  %end;
%end;

proc append base=__logdir.STPlog data=__LogRecord ;
run ;

%if &locked=1 %then %do ;
  lock __logdir.STPlog clear ;
%end ; 

%mexit:
%*cleanup;
proc datasets library=work memtype=data nolist ;
  delete __LogRecord ;
quit ;
libname __logdir clear ;

%mend InsertSTPLogRecord;

The first step is to collect the log data into a temporary one record data set,  __LogRecord.  The name of the stored process and the metadata path of the stored process are read from &_Program.  The user information is read from &_MetaPerson and &_MetaUser.  These macro variables are created by the Stored Process Web Application when a stored process executes.  Other clients (Web Report Studio, Office Add-In, etc) may create different macro variables, so the macro may need to be adapted to support other clients.  The RunDate is obtained using %NOW.  The prompt values passed in from the user can be passed to the macro via the &Mvar parameter.

The second step is to append the log record to the permanent log data set.  In order to avoid a collision in which two stored processes try to write to the permanent log data set at the same time, I added some code to check if the permanent log data set is locked.  If it’s in use, it skips the logging.  It could would wait until the data set is available (a PharmaSUG paper by John Leveille and and Jimmy Hunnings illustrates a nifty approach to doing that using a macro %TryLock), but in this case I’d rather skip the logging than have logging slow down delivery of the main stored process results.

To turn on logging for a stored process, I just add a call to %InsertSTPLogRecord to the stored process source code, and pass it a list of the macro variables I would like to have included in the log record:

%InsertSTPLogRecord(mvar=data=&data _ODSdest=&_ODSdest)

The Output: Log Data Set

After adding %InsertSTPLogRecord to the stored process source code,  every time the stored process is called a record will be added to the permanent log data set.  If I were developing stored processes for a world-class psychology department, a PROC PRINT of the log data set might look like:

I can see that B.F. Skinner has been plotting data from his favorite pigeon, Rorschach has been generating more ink blot prototypes, and Freud is still looking for hidden meanings in everything.

The Report: Whatever You Want

Once you have a SAS data set of stored process log data, you can report on whatever you want.  I plan to write stored processes that will report on the usage of stored processes I have written (how meta!).  When I release a new stored process for a project, I will be able to easily see whether the project team is using it, and how they are using it.  This could help me identify gaps in my design, implementation, or dissemination  (if nobody ever uses a prompt, it could be because it is not needed, or is poorly implemented, or users don’t understand it).   Over time, I will be able to report on general trends in stored process usage (number of users, number of stored processes executed, etc),  categorized by project and/or department.  I look forward to walking into my next performance review (or next request for additional SAS infrastructure) with hard data on how the SAS tools we have developed are being used.

The Verdict: ???

Like many things I have posted on this blog, this falls into the category of “I think this is a good idea, but would love to hear feedback from folks.”  So I would welcome comments, suggestions, and yes, even (kind) criticism.

I think the idea of logging stored process usage and reporting on usage makes sense.  There are of course other ways to achieve this goal.  The stored process server itself creates the usual .log files.  Instead of having each stored process write records to the log data set in real time, you could set up a nightly job which parses the log files to extract similar information.   The SAS logging facility and the SAS Audit, Performance, and Measurement instrumentation package also allow enhanced logging and reporting (see this nifty GloFo 2013 paper by Edoardo Riva and Simon Williams for an overview).

But as a stored process developer (and not a SAS admin), this seemed like an easy way to start logging the usage of stored processes I write.   And as the data comes, and the analysis begins, I’m optimistic that  insights will follow.

Post Building a SAS Stored Process Log appeared first on BI Notes for SAS® Users. Go to BI Notes for SAS® Users to subscribe.

This post was kindly contributed by BI Notes for SAS® Users - go there to comment and to read the full post.