Delay while running a job or a code in SAS-DI studio

[sangeeta128]

Hello,

 I see a 3 minutes delay/wait when  trying to run a job in DI studio. This is happening only on one environment so I do not understand what is causing it, I checked all configuration (which is same as other environments) but did not find the problem. Below is the object spawner logs, as you can see I triggered the job at 15:27, that's when the logs states "Created process 119614..." but after this it waits for 3 mins then the logs states 'New out call client connection...', this is when the jobs actually starts running. 

Another observation is that if I try to run the job again it runs immediately (no delay) but if I close the job window (process ends ), when I open it again the issue re-occurs when I run the it the first time. 

Please help me understand why is it waiting for 3 mins and how can I fix this.

2024-09-17T15:27:39,047 INFO [00002165] : New out call client connection (228) for user sas***. Encryption level is Credentials using encryption algorithm SASPROPRIETARY. Peer IP address and port are [xx.xxx.xxx.xx]:8561.
2024-09-17T15:27:39,049 INFO [00002165] : New client connection (227) accepted from server port 8591 for SAS token user sas***. Encryption level is Credentials using encryption algorithm SASPROPRIETARY. Peer IP address and port are [xx.xxx.xxx.xx]:65360 for APPNAME=SAS Data Integration Studio.
2024-09-17T15:27:39,059 INFO [00002165] :Created process 119614 using credentials sas*** for user sas*** (child id 72).
2024-09-17T15:30:39,807 INFO [00002175] :New out call client connection (229) for launched server (child 72). Peer IP address and port are [xx.xxx.xxx.xx]:45062.
2024-09-17T15:30:39,809 INFO [00002175] : Client connection 227 for user sas*** closed.
2024-09-17T15:30:39,810 INFO [00000010] : Client connection 228 for user sas*** closed.

2024-09-17T15:31:05,827 INFO [00000010] :Client connection 229 for user sas*** closed.
2024-09-17T15:31:05,963 INFO [00002399] :Process 119614 owned by user sas*** (child id 72) has ended.

[LinusH]

I don't think I can help you directly.

Here's an old paper on the subject, there might some thinkgs you can check:

Tracking Down the Culprit of a SAS® Workspace Server Initialization Delay

What happens if you start a WS session from another client (e.g., Enterprise Guide)?

Not trying to reduce your problem, but in my mind submitting jobs in DI Srudio is usually only done in dev, and sometimes during test - rarely/never in prod. The default pattern is to use the Batch Server where the object spawner/workspace server is not involved.

[sangeeta128]

Hello,

Thanks for the reply. I saw the paper you shared but the delay we see is probably NOT during initialization, its happening after the initialization. We are having this issue only on our dev environment (in DI Studio), when I tried to run the same job on other environment (in DI studio) it ran fine without any delay.  We generally use flow manager to run the batch and there I DO NOT see any delay in any environment. So I guess there might be some issue with workspace server?

[Patrick]

If it's happening after the initialization then compare the logs for the same job run in two different environments and then investigate the job where the times differ the most. It could for example be some delay (or bad performance) with a libname pointing to some network drive.

I would also expect you'd see the same timing differences if you copy/paste the DIS generated code into SAS EG. 

Using SAS EG you could actually first create the SAS Session and then execute the code. In doing so does performance between DEV and TEST still differ the same? ...or does it eventually take a long time in DEV to create a SAS session with EG?

[sangeeta128]

Hello Patrick,

Unfortunately, we do not have Enterprise Guide as part of our SAS package. I generated the workspace server logs and I see the latency of 1.5 minutes at two places adding up to a total of 3 mins delay. Below is a piece of workspace server logs, I ran the job at 12:01:23 but the job does not start, there are some activity at 12:02:53 but nothing changes in DI studio, then at 12:04:23 the job actually starts running.

I noticed both delays are after "SecurityProxy::GetLoginForAuthDomain()", I don't know if this is relevant to the issue.

2024-09-18T12:01:23,743 DEBUG [00000005] :sas*** - IOM CALL {compRef:7f5a000f37e0}->OMIProxy::GetMetadata()
2024-09-18T12:01:23,744 DEBUG [00000005] :sas*** - IOM RETURN 0={compRef:7f5a000f37e0}->OMIProxy::GetMetadata()
2024-09-18T12:01:23,744 DEBUG [00000005] :sas*** - IOM CALL {compRef:7f5a000f3460}->SecurityProxy::GetLoginForAuthDomain()
2024-09-18T12:01:23,745 DEBUG [00000005] :sas*** - IOM RETURN 0={compRef:7f5a000f3460}->SecurityProxy::GetLoginForAuthDomain()
2024-09-18T12:02:53,823 DEBUG [00000005] :sas*** - IOM ENTRY OMIProxy {compRef:7f5a000f37e0}->CompDtor()
2024-09-18T12:02:53,824 DEBUG [00000005] :sas*** - IOM RETURN OMIProxy 0={compRef:7f5a000f37e0}->CompDtor()
2024-09-18T12:02:53,824 DEBUG [00000005] :sas*** - IOM ENTRY SecurityProxy {compRef:7f5a000f3460}->CompDtor()
2024-09-18T12:02:53,824 DEBUG [00000005] :sas*** - IOM RETURN SecurityProxy 0={compRef:7f5a000f3460}->CompDtor()
2024-09-18T12:02:53,825 DEBUG [00001900] :sas*** - IOM CALL svcGetOption(): opt=SELFTEST not found
2024-09-18T12:02:53,825 DEBUG [00000005] :sas*** - IOM LOGIC ENTRY {class:7f59f0ab4c40}->OMIProxyClassNew()
2024-09-18T12:02:53,825 DEBUG [00000005] :sas*** - IOM NEW OMIProxy (compRef:7f5a000f3460, comp:7f59f0ab4d20)
2024-09-18T12:02:53,825 DEBUG [00000005] :sas*** - IOM CALL {compRef:7f5a000f3460}->OMIProxy::ProxyInit()
2024-09-18T12:02:53,825 DEBUG [00000005] :sas*** - IOM RETURN 0={compRef:7f5a000f3460}->OMIProxy::ProxyInit()
2024-09-18T12:02:53,825 DEBUG [00000005] :sas*** - IOM CALL {compRef:7f5a000f3460}->OMIProxy::ProxyPEInfo()
2024-09-18T12:02:53,825 DEBUG [00000005] :sas*** - IOM RETURN 0={compRef:7f5a000f3460}->OMIProxy::ProxyPEInfo()
2024-09-18T12:02:53,825 DEBUG [00000005] :sas*** - IOM LOGIC ENTRY {class:7f59f0ab4de0}->SecurityProxyClassNew()
2024-09-18T12:02:53,825 DEBUG [00000005] :sas*** - IOM NEW SecurityProxy (compRef:7f5a000f37e0, comp:7f59f0169040)
2024-09-18T12:02:53,825 DEBUG [00000005] :sas*** - IOM CALL {compRef:7f5a000f37e0}->SecurityProxy::ProxyInit()
2024-09-18T12:02:53,825 DEBUG [00000005] :sas*** - IOM RETURN 0={compRef:7f5a000f37e0}->SecurityProxy::ProxyInit()
2024-09-18T12:02:53,825 DEBUG [00000005] :sas*** - IOM CALL {compRef:7f5a000f37e0}->SecurityProxy::GetCredentials()
2024-09-18T12:02:53,826 DEBUG [00000005] :sas*** - IOM RETURN 0={compRef:7f5a000f37e0}->SecurityProxy::GetCredentials()
2024-09-18T12:02:53,826 DEBUG [00000005] :sas*** - IOM CALL {compRef:7f5a000f37e0}->SecurityProxy::GetInfo()
2024-09-18T12:02:53,827 DEBUG [00000005] :sas*** - IOM RETURN 0={compRef:7f5a000f37e0}->SecurityProxy::GetInfo()
2024-09-18T12:02:53,827 DEBUG [00000005] :sas*** - IOM CALL {compRef:7f5a000f37e0}->SecurityProxy::FreeCredentials()
2024-09-18T12:02:53,827 DEBUG [00000005] :sas*** - IOM RETURN 0={compRef:7f5a000f37e0}->SecurityProxy::FreeCredentials()
2024-09-18T12:02:53,827 DEBUG [00000005] :sas*** - IOM CALL {compRef:7f5a000f3460}->OMIProxy::GetMetadata()
2024-09-18T12:02:53,828 DEBUG [00000005] :sas*** - IOM RETURN 0={compRef:7f5a000f3460}->OMIProxy::GetMetadata()
2024-09-18T12:02:53,828 DEBUG [00000005] :sas*** - IOM CALL {compRef:7f5a000f37e0}->SecurityProxy::GetLoginForAuthDomain()
2024-09-18T12:02:53,829 DEBUG [00000005] :sas*** - IOM RETURN 0={compRef:7f5a000f37e0}->SecurityProxy::GetLoginForAuthDomain()
2024-09-18T12:04:23,910 DEBUG [00000005] :sas*** - IOM ENTRY OMIProxy {compRef:7f5a000f3460}->CompDtor()
2024-09-18T12:04:23,912 DEBUG [00000005] :sas*** - IOM RETURN OMIProxy 0={compRef:7f5a000f3460}->CompDtor()
2024-09-18T12:04:23,912 DEBUG [00000005] :sas*** - IOM ENTRY SecurityProxy {compRef:7f5a000f37e0}->CompDtor()
2024-09-18T12:04:23,915 DEBUG [00000005] :sas*** - IOM RETURN SecurityProxy 0={compRef:7f5a000f37e0}->CompDtor()
2024-09-18T12:04:23,915 INFO [00000008] :sas*** - NOTE: Libref SASDATA successfully assigned from logical server.
2024-09-18T12:04:23,915 INFO [00000008] :sas*** - NOTE: Libref STPSAMP successfully assigned from logical server.