I/O Bottleneck suspected, how to confirm what is causing the performance issues?

rawagah — Tue, 17 Jun 2025 12:01:56 GMT

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         
 
 
.

Re: I/O Bottleneck suspected, how to confirm what is causing the performance issues?

Kathryn_SAS — Tue, 17 Jun 2025 12:20:56 GMT

The following link may provide some tools to help you get started:

https://sas.service-now.com/kb?id=kb_article_view&sysparm_article=KB0039569

If you continue to have problems, you may want to open a case with Technical Support with the log information and diagnostic results.

Re: I/O Bottleneck suspected, how to confirm what is causing the performance issues?

rawagah — Tue, 17 Jun 2025 12:30:01 GMT

Thank you for sharing the link, but it seems it needs me to login with SAS credentials.

Can you share the article in a public link?

Thanks again,

Re: I/O Bottleneck suspected, how to confirm what is causing the performance issues?

Kathryn_SAS — Tue, 17 Jun 2025 13:25:24 GMT

Try this link:

https://sas.service-now.com/csm?id=kb_article_view&sysparm_article=KB0039569

topic Re: I/O Bottleneck suspected, how to confirm what is causing the performance issues? in SAS Programming

I/O Bottleneck suspected, how to confirm what is causing the performance issues?

Re: I/O Bottleneck suspected, how to confirm what is causing the performance issues?

Re: I/O Bottleneck suspected, how to confirm what is causing the performance issues?

Re: I/O Bottleneck suspected, how to confirm what is causing the performance issues?