The SAS Output Delivery System and reporting techniques

reporting step runtimes

Reply
N/A
Posts: 0

reporting step runtimes

I was using the step runtimes in the SAS log with some confidence, before ODS started to have an effect. It is easy to notice the time between the reporting of the end-of-step NOTE:s and the point when the "ODS .... close" appears.
I guess the memory usage for rendering ODS to it's relevant destinations also consumes memory and other system resources that are not reported.
If anyone else is interested in this information, please can normal (platform dependent) reporting of time, memory etc, be implemented for the impact of ODS.

Peter
SAS Employee
Posts: 174

Re: reporting step runtimes

Posted in reply to deleted_user
What about closing all ODS destinations, e.g.
[pre]
ods _all_ close;
[/pre]
and comparing the results to running your jobs with the destinations active?

Closing destinations doesn't completely eliminate ODS from procedure and DATA step execution, but it does eliminate the rendering of output.

-- David Kelley, SAS
N/A
Posts: 0

Re: reporting step runtimes

Posted in reply to David_SAS
thank you David

I want ODS to render its output. I don't want to eliminate it.
With your proposal (closing all ODS destinations) proc tabulate runs very quickly, but delivers no results and, for proc tabulate the internal logic is different when ODS is delivering only to the Listing destination.

While watching the saslog when proc tabulate runs, I noticed that the proc step message, like [pre]NOTE: PROCEDURE TABULATE used (Total process time):
real time 1.12 seconds
user cpu time 0.32 seconds
system cpu time 0.04 seconds
Memory 7436k [/pre]appears some time before the following statement

177 ods _all_ close ;

I imagined that between these messages appearing, the ODS is being rendered, and assume that the "real time" reported for the "step" cannot include the time for "rendering".
It is not difficult to measure the "rendering" time. However, it means I have to add that measurement into sas programs where I want to measure performance. (Perhaps that would be similar to adding ARM macros).

It is when using the new excelXP tagset, that I noticed the rendering time most. Here is a clip from a sas log.[pre]166 option fullstimer;
167 ods _all_ close ;
168 ods tagsets.excelxp file="demo_2.xls" ;
NOTE: Writing TAGSETS.EXCELXP Body file: demo_2.xls
NOTE: This is the Excel XP tagset (SAS 9.1.3, v1.37, 05/31/06). Add options(doc='help') to the ods statement
for more information.
169 %put %sysfunc( time(), time11.2);
13:06:10.37
170 proc tabulate missing format= comma7. data= forcedl.forced_dec06 ;
171 class prdid ;
172 format prdid best4. ;
173 var exposure ;
174 table (prdid all), exposure*(n mean) ;
175 run;

NOTE: There were 65055 observations read from the data set FORCEDL.FORCED_DEC06.
NOTE: PROCEDURE TABULATE used (Total process time):
real time 1.31 seconds
user cpu time 0.51 seconds
system cpu time 0.04 seconds
Memory 7435k

176 %put %sysfunc( time(), time11.2);
13:06:11.81
177 ods _all_ close ;
178 %put %sysfunc( time(), time11.2);
13:06:14.68[/pre]
If others are interested in having procedure step-timings (real time and cpu time) include the time for ODS rendering, then I think there might be value in having some change.

I would be very happy with alternatives, like having ODS report the time that "ods ... close" has taken. (perhaps as an optional extra, a bit like the sastrace options or the proc sql option stimer ).

Peter
SAS Employee
Posts: 174

Re: reporting step runtimes

Posted in reply to deleted_user
PROC TABULATE's internal logic is not different when ODS is delivering only to the Listing destination. TABULATE is not even aware of which destinations are active.

TABULATE and all other procedures that generate SAS output do so in a buffered manner. It's not as if TABULATE builds the entire table then renders it. That would be inefficient, and would lead to poor performance for very large tables. Rather, TABULATE computes N rows worth of results, and then hands them to ODS for formatting. There's no way to separate the rendering time from the computation time, because those steps are interleaved.

Now some destinations, such as RTF, accept buffered results and in turn build the entire table in memory, so you can run into performance problems. We're addressing that issue with the 9.2 TAGSETS.RTF destination.

-- David Kelley, SAS
N/A
Posts: 0

Re: reporting step runtimes

Posted in reply to David_SAS
David

re: different tabulate processing for listing

http://support.sas.com/techsup/unotes/SN/017/017344.html .

Peter
SAS Employee
Posts: 174

Re: reporting step runtimes

Posted in reply to deleted_user
Yes, *every* destination behaves differently. But destinations are separate from procedures. I know that from a user's perspective this is probably a meaningless distinction. Architecturally however, TABULATE has no knowledge of the Listing destination.

-- David Kelley, SAS
SAS Employee
Posts: 174

Re: reporting step runtimes

Posted in reply to David_SAS
As for timings, it's probably best to think of them as measured for a destination without regard to particular procedures. Currently we don't offer tools to do that. My previous suggestion to compare performance between active and inactive destinations was the best I could come up with.

-- David Kelley, SAS
N/A
Posts: 0

Re: reporting step runtimes

Posted in reply to David_SAS
David

As there is a handover from tabulate to ODS for formatting, is it only the formatting of the last buffer that is not "measured" by the step times ?

Could the timing of the rendering of that final buffer be captured in step time, in some way ?

Peter
Contributor
Posts: 23

Re: reporting step runtimes

Posted in reply to deleted_user
Would it be helpful to run the PROC TABULATE with output going to the DOCUMENT destination, and then try separately replaying it to other destinations?

While this wouldn't solve the initial problem of separating calculation time from rendering time in "normal" output mode, it could at least help to identify performance differences between destinations with a particular job, I would think.
SAS Super FREQ
Posts: 8,868

Re: reporting step runtimes

Posted in reply to MikeRhoads
Rendering is not done by SAS for all destinations. So, even if you saved the output object to the DOCUMENT destination, you would have to replay the output object to LISTING destination (capture that time) and then replay the same output object to each of PDF, RTF and HTML in turn -- I would expect that all 3 of those replays would take more time than replaying to the LISTING destination because of the added markup/translation/overhead that comes with those destination file formats.

It seems to me that since RENDERING is done by the RENDERING APP (Word, Acrobat Reader, browser), you would want to prevent SAS from launching any of these helper apps. Then, the time is EXCLUSIVE of 3rd party program launch and your log should measure time from the completed OUTPUT OBJECT (stored in ODS DOCUMENT form) to creation of the completed result file. That takes the rendering issue out of the picture -- since with PDF, HTML and RTF you are creating a file that is meant to be opened outside of SAS -- and just leaves you with whatever overhead has accrued in going from the output object to the operating system destination file.

This is what I did with a fairly simple proc tabulate (seen at the top of the LOG):[pre]
NOTE: SAS 9.1.3 Service Pack 4

NOTE: SAS initialization used:
real time 1.72 seconds
cpu time 1.12 seconds

1 ods html file='somefile.html';
NOTE: Writing HTML Body file: somefile.html
2 ods rtf file='somefile.rtf';
NOTE: Writing RTF Body file: somefile.rtf
3 ods pdf file='somefile.pdf';
NOTE: Writing ODS PDF output to DISK destination
"C:\Documents and Settings\sasczz\somefile.pdf", printer "PDF".
4 proc tabulate data=sashelp.shoes;
5 var sales;
6 class region product;
7 table region all,
8 product*sales*(min mean max);
9 run;

NOTE: There were 395 observations read from the data set SASHELP.SHOES.
NOTE: PROCEDURE TABULATE used (Total process time):
real time 0.90 seconds
cpu time 0.29 seconds


10 ods _all_ close;
NOTE: ODS PDF printed 3 pages to C:\Documents and Settings\sasczz\somefile.pdf.
11 ods listing close;
12
13 ods document name=work.shoetab(write);
14
15 proc tabulate data=sashelp.shoes;
16 var sales;
17 class region product;
18 table region all,
19 product*sales*(min mean max);
20 run;

NOTE: There were 395 observations read from the data set SASHELP.SHOES.
NOTE: PROCEDURE TABULATE used (Total process time):
real time 0.18 seconds
cpu time 0.00 seconds


21
22 ods document close;
23 ods html file='somefile.html';
NOTE: Writing HTML Body file: somefile.html
24 proc document name=shoetab;
25 replay;
26 run;

27 quit;

NOTE: PROCEDURE DOCUMENT used (Total process time):
real time 0.15 seconds
cpu time 0.05 seconds


28 ods _all_ close;
29
30 ods rtf file='somefile.rtf';
NOTE: Writing RTF Body file: somefile.rtf
31 proc document name=shoetab;
32 replay;
33 run;

34 quit;

NOTE: PROCEDURE DOCUMENT used (Total process time):
real time 0.09 seconds
cpu time 0.03 seconds


35 ods _all_ close;
36 ods pdf file='somefile.pdf';
NOTE: Writing ODS PDF output to DISK destination
"C:\Documents and Settings\sasczz\somefile.pdf", printer "PDF".
37 proc document name=shoetab;
38 replay;
39 run;

40 quit;

NOTE: PROCEDURE DOCUMENT used (Total process time):
real time 0.12 seconds
cpu time 0.12 seconds

41 ods _all_ close;
NOTE: ODS PDF printed 3 pages to C:\Documents and Settings\sasczz\somefile.pdf.
42 ods listing;
43 proc document name=shoetab;
44 replay;
45 run;

46 quit;

NOTE: PROCEDURE DOCUMENT used (Total process time):
real time 0.01 seconds
cpu time 0.02 seconds


47 ods _all_ close;
48
49 ods listing;
50
51 proc tabulate data=sashelp.shoes;
52 var sales;
53 class region product;
54 table region all,
55 product*sales*(min mean max);
56 run;

NOTE: There were 395 observations read from the data set SASHELP.SHOES.
NOTE: PROCEDURE TABULATE used (Total process time):
real time 0.03 seconds
cpu time 0.03 seconds

[/pre]

I probably should do all sorts of handwaving here because testing performance or making decisions on performance issues should NEVER be done from
just one run. The first run produced one set of numbers. Then, the individual steps, each replaying from the DOCUMENT store do not add up to those numbers, nor do I really expect that they would.

I had Outlook running and that could have affected the time, I had Word and PowerPoint running. So in my mind, this might approximate some kind of separation of OUTPUT OBJECT creation from DESTINATION file creation -- without making SAS launch any of the 3rd party rendering apps.

But to what end??? I could add the COMPRESS option or the COLUMNS option to PDF and I bet that would have an effect on the time. I could probably add some kind of option or pick a different tagset for HTML and that would have an effect on the time. Or I could use a tagset that checked to see if the variables were character or numeric and I bet that would take a LOT longer.

Real performance testing requires rigorous, almost neurotic procedures. Close down everything. Do a reboot. Only start the one app you're testing. Run your job/step/procedure. Capture the times. Log off. Do another reboot. start the one app you're testing. Change one thing. run your job/step/procedure. Capture the times. Log off. Do another reboot, etc, etc. Then do it all again with different data (more class variables) or do it all again with different options.

And I'm not sure what the real purpose of that kind of testing would be. You might be able to fine tune your system for performance--set different buffer sizes or different page file sizes -- or fine tune SAS in general -- but I don't think there's a lot you can do to fine tune ODS in the creation of destination files....not the same way that performance folks talk about fine tuning.

Just my .02,
cynthia
Ask a Question
Discussion stats
  • 9 replies
  • 247 views
  • 0 likes
  • 4 in conversation