we are running SAS 9.4 on a remote windows server, many users (mostly using EG) are facing long run time where real time is significantly higher than cpu time. I ran a dummy benchmark program to see what could cause the issue and it seems it could be an i/o disk related. The result showed that cpu only utilized 1/4 of the time when doing intensive joins and sorting (15 mins cpu time vs 1hr real time for example)
I spoke with our infrastructure team and told me that the server is virtual and the disks are SSD (with no more details than that).
What can be done to pinpoint the root cause?
Here is the benchmark log:
step 1:
NOTE: The data set WORK.ULTRA_PRIMARY has 500000000 observations and 6 variables.
NOTE: At least one W.D format was too small for the number to be printed. The decimal may be shifted by the "BEST" format.
NOTE: DATA statement used (Total process time):
real time 11:15.48
user cpu time 4:39.09
system cpu time 2:31.73
memory 647.62k
OS Memory 20832.00k
Timestamp 05/25/2025 03:18:50 PM
Step Count 216 Switch Count 2
40 /* STEP 2: Supporting Table A (100 million rows) */
41 data work.ultra_support1;
42 length y1 y2 $150;
43 do id = 1 to 100e6;
44 y1 = repeat('support1', 15);
45 y2 = repeat('valueA', 25);
46 output;
47 end;
48 run;
NOTE: The data set WORK.ULTRA_SUPPORT1 has 100000000 observations and 3 variables.
NOTE: DATA statement used (Total process time):
real time 55.71 seconds
user cpu time 16.95 seconds
4 The SAS System 14:38 Sunday, May 25, 2025
system cpu time 12.32 seconds
memory 668.84k
OS Memory 20832.00k
Timestamp 05/25/2025 03:19:46 PM
Step Count 217 Switch Count 2
49 /* STEP 3: Supporting Table B (100 million rows) */
50 data work.ultra_support2;
51 length z1 $200;
52 do id = 1 to 100e6;
53 z1 = repeat('support2_data_block_', 10);
54 output;
55 end;
56 run;
NOTE: The data set WORK.ULTRA_SUPPORT2 has 100000000 observations and 2 variables.
NOTE: DATA statement used (Total process time):
real time 26.54 seconds
user cpu time 9.85 seconds
system cpu time 7.73 seconds
memory 664.62k
OS Memory 20832.00k
Timestamp 05/25/2025 03:20:12 PM
Step Count 218 Switch Count 2
57 /* STEP 4: Sort for Merge Join (forces WORK and UTILLOC writes) */
58 proc sort data=work.ultra_primary; by id; run;
NOTE: There were 500000000 observations read from the data set WORK.ULTRA_PRIMARY.
NOTE: The data set WORK.ULTRA_PRIMARY has 500000000 observations and 6 variables.
NOTE: PROCEDURE SORT used (Total process time):
real time 41:40.23
user cpu time 4:33.21
system cpu time 7:37.43
memory 3156072.43k
OS Memory 3176496.00k
Timestamp 05/25/2025 04:01:53 PM
Step Count 219 Switch Count 3663
59 proc sort data=work.ultra_support1; by id; run;
NOTE: There were 100000000 observations read from the data set WORK.ULTRA_SUPPORT1.
NOTE: The data set WORK.ULTRA_SUPPORT1 has 100000000 observations and 3 variables.
NOTE: PROCEDURE SORT used (Total process time):
real time 3:18.70
user cpu time 32.89 seconds
system cpu time 48.78 seconds
memory 3162737.73k
OS Memory 3182856.00k
Timestamp 05/25/2025 04:05:11 PM
Step Count 220 Switch Count 304
60 proc sort data=work.ultra_support2; by id; run;
5 The SAS System 14:38 Sunday, May 25, 2025
NOTE: There were 100000000 observations read from the data set WORK.ULTRA_SUPPORT2.
NOTE: The data set WORK.ULTRA_SUPPORT2 has 100000000 observations and 2 variables.
NOTE: PROCEDURE SORT used (Total process time):
real time 1:53.93
user cpu time 27.53 seconds
system cpu time 32.18 seconds
memory 3160341.57k
OS Memory 3180420.00k
Timestamp 05/25/2025 04:07:05 PM
Step Count 221 Switch Count 173
61 /* STEP 5: Join All Tables */
62 proc sql;
63 create table work.joined_ultra as
64 select
65 a.id, a.x1, a.x2, a.x3, a.x4, a.x5,
66 b.y1, b.y2,
67 c.z1
68 from work.ultra_primary as a
69 left join work.ultra_support1 as b on a.id = b.id
70 left join work.ultra_support2 as c on a.id = c.id;
NOTE: Table WORK.JOINED_ULTRA created, with 500000000 rows and 9 columns.
71 quit;
NOTE: PROCEDURE SQL used (Total process time):
real time 21:40.85
user cpu time 2:48.31
system cpu time 7:11.28
memory 6193.31k
OS Memory 26212.00k
Timestamp 05/25/2025 04:28:46 PM
Step Count 222 Switch Count 1893
72 /* STEP 6: Summary Analysis */
73 proc summary data=work.joined_ultra nway;
74 class x4;
75 var x1 x2;
76 output out=work.final_summary mean= std= sum=;
77 run;
WARNING: Variable x1 already exists on file WORK.FINAL_SUMMARY.
WARNING: Variable x2 already exists on file WORK.FINAL_SUMMARY.
WARNING: Variable x1 already exists on file WORK.FINAL_SUMMARY.
WARNING: Variable x2 already exists on file WORK.FINAL_SUMMARY.
WARNING: The duplicate variables will not be included in the output data set of the output statement number 1.
NOTE: There were 500000000 observations read from the data set WORK.JOINED_ULTRA.
NOTE: The data set WORK.FINAL_SUMMARY has 1 observations and 5 variables.
NOTE: PROCEDURE SUMMARY used (Total process time):
real time 22:46.70
user cpu time 4:47.82
system cpu time 2:06.95
memory 6596.06k
OS Memory 26732.00k
Timestamp 05/25/2025 04:51:33 PM
Step Count 223 Switch Count 2156
6 The SAS System 14:38 Sunday, May 25, 2025
78 /* STEP 7: Heavy Sort */
79 proc sort data=work.final_summary out=work.sorted_summary;
80 by descending x4;
81 run;
NOTE: There were 1 observations read from the data set WORK.FINAL_SUMMARY.
NOTE: The data set WORK.SORTED_SUMMARY has 1 observations and 5 variables.
NOTE: PROCEDURE SORT used (Total process time):
real time 0.01 seconds
user cpu time 0.01 seconds
system cpu time 0.00 seconds
memory 1476.56k
OS Memory 22376.00k
Timestamp 05/25/2025 04:51:33 PM
Step Count 224 Switch Count 2
82
83 %LET _CLIENTTASKLABEL=;
84 %LET _CLIENTPROCESSFLOWNAME=;
85 %LET _CLIENTPROJECTPATH=;
86 %LET _CLIENTPROJECTPATHHOST=;
87 %LET _CLIENTPROJECTNAME=;
88 %LET _SASPROGRAMFILE=;
89 %LET _SASPROGRAMFILEHOST=;
90
91 ;*';*";*/;quit;run;
92 ODS _ALL_ CLOSE;
93
94
95 QUIT; RUN;
96
.
