Generating Trace Information for Threaded Reads

A threaded Read is a complex feature. A SAS step can be eligible for a threaded Read, but not have it applied. Performance effect is not always easy to predict. Use the SASTRACE option to see whether threaded Reads occurred and to help assess performance. These examples demonstrate usage scenarios with SAS/ACCESS to Oracle. Keep in mind that trace output is in English only and changes from release to release.
/*Turn on SAS tracing */
options sastrace=”,,t,” sastraceloc=saslog nostsuffix;

/* Run a SAS job */

data work.locemp;
set trlib.MYEMPS(DBBSLICEPARM=(ALL,3));
where STATE in ('GA', 'SC', 'NC') and ISTENURE=0;
run;
The above job produces these trace messages:
406  data work.locemp; 
407  set trlib.MYEMPS(DBSLICEPARM=(ALL, 3));
408  where STATE in ('GA', 'SC', 'NC') and ISTENURE=0; 
409  run;  

ORACLE:  DBSLICEPARM option set and 3 threads were requested 
ORACLE:  No application input on number of threads. 
 
ORACLE:  Thread 2 contains 47619 obs. 
ORACLE:  Thread 3 contains 47619 obs. 
ORACLE:  Thread 1 contains 47619 obs. 
ORACLE:  Threaded read enabled. Number of threads created: 3 
If you want to see the SQL that is executed during the threaded Read, you can set tracing to sastrace=',,t,d' and run the job again. This time the output contains threading information and all SQL statements that Oracle processes.
ORACLE_9: Prepared: 
SELECT * FROM MYEMPS  418  data work.locemp; 

419  set trlib.MYEMPS(DBSLICEPARM=(ALL, 3));
420  where STATE in ('GA', 'SC', 'NC') and ISTENURE=0; 
421  run;  

ORACLE:  DBSLICEPARM option set and 3 threads were requested 
ORACLE:  No application input on number of threads.  

ORACLE_10: Executed: 
SELECT  "HIREDATE", "SALARY", "GENDER", "ISTENURE", 
        "STATE", "EMPNUM", "NUMCLASSES" 
     FROM MYEMPS WHERE  ( ( ("STATE" IN  ( 'GA' , 'NC' , 'SC' ) ) ) AND  
     ("ISTENURE" = 0 ) ) AND ABS(MOD("EMPNUM",3))=0

ORACLE_11: Executed: 
SELECT  "HIREDATE", "SALARY", "GENDER", "ISTENURE", 
        "STATE", "EMPNUM", "NUMCLASSES" 
     FROM MYEMPS WHERE  ( ( ("STATE" IN  ( 'GA' , 'NC' , 'SC' ) ) ) AND  
     ("ISTENURE" = 0 ) ) AND ABS(MOD("EMPNUM",3))=1

ORACLE_12: Executed: 
SELECT  "HIREDATE", "SALARY", "GENDER", "ISTENURE", 
        "STATE", "EMPNUM", "NUMCLASSES" 
     FROM MYEMPS WHERE  ( ( ("STATE" IN  ( 'GA' , 'NC' , 'SC' ) ) ) AND  
     ("ISTENURE" = 0 ) ) AND (ABS(MOD("EMPNUM",3))=2 OR "EMPNUM" IS NULL)  

ORACLE:  Thread 2 contains 47619 obs. 
ORACLE:  Thread 1 contains 47619 obs. 
ORACLE:  Thread 3 contains 47619 obs. 
ORACLE:  Threaded read enabled. Number of threads created: 3 
Notice that the Oracle engine used the EMPNUM column as a partitioning column.
If a threaded Read cannot be done either because all of the candidates for autopartitioning are in the WHERE clause, or because the table does not contain a column that fits the criteria, SAS places a warning in the log. For example, the data set below uses a WHERE clause that contains all possible autopartitioning columns.
data work.locemp;
set trlib.MYEMPS (DBLISCEPARM=ALL);
where EMPNUM<=30 and ISTENURE=0 and SALARY<=35000 and NUMCLASSES>2;
run;
These warnings are displayed:
ORACLE:  No application input on number of threads. 
ORACLE:  WARNING: Unable to find a partition column for use w/ MOD() 
ORACLE:  The engine cannot automatically generate the 
         partitioning WHERE clauses. 
ORACLE:  Using only one read connection. 
ORACLE:  Threading is disabled due to an error.  
         Application reverts to nonthreading I/O's.
If the SAS job contains any options that are invalid when the engine tries to perform threading, you also receive a warning.
libname trlib oracle user=orauser pw=orapw path=oraserver DBSLICEPARM=(ALL);

proc print data=trlib.MYEMPS (OBS=10);
where EMPNUM<=30;
run;
This produces these messages:
ORACLE:  Threading is disabled due to the 
         ORDER BY clause or the FIRSTOBS/OBS option. 
ORACLE:  Using only one read connection. 
To produce timing information, add an S in the last slot of SASTRACE=.
options sastrace=',,t,s' sastraceloc=saslog nostsuffix;

data work.locemp;
set trlib.MYEMPS (DBSLICEPARM=ALL);
where EMPNUM<=10000;
run;
Here is the resulting timing information.
ORACLE:  No application input on number of threads.
ORACLE:  Thread 1 contains 5000 obs. 
ORACLE:  Thread 2 contains 5000 obs.  

Thread 0 fetched 5000 rows 
DBMS Threaded Read Total Time: 1234 mS 
DBMS Threaded Read User CPU:   46 mS 
DBMS Threaded Read System CPU: 0 mS 

Thread 1 fetched 5000 rows 
DBMS Threaded Read Total Time: 469 mS 
DBMS Threaded Read User CPU:   15 mS 
DBMS Threaded Read System CPU: 15 mS 
ORACLE:  Threaded read enabled. Number of threads created: 2 
NOTE: There were 10000 observations read from the data set TRLIB.MYEMPS.
     WHERE EMPNUM<=10000;  

Summary Statistics for ORACLE are:  Total SQL prepare seconds were:  0.00167 
Total seconds used by the ORACLE ACCESS engine were 7.545805 
For more information about tracing, see the SASTRACE= system option.