SQL Execution Statistics -- 2 : SQL_ID from a Tracefile

In my previous blog post, I have demonstrated sql execution statistics for the last SQL statement of the current session.

However, you can trace SQL execution in the current session or in any other session and then review the information from the tracefile.

(For different methods of SQL Tracing see this series of blog posts) 

For example, in an SQLPlus session :

SQL> alter session set tracefile_identifier='CUSTOMER_COUNT';

Session altered.

SQL>
SQL> select *
  2  from v$diag_info
  3  where name = 'Default Trace File';

   INST_ID NAME
---------- ----------------------------------------------------------------
VALUE
---------------------------------------------------------------------------------------
    CON_ID
----------
         1 Default Trace File
/opt/oracle/diag/rdbms/orclcdb/ORCLCDB/trace/ORCLCDB_ora_9416_CUSTOMER_COUNT.trc
         0


SQL>
SQL> exec DBMS_SESSION.SET_SQL_TRACE(sql_trace=>TRUE);

PL/SQL procedure successfully completed.

SQL> select /*+ gather_plan_statistics */ count(*) from tpcc.orders;

  COUNT(*)
----------
    303697

SQL> quit
Disconnected from Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
oracle19c>

From the tracefile :
PARSING IN CURSOR #139722640816616 len=62 dep=0 uid=106 oct=3 lid=106 tim=20489021058 hv=3158106211 ad='777865e0' sqlid='du49mwuy3ts33'
select /*+ gather_plan_statistics */ count(*) from tpcc.orders
END OF STMT
PARSE #139722640816616:c=10950,e=11447,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=630573765,tim=20489021057
EXEC #139722640816616:c=52,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=630573765,tim=20489021253
FETCH #139722640816616:c=78319,e=464572,p=1504,cr=1508,cu=0,mis=0,r=1,dep=0,og=1,plh=630573765,tim=20489485885
STAT #139722640816616 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1508 pr=1504 pw=0 str=1 time=464570 us)'
STAT #139722640816616 id=2 cnt=303697 pid=1 pos=1 obj=80213 op='TABLE ACCESS FULL ORDERS (cr=1508 pr=1504 pw=0 str=1 time=566811 us cost=411 size=0 card=303697)'
FETCH #139722640816616:c=1,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=630573765,tim=20489486318


From a tkprof of the tracefile :
SQL ID: du49mwuy3ts33 Plan Hash: 630573765

select /*+ gather_plan_statistics */ count(*)
from
 tpcc.orders


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.07       0.46       1504       1508          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.08       0.47       1504       1508          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 106
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=1508 pr=1504 pw=0 time=464570 us starts=1)
    303697     303697     303697   TABLE ACCESS FULL ORDERS (cr=1508 pr=1504 pw=0 time=566811 us starts=1 cost=411 size=0 card=303697)
    
 
 SQL> select * from table(dbms_xplan.display_cursor('du49mwuy3ts33',format=>'ALLSTATS LAST +COST'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  du49mwuy3ts33, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from tpcc.orders

Plan hash value: 630573765

-------------------------------------------------------------------------------------------------------------
| Id  | Operation          | Name   | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers | Reads  |
-------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |        |      1 |        |   411 (100)|      1 |00:00:00.38 |    1506 |   1505 |
|   1 |  SORT AGGREGATE    |        |      1 |      1 |            |      1 |00:00:00.38 |    1506 |   1505 |
|   2 |   TABLE ACCESS FULL| ORDERS |      1 |    303K|   411   (1)|    303K|00:00:00.07 |    1506 |   1505 |
-------------------------------------------------------------------------------------------------------------


14 rows selected.

SQL>

From the tracefile, I could identify the SQL_ID (du49mwuy3ts33) and then run dbms_xplan.display_cursor for that SQL_ID.  

There is a slight discrepancy between the tracefile and the dbms_xplan.display_cursor output on the Actual Time and Buffers ("cr" in the tracefile) and Physical Reads ("pr" in the tracefile).  Similarly, you might notice a discrepancy in the time reported in the raw trace file STAT lines for operation Ids 2 and 1.  When the timing is in microseconds, some discrepancies may arise.

You must also note that gather_plan_statistics itself introduces an overhead on execution time for SQL statements that run in microseconds/milliseconds.

(For an explanation of reading the tracefile, see this post on the details and and this post on the summary)