SAS DI studio job runs normally, but same job in batch takes 5 more hours to complete

[naveenraj]

I have a SAS data integration studio, and when i run the job from DI studio itself the job is completing in 1 hour. As we schedule most of our jobs through batch, when i try to execute the same job from batch it is taking longer than 5 hours. Can some please guide me why its long running. 

Few thing i have noticed. 

The procedures that are long running are the proc sql's that are used to join two SAS datasets. If i check the memory consumption it is same for both the runs. Is it something related to SAS server configuration that is causing the job to long run in batch. 

[Kurt_Bremser]

Maxim 2: Read the Log.

In this case, read both logs and compare them step by step, to see if you have an overall difference or if only certain steps cause it.

Also compare the setups: are you running with a different user in batch? Where are the WORKs located? Do you have different MEMSIZE (or other) settings?

[AnandVyas]

Hi @naveenraj

Assuming Server options, user permissions and input data (if any) is the same, I would suggest the same as suggested by @Kurt_Bremser to read and compare the logs step by step. see if the option fullstimer would help to get some extra statistics to understand what is causing the bottleneck.

https://support.sas.com/rnd/scalability/tools/fullstim/index.html

Thanks!

[AhmedAl_Attar]

@naveenraj,

Few things to keep in mind when comparing between SAS Client Applications

1. The back-end/compute SAS Workspace Server settings/configurations 

2. The user id running the task/job be it in batch or interactive 

Here is why!

Depending on your SAS Multi-Tier installation, Knowing the following would help in isolating the reason

- Do you have multiple SASApps configured (Multiple Compute Tiers)

  - if Yes, are all share the same settings?

- Did both of your SAS Client Apps (DIS & Studio) run using the same SASApp instance?

- Did both of your SAS Client Apps (DIS & Studio) run under the same user ID?

Typically, the SAS Workspace Server instance would look for sasv9.cfg file under the current user home directory, and apply/use those settings.

I would recommend adding the following to the top of the SAS Code/Program and then repeat your execution scenarios

PROC OPTIONS GROUP=PERFORMANCE;
RUN;

%macro loginfo;
	data _null_;
		temp=datetime();
		temp2=lowcase(trim(left(put(temp,datetime16.))));
		call symput('g_datetime', trim(temp2));
	run;

	%put LOG HEADER BEGIN;
	%put LOG HEADER os=&sysscp;
	%put LOG HEADER os2=&sysscpl;
	%put LOG HEADER host=&g_computeHostName;
	%put LOG HEADER ver=&sysvlong;
	%put LOG HEADER date=&g_datetime;
	%put LOG HEADER parm=&sysparm;

	%put LOG HEADER END;
%mend loginfo;
%loginfo;

The results of the above code snippet will update your log file with information that could help with your quest.

Hope this helps,

Ahmed 

[ccaulkins9]

#kudoSAS @AHMED_alAttar!

[naveenraj]

hi @Kurt_Bremser, @AnandVyas, @AhmedAl_Attar . Thank you for your reply

for the time being i have enabled fullstimer option and ran the job. Whenever its long running this is the log

NOTE: PROCEDURE SQL used (Total process time):
real time 46:45.31
user cpu time 11:09.30
system cpu time 22:48.35
memory 2110359.71k
OS Memory 2120860.00k
Timestamp 08/07/2019 09:57:24 PM
Page Faults 15
Page Reclaims 2792475
Page Swaps 0
Voluntary Context Switches 7856852
Involuntary Context Switches 983261
Block Input Operations 314774320
Block Output Operations 682482984

when normal run: 

NOTE: SAS threaded sort was used.
NOTE: Table WORK.testcreated, with 148455601 rows and 15 columns.

quit;
NOTE: PROCEDURE SQL used (Total process time):
real time 8:03.16
user cpu time 7:45.12
system cpu time 5:14.55
memory 2110364.18k
OS Memory 2120860.00k
Timestamp 08/07/2019 04:27:34 AM
Page Faults 14
Page Reclaims 2233821
Page Swaps 0
Voluntary Context Switches 7479031
Involuntary Context Switches 625212
Block Input Operations 310773896
Block Output Operations 682466728

Any idea why real time is this high

The user, server everything is same when executing from SAS DI or as batch. 

[Kurt_Bremser]

Looks like you are on a completely different type of storage for your WORK and/or UTILLOC that causes much more wait states and more system (kernel) CPU action. Just compare the system CPU times (4 times as much in the longer run). Simple I/O waits would never cause such an increase, the CPU would just wait and do nothing.

Do

proc options option=(utilloc work threads);
run;

in both environments.

[naveenraj]

Same for both. 

UTILLOC=/*****/work/SASUtils

WORK=/*****/work/SASWork/SAS_work****

THREADS Threads are available for use with features of the SAS System that support threading. 

[Kurt_Bremser]

So you need to dig deeper:

%put &sysuserid.;
%put &syshostname.;
%put &syshostinfolong.;

and

proc options;
run;

If both of these are identical, I fear I've run out of ammunition to shoot at the problem.

[ccaulkins9]

#good_job, @Kurt_bremser!

[MargaretC · Accepted solution]

Can you check your system to see if there are other IO heavy things happening at 10:00 pm?  Like a backup or another heavy IO job?  Your System CPU time is has increased by more than 4 times.  System CPU is the amount of time the operating system is doing an activity for SAS - such as reading and/or writing data to a file system.  The fact that it is taking 4 times longer indicates that during the timeframe you ran this job it was having to do several retries to access the data.  This happens a lot when a backup is running on a system or other heavy IO jobs are running.

Can you schedule the batch job to run at 4:00 am?  This seems to be when the normal run ran. 

Also, what operating system are you running on?  Can you gather hardware monitor data during the batch run to see if the extra time is coming from IOWaits?

Cheers,

Margaret

[naveenraj]

Thanks for the suggestion @MargaretC . We have already setup a meeting with Unix administrators to see the performance of the system today evening (we have scheduled the sas job to run at this time sequentially) to see if its something related to system. 

To answer your question, the SAS is hosted on Unix system and we will ask administrators for the IOWaits data. 

[Kurt_Bremser]

Completely missed to look at the timestamps. That could explain everything.

(Basically, I now think that this is what we've been looking for. And I can't even blame not having had enough coffee ...)