Building a SAS Stored Process Log

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

%local locked idnum rc ;

libname __logdir "&dir";

%*Build the log record;
data __LogRecord;
    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" ;

    RunDate datetime20.

%*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 ;

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

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

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:

STPLogI 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.

Never miss a BI Notes post!

Click here for free subscription. Once you subscribe you'll be asked to confirm your subscription through your email account. You email address is kept private and you can unsubscribe anytime.

Learn More about SAS Stored Processes and Prompts

You can learn more tips and tricks for creating, debugging, and using SAS stored processes in the 50 Keys to Learning SAS Stored Processes book. It's a complete guide to SAS stored processes. Check Amazon for best pricing and quick shipping!

9 thoughts on “Building a SAS Stored Process Log

  1. This entire thread makes me think of a recent meeting at a customer site. The system administrator said “I’ve learned there is not one best approach. There’s a way that works for the current issue at hand.” It was a true statement.

    I have to agree with Quentin – I have worked in a HUGE enterprise where asking IT to do often took forever – if they were even willing to do. Maybe it’s not so much about would they do … but would they have time or inclination? Many times IT doesn’t understand the SAS system well and take the approach – “it’s not broke so I’m not touching it.”

    If you want some quick statistics – this is an alternate method until you can talk some sense into IT. It’s not long term solution – its the best approach for the current issue at hand.

  2. Quentin, You noted the best argument you could bring.
    That is: as a “proof-of-concept” of the benefits of logging.

    There is a need for a sponsor IT-manager supporting those logging monitoring.
    As all can be seen as a “cost-factor”, the HR-vision to operations is sometimes experimented by reducing, until they get escalations of things going very wrong.

    Being pro-active is preventing those escalations. Smooth running is being not visible, escalations makes you visible promoting your
    name. Contradictions…

  3. Thanks @Jaap,
    Always enjoy your detailed and referenced comments. Makes sense that from an admin perspective, it’s a bit silly to have every developer designing (and executing) their own logging. However, not everyone is lucky enough to have a full-time admin with the resources to explore all that SAS has to offer. If only as a “proof-of-concept” of the benefits of logging, I think this approach is defensible. And perhaps after assessing the benefits of logging my own stored processes, that would help make the case for turning on more logging at the server level. On the other hand, there is some benefit to being able to choose which stored processes are worth logging, rather than turning on extensive logging for everything at the server level. Interesting TS note on the INITSTMT.

  4. Thanks @Ronan,
    The asynchronous method you suggest is actually similar to the method described in Richard Koopman’s paper which inspired this post. Each user had their own log file, then he had a nightly job (or a job that ran when the user started SAS?) which gathered records from the user logs and added them to his main log. For this “quck-and-dirty” first attempt, it seemed easiest to me just to write the records in real time. But I’m sure in time I may change approaches.

  5. When necessary you need modifications in the usermod-files of a App-server. This part is not the best documented one.
    These tasks are assigned to the Platform Admin. As you already need him…
    Why not let him deliver the reports you need. The BI/DI environment is set up with a lot of options to do that.
    The APM will become regular as Environmentmanger (9.4) Logging is also available this way in 9.3
    This is based on the logconfig.xml files found in the appserver config-directories. (java/arm based)

    Performance is coming back at the same areas

    I would not use initstmt termstmt as are problematic in a bi/di server approach.
    They are activated again for IOM servers with 9.3 (not working with older 9 versions bi/di server)

    All is Platform admin-s work related.

    At SAS 9.3 SP’s can run by a WS or SP server and by different tools Web-based and eg Eguide/Amo.
    When the whole environment is operating using a single key, group account (high priviledged), you could get you program working.
    This is involving a security pit-fall like the famous SQL-injection would call it SAS-code injection.
    You need to choose the SAS usage goal. Either to compete with the LAMP stack (fixed well tested programs) or BI/Analytics with more code freedom for the users requiring better designed security isolations.

    = It is the same kind of segregation with HR-functionality as seen many times before
    = It is the same kind of resistance to accept it that change.
    When the choice ha been made the logging monitoring etc. is a platform admin role….. tools are delivered for them then:
    why would you ignore that, even overruling, by trying to build that yourself?
    Nice to see even obstinate admins can be convinced, can be hard work as it has always been that way.

  6. Hi Quentin,

    This is very funny, psychologically speaking ;-). Thanks for the useful tips. A few disorderly remarks :

    – to get rid of this locking issue, you could also build a two-step process with each STP leaving a single trace log using name fields (eg : a blank file at initialization named “___etc.log”) then scheduling a small parsing code to gather the informations from the log files. Asynchronous processes are sometimes easier to code, albeit harder to design or specify. You can even obfuscate the sensitive fields (User Name) using Base64 encoding.

    – I agree with Don : using INITSTMT and/or TERMSTMT options at the STP Server level is good idea, less intrusive.

    – another approach would be to use the Log4SAS API at the STP Server level (“logconfig.xml”) . Perhaps it could trace the session information specifically to build a small log file for each user session or even a complete log file with the relevant information one line at a time. Then reading/parsing this log comes easily. Just guessing, I’ve not checked with the technical doc.


  7. Thx Quentin.

    And I am also rarely the SAS admin on my client projects. But FWIW I have never had a problem getting an admin to set up the init and term programs (and, yes, I am worked with countably infinite obstinate admins).

    What I tell them is that the init and term programs are a nice way to reset things if they need to without have to bounce the servers (e.g., re-issue a libname for an external database).

    And once they have set that up, it is easy to get them to add simple things to those programs. You have to be careful however to not do too much processing in them.

  8. Thanks Don,
    Glad the idea makes sense.

    Like your suggestion to put this in the server-level init/term programs instead of individual source code for each stored process.

    Since I’m not an admin, I couldn’t do that myself. But I do have an autocall macro %Setup() that I basically use like an INIT routine. And probably should have a %Term() to run my own standard termination routine (log parsing, writing the log data record, etc…) So I could put a call to %InsertSTPLogRecord inside the definition of %Term().

  9. The SAS/IntrNet Application Dispatcher has had a configurable statistics option for several years now that can collect such data. Don’t understand why the same feature has not been added to the stored process server.

    This is a good idea, but a much better approach IMO is to take advantage of the stored process server request init and term programs to capture this data. The name of the stored process and all if its parameters are known when the request init program is run and so it can capture whatever information you want and post it to a data set. And if you want timing information, you can capture the start time, and then in the term program, capture and save the end time.

    The advantage of using the init/term approach is that it captures data about all the stored processes and there is no need for any of the individual stored process programs or macros to do anything special/extra.

Comments are closed.