Thursday, December 10, 2015

New version of the Hotsos SQL Test Harness: V5

Dateline – December 2015, Grapevine TX, Hotsos World Headquarters

The latest and greatest version of the Harness is now available for download from the Hotsos Education Downloads page.  

This version is functionally quite different from the old one.  The use of it remains the same, you provide a SQL script file name, a workspace and scenario name and the test harness will run the SQL file and provide key statistics on the run, including the Extended SQL Trace File (10046).

How it works is quite different and it does show some different and I believe more useful information then the old one.  In version past the output included the explain plan.  However this is becoming less useful with the new features like Cardinality Feedback in 11 and Adaptive Query Optimization in 12.  The new version of the Harness now shows the execution plan using DBMS_XPLAN.DISPLAY_CURSOR.  The format options are set to TYPICAL ALLSTATS LAST ALIAS which I believe give you key information about the run. 

You still get the PARSE line and all the STAT lines from the 10046 trace as part of the output.  Also it still takes a snap shot of the statistics before and after the run to show you the total work done by the query. 

But a really big change is that the Harness no longer requires the use of a username and password.  In the old version the tool had to log off and back on a few times as trace files were created.   The new version uses the DBMS_MONITOR.SESSION_TRACE_ENABLE and DISABLE to create the 10046 trace file so logging off and on is no longer required to get the full trace file.  The problem really was in the old style of creating trace file you might not get “everything” if you just turned off trace when you were done with the statement.  And a key part was the STAT lines didn’t always get written to the trace file when you just “turned it off”.  Now they do.

Also, the new Harness doesn’t create the 10053 trace anymore (CBO Enable optimizer trace).  This is the trace of a hard parse and for the most part it’s not used for performance optimization.  Yes it can be interesting to look at to see what the optimizer was “thinking” as it created a plan.  There will be a separate utility to create and load the 10053 trace added to the tool pack soon.   

Please let me know of any issue you have while using the Harness.   

A simple example of a run:

SQL> @dosql emp emp emp
+-+-+-+-+-+-+
Starting Test
+-+-+-+-+-+-+
Snapshot 1 collection OK.
Snapshot 2 collection OK.

+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
| Actual PARSE and STAT line data for emp:emp
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+

PARSE #383679648:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1445457117,tim=343535899973

STAT #383679648 id=1 cnt=27 pid=0 pos=1 obj=116599 op='TABLE ACCESS FULL EMPLOYEES (cr=363 pr=0 pw=0 time=1331 us cost=73 size=83 card=1)'

+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
| Plan using DBMS_XPLAN.DISPLAY_CURSOR
| Format options: TYPICAL ALLSTATS LAST ALIAS
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  g76m74pycbct4, child number 0
-------------------------------------
select * from employees where first_name = 'David'

Plan hash value: 1445457117

----------------------------------------------------------------------------------------------------------
|Id |Operation         |Name      |Starts |E-Rows|E-Bytes|Cost (%CPU)|E-Time  |A-Rows|   A-Time  |Buffers|
----------------------------------------------------------------------------------------------------------
|  0|SELECT STATEMENT  |          |     1 |      |       |   73 (100)|        |    27|00:00:00.01|    363|
|* 1| TABLE ACCESS FULL|EMPLOYEES |     1 |     1|    83 |   73   (0)|00:00:01|    27|00:00:00.01|    363|
----------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

   1 - SEL$1 / EMPLOYEES@SEL$1

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("FIRST_NAME"='David')


+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
| Statistics Snapshot for emp:emp
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+

Type  Statistic Name                                    Value
----- ---------------------------------------- --------------
Latch cache buffers chains                              1,040
      row cache objects                                    55
      shared pool                                          33

Stats buffer is pinned count                                0
      consistent gets                                     363
      consistent gets direct                                0
      db block changes                                      0
      db block gets                                         0
      execute count                                         6
      index fast full scans (full)                          0
      parse count (hard)                                    0
      parse count (total)                                   6
      physical reads                                        0
      physical writes                                       0
      redo size                                             0
      session logical reads                               363
      session pga memory                                    0
      session pga memory max                                0
      session uga memory                                    0
      session uga memory max                                0
      sorts (disk)                                          0
      sorts (memory)                                        0
      sorts (rows)                                          0
      table fetch by rowid                                  0
      table scan blocks gotten                            355
      table scans (long tables)                             0
      table scans (short tables)                            1

Time  elapsed time (centiseconds)                           3

+-+-+-+-+-+-+
Test Complete
+-+-+-+-+-+-+
SQL>

Happy Optimizing!