Compilation time for compiling autocall macros

[Quentin]

Hi,

Guess I haven't thought much in the past about the amount of real time needed to compile autocall macros.  I'm working on a SAS/AF program (yes, really : ), which runs slowly the first time, but much faster the second time.  And it hit me that a good chunk of the difference could be macro compilation time, though I haven't fully tested it yet.

Below is a log from playing around a bit.  It uses Peter Crawford's macro one-liner %NOW().  It looks to me like it takes between .5 seconds and 1 second to compile a one-liner.  I thought I would blame slow network (my autocall directory is on a remote server), but when I moved the macro source code to my local drive, it still took .25 seconds to compile.  Does this seem typical?  Is there a better way for me to track this time?

I've never been tempted to use a pre-compiled macro library, but I guess this might point me in that direction.  (Reaching for Carpenter's guide....)

Kind Regards,

--Q.

1    options fullstimer mprint mcompilenote=all mautolocdisplay;
2
3    options  sasautos=(sasautos);
4
5    *Initial use- compile from network drive;
6    data _null_;
7      now=%__now();
NOTE: The macro __NOW completed compilation without errors.
      9 instructions 216 bytes.
MAUTOLOCDISPLAY(__NOW):  This macro was compiled from the autocall file
                         Q:\...\__now.sas
MPRINT(__NOW):  01/05/2015
8    run;

NOTE: DATA statement used (Total process time):
      real time           1.03 seconds
      user cpu time       0.01 seconds
      system cpu time     0.03 seconds
      memory              317.02k
      OS Memory           4720.00k
      Timestamp           01/05/2015 02:35:20 PM


9
10   *already compiled;
11   data _null_;
12     now=%__now();
MAUTOLOCDISPLAY(__NOW):  This macro was compiled from the autocall file
                         Q:\...\__now.sas
MPRINT(__NOW):  01/05/2015
13   run;

NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      user cpu time       0.00 seconds
      system cpu time     0.00 seconds
      memory              151.22k
      OS Memory           4720.00k
      Timestamp           01/05/2015 02:35:20 PM


14
15   %sysmacdelete __now;
16
17   *Compile again from network drive;
18   data _null_;
19     now=%__now();
NOTE: The macro __NOW completed compilation without errors.
      9 instructions 216 bytes.
MAUTOLOCDISPLAY(__NOW):  This macro was compiled from the autocall file
                         Q:\...\__now.sas
MPRINT(__NOW):  01/05/2015
20   run;

NOTE: DATA statement used (Total process time):
      real time           0.48 seconds
      user cpu time       0.03 seconds
      system cpu time     0.03 seconds
      memory              199.40k
      OS Memory           4720.00k
      Timestamp           01/05/2015 02:35:21 PM


21
22   *already compiled;
23   data _null_;
24     now=%__now();
MAUTOLOCDISPLAY(__NOW):  This macro was compiled from the autocall file
                         Q:\...\__now.sas
MPRINT(__NOW):  01/05/2015
25   run;

NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      user cpu time       0.00 seconds
      system cpu time     0.00 seconds
      memory              151.22k
      OS Memory           4720.00k
      Timestamp           01/05/2015 02:35:21 PM


26
27   %sysmacdelete __now;
28
29   options  sasautos=('d:\junk' sasautos);
30
31   *Compile again from local drive;
32   data _null_;
33     now=%__now();
NOTE: The macro __NOW completed compilation without errors.
      9 instructions 216 bytes.
MAUTOLOCDISPLAY(__NOW):  This macro was compiled from the autocall file d:\junk\__now.sas
MPRINT(__NOW):  01/05/2015
34   run;

NOTE: DATA statement used (Total process time):
      real time           0.25 seconds
      user cpu time       0.00 seconds
      system cpu time     0.01 seconds
      memory              151.22k
      OS Memory           4720.00k
      Timestamp           01/05/2015 02:35:21 PM


35
36   *already compiled;
37   data _null_;
38     now=%__now();
MAUTOLOCDISPLAY(__NOW):  This macro was compiled from the autocall file d:\junk\__now.sas
MPRINT(__NOW):  01/05/2015
39   run;

NOTE: DATA statement used (Total process time):
      real time           0.01 seconds
      user cpu time       0.01 seconds
      system cpu time     0.00 seconds
      memory              151.22k
      OS Memory           4720.00k
      Timestamp           01/05/2015 02:35:21 PM

[data_null__]

To me this seem closer to measuring the compile time part of an auto called macro.

%let t1=%sysfunc(datetime(),32.3);
%include 'path-to-macro.sas';
%let t2=%sysfunc(datetime(),32.3);
%put NOTE: %sysevalf(&t2-&t1);

[Quentin]

Thanks _null_,

Makes sense.  But I'm still surprised (perhaps chasing ghosts).

Looks to me like I pay quite a price the first time I compile a macro.  Though perhaps it's only paid the first time I compile *a* macro.  Will have to play more with this, and perhaps just sprinkle some of your timing macros through my code to see where the time goes... : )

NOTE: Compile from network: 1.10
NOTE: Compile from network: 0.57
NOTE: Include from network: 0.48

NOTE: Compile from local:   0.32
NOTE: Compile from local:   0.01
NOTE: Include from local:   0



841   options fullstimer mprint mcompilenote=all mautolocdisplay;
842
843   options  sasautos=(sasautos);
844   %sysmacdelete __now /nowarn;
845   %let t1=%sysfunc(datetime(),32.3);
846   %put %__now();
NOTE: The macro __NOW completed compilation without errors.
      9 instructions 216 bytes.
MAUTOLOCDISPLAY(__NOW):  This macro was compiled from the autocall file
                         Q:\...\SASmacros\__now.sas
01/05/2015
847   %let t2=%sysfunc(datetime(),32.3);
848   %put NOTE: Compile from network: %sysevalf(&t2-&t1);
NOTE: Compile from network: 1.10700011253356
849
850   %sysmacdelete __now /nowarn;
851   %let t1=%sysfunc(datetime(),32.3);
852   %put %__now();
NOTE: The macro __NOW completed compilation without errors.
      9 instructions 216 bytes.
MAUTOLOCDISPLAY(__NOW):  This macro was compiled from the autocall file
                         Q:\...\SASmacros\__now.sas
01/05/2015
853   %let t2=%sysfunc(datetime(),32.3);
854   %put NOTE: Compile from network:  %sysevalf(&t2-&t1);
NOTE: Compile from network:  0.57799983024597
855
856   *Include from network drive;
857   %let t1=%sysfunc(datetime(),32.3);
858   %include "Q:\..\SASmacros\__now.sas";
NOTE: The macro __NOW completed compilation without errors.
      9 instructions 216 bytes.
865   %let t2=%sysfunc(datetime(),32.3);
866   %put NOTE: Include from network: %sysevalf(&t2-&t1);
NOTE: Include from network: 0.48300004005432
867
868
869   options  sasautos=('d:\junk' sasautos);
870   %sysmacdelete __now;
871   %let t1=%sysfunc(datetime(),32.3);
872   %put %__now();
NOTE: The macro __NOW completed compilation without errors.
      9 instructions 216 bytes.
MAUTOLOCDISPLAY(__NOW):  This macro was compiled from the autocall file d:\junk\__now.sas
01/05/2015
873   %let t2=%sysfunc(datetime(),32.3);
874   %put NOTE: Compile from local: %sysevalf(&t2-&t1);
NOTE: Compile from local: 0.32699990272521
875
876   %sysmacdelete __now;
877   %let t1=%sysfunc(datetime(),32.3);
878   %put %__now();
NOTE: The macro __NOW completed compilation without errors.
      9 instructions 216 bytes.
MAUTOLOCDISPLAY(__NOW):  This macro was compiled from the autocall file d:\junk\__now.sas
01/05/2015
879   %let t2=%sysfunc(datetime(),32.3);
880   %put NOTE: Compile from local: %sysevalf(&t2-&t1);
NOTE: Compile from local: 0.01600003242492
881
882   *Include from local;
883   %let t1=%sysfunc(datetime(),32.3);
884   %include "d:\junk\__now.sas";
NOTE: The macro __NOW completed compilation without errors.
      9 instructions 216 bytes.
891   %let t2=%sysfunc(datetime(),32.3);
892   %put NOTE: Include from local: %sysevalf(&t2-&t1);
NOTE: Include from local: 0

[Tom]

What is that you are trying to test?

To "auto" compile it will need to:

1. check if the macro already exists.
2. If not it will need to check you SASAUTOS settings (and other settings that effect autocall).
3. Then it will need to generate a filename to look for.
4. Look for that file across the potentially multiple directories covered by your SASAUTOS settings.
5. Then it can include the file.
6. Then it can execute the macro.

If you compare it to just compiling the macro in line then you can eliminate steps 2 , 3 and 4.  And step 5 will be much faster since you have already read the program file into memory.

If you compare it to including a file with the source code then it can skip steps then it can skip steps 2 and 3.  Plus the compiled macro will most likely already exist in buffers so you get to skip other I/O that might have to happen at step 6.

[Quentin]

Thanks Tom,

Good points.

Basically, I'm trying to get a rough sense of some of the real-time efficiencies of using autocall macros.  Haven't thought about this much before, because when I was doing data management / analytic stuff for me, a few seconds here or there when running a batch job never mattered much. But now that I'm doing more web BI stuff, the seconds matter.  And same with this case, where it's a local AF app.

Just to play a little bit more, I did some quick testing where the test code looked like:

%let t1=%sysfunc(datetime(),32.3);
%SomeMacro()

And the autocall macro file (SomeMacro.sas) looks like:

%macro SomeMacro(debug=);
  %put macro SomeMacroRan ran;
%mend;
%let t2=%sysfunc(datetime(),32.3);
%put Compile Time:%sysevalf(&t2-&t1);

So I think then when I batch submit my test code, the compile time shown on log should be close to what I want.  Includes steps 1-5 of your list.  I also compared those times to using %include instead of autocall.

What I see is:

• Seems to be some overhead the first time an autocall macro is called (vs using %include),   <.5 seconds.  After first call, I don't see much difference.
• Obviously by storing my .sas files on a network drive far away, I can slow down everything (autocall and include).

Thanks again,

--Q.

[Tom]

Probably for a web server process you would just want to pre-compile the macros when a new server process is started.  You could also look into storing the compiled macros into a catalog.  But you also might want to have it copy the catalog to WORK when the server starts because I bet that the disk used for SASWORK will be faster than that used to store your SAS code and catalog files.

[FriedEgg]

This is the typical scheme I have followed as well.  Along with copying any format libraries, etc... that my process may need.

[Quentin]

Thanks and @Tom

Can you say a little more about how you do this in the web setting?

For example, suppose I'm using BI stored processes running on a stored process server.

I have reports (stored processes) for multiple projects on the same server.  Each project has project-specific autocall macros, formats, templates, etc, that are shared across its stored processes.

1. One option (least efficient) would be to have each stored process compile everything every time it is called.  So use a project-specific autocall macro library, and have project specific proc format code and proc template code that gets executed (%included) at the beginning of a stored process.

2. Another option would be to pre-compile everything and store compiled catalogs in a permanent location that is accessible.  Then the stored process starts by pointing sasautos, fmt search, and ODS path to these locations.  So that saves compiling time.

3. Are you saying I should consider a third option, that is stored compiled versions of everything in a permanent location as in (#2) and then in start of stored process copy (using proc catalog, or OS commands?) from those perm locations to WORK, so that they will be accessible more quickly?  Seems like for that to be of benefit, the permanent location would have to be somewhere really slow (in my original question in the AF setting, it was really slow because going across network, in the BI setting, won't have that delay).

But perhaps the key point is that Tom says copy to WORK *when the server starts*.  I guess for macros/formats/templates that are server-specific (i.e. wanted to be available to all stored processes that run on the server), this makes sense.  Because by the time an individual stored process starts it would already have everything in work.  But in the case where I have project-specific catalogs, would you think it is still worth copying them to WORK?

Obviously this is all testable, but curious as to the general approach that you've see work best.

Thanks,

--Q.

[FriedEgg]

Option One I would say is what is most typical to see and most often efficient enough.

When it comes to options 2 and 3 it really depends on the sites specific environment.  I have dealt with situations where a company had servers spread through several data-centers around the globe.  Everything was developed and maintained from a single location.  Macros/Formats/Catalogs/Templates/Etc were kept in source control and when a release was made it would be checked out, compiled and distributed to the storage areas at each of the data centers.  When a stored process was ran it would use the copies available on the closest shared storage.  This is like your option 2.  Everything was very well orchestrated and controlled.  At a different company that was much less strict option 3 made more sense because it kept the compiled sources more secure as someone very well may have written a stored process that overwrote one of the stored items and break everything...

As for implementation, there are many options, as with anything else.  You may choose to look at setting the request or session initialization program property on the stored process.  This can be done in the Management Console.

[Quentin]

Thanks again Matt,

Makes me feel better about using option #1 almost exclusively up until this point. : )

Really what I need to do is sit down with some of my slower stuff and start doing some efficiency analysis  to see where the time goes, and work back from there.  If a stored process takes 10 seconds to return results and 5 seconds of that is  SGRENDER generating a whole bunch of images, and 3 seconds is the images being transferred from web server on other side of globe back to user's browser, then I need to spend time on optimizing that rather than worry about time it took to compile my macros and formats.

That said, appreciate your thoughts on this.

[FriedEgg]

In most of my experiences even 5 seconds would be substantially too long, but obviously it depends what you're doing.  In the examples I gave you we were usually fighting for saving milliseconds.  An acceptable turn around would be 1 second, maybe 1.5 for something relatively large and typically we were returning 'far' under 1 second.

[Quentin]

Yeah, understood.  I'm working on a "please wait" message for my longest running stored processes.  : )

Most of these are where a single stored process makes some big report (e.g. returns PDF file with 100s of charts) or something like that.  Recognize it's not the typical web thing to do...  It's not really a true web app where folks are clicking around a lot.  It's just a little web UI to build a complete report.  And if they want a big report, it takes more time...

That said, if using GTL to make even a single chart returning to ODS HTML/PDF, not sure you could get results returned in milliseconds (but I haven't tried too hard).

, my 5 second example wasn't 5 seconds for macro compilation. Was trying to make the same point you do, that in the grand scheme, cost of macro compilation time should be small, except when there are network issues as you describe.

[FriedEgg]

Like I said, it depends what you're doing.  I certainly wouldn't expect something like a PDF with 100s of charts to complete so fast, but it's not something I would really expect from a web-based application.  In my experience, however, you are not alone in doing things like this either and I'm sure there are points where it makes sense.

I am certain that you can build charts using GTL and have results return in milliseconds (a few hundred of them, probably).  Take this usage note, for example:

54314 - Customize your symbols with the SYMBOLCHAR statement in the Graph Template Language (GTL)

It produces the following chart in 0.46 seconds on a very junky VM...  But, I digress.

If you need any guidance with your 'please wait' screen you should look into PROC STREAM, and I believe the following page at sascommunity.org even has an example for you.

PROC STREAM and SAS Server Pages: Generating Custom User Interfaces - sasCommunity

[Quentin]

Yeah, PDFs with 100s of charts is an extreme example.  But I have plenty of STPs that users typically generate 4-10 charts with a single submission, then scroll through the html file.

When I said I would be surprised if GTL could return a serious graph in miliseconds, I was meaning <.01 seconds.  On our stored process server and workspaces server, I typically see SGRENDER steps complete in .3-.5 seconds.  I'd describe that as "sub-second", but not "in miliseconds."   At that rate, if a user runs a STP that makes 10 charts they can easily end up waiting several seconds to see a result.

Funny that you would reference Don Henderson's SAS Server Page stuff.  I'm not quite doing that, yet, but I'm playing with a PleaseWait approach based on his javascript macro also posted on sascommunity.org:

http://www.sascommunity.org/wiki/Generating_Descriptive_Please_Wait_Messages_for_Long_Running_Stored...

Cheers!

[FriedEgg]

Indeed, sub-second is the more appropriate term there.

The only place to go from there is to run the SGRENDERs in parallel and then replay the output to put them together.  Depending on the situation, you could end up saving large amounts of wall time.

The concepts in these two 'please wait' schemes are both good, I prefer the custom form style (since I tend to use them anyway), which can be done with the PROC STREAM, as the link I posted, or without.  For certain long running processes where I wanted 'live' feedback from the STP I would send the information to the browser using Application Messaging, such as ActiveMQ.  SAS introduces a lot of very nice options to support this in 9.4, way less of a headache than how I had done it previously: using custom built java classes and the javaobj in 9.2 or PROC GROOVY in 9.3.