Tuesday, July 8, 2014

Just where is my trace file?

This is pretty cool.

There is a view you can use to see some settings from a diagnostic point of view: V$DIAG_INFO

SQL> DESC V$DIAG_INFO
 NAME                 NULL?    TYPE
 -------------------- -------- --------------
 INST_ID                       NUMBER
 NAME                          VARCHAR2(64)
 VALUE                         VARCHAR2(512)
 CON_ID                        NUMBER


It's a fairly small view with 11 rows in it (in  my 12.1.0.1 database on my laptop at least).  The name column shows the kind of information stored:

SQL> select name from v$diag_info;

NAME
----------------------------------
Diag Enabled
ADR Base
ADR Home
Diag Trace
Diag Alert
Diag Incident
Diag Cdump
Health Monitor
Default Trace File
Active Problem Count
Active Incident Count


Of interest to this post is Default Trace File.  When selecting this it shows not just the trace file name but also the entire path.  On my little laptop this is what I have:

SQL> SELECT VALUE FROM V$DIAG_INFO WHERE NAME='Default Trace File';

VALUE
--------------------------------------------------------------------
C:\APP\ORACLE\diag\rdbms\hotsos\hotsos\trace\hotsos_ora_9616.trc

And if I set TRACEFILE_IDENTIFIER that will get reflected in the name:

SQL> ALTER SESSION SET TRACEFILE_IDENTIFIER = 'RVD_TEST';
Session altered.
SQL> SELECT VALUE FROM V$DIAG_INFO WHERE NAME='Default Trace File';

VALUE
--------------------------------------------------------------------------
C:\APP\ORACLE\diag\rdbms\hotsos\hotsos\trace\hotsos_ora_9616_RVD_TEST.trc

Nice. 

Monday, June 30, 2014

It's a bug.

Just wanted to let ya all know that the delayed block cleanout issue I logged with Oracle last December is an official bug:

Bug 17912562 : DELAYED BLOCK CLEANOUT NOT WORKING IN12C




Friday, June 6, 2014

Memory Used in a Sort

Found a little issue with the data displayed by DBMS_XPLAN.DISPLAY_CURSOR when it comes to the Used-Tmp column. This is certainly something to be aware of when you look at that column in the output. 


Take a look at this simple statement:


SQL> SELECT PLAN_TABLE_OUTPUT
  2    FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR
  3    ('g4tr51k11z5a0',0,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  g4tr51k11z5a0, child number 0
-------------------------------------
select * from big_tab order by owner

Plan hash value: 3765827574

-----------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation          | Name    | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem | Used-Tmp|
-----------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |         |      1 |        |   2868K|00:00:46.50 |   48224 |  97395 |  49190 |       |       |          |         |
|   1 |  SORT ORDER BY     |         |      1 |   2868K|   2868K|00:00:46.50 |   48224 |  97395 |  49190 |   432M|  6863K|  100M (1)|     385K|
|   2 |   TABLE ACCESS FULL| BIG_TAB |      1 |   2868K|   2868K|00:00:04.26 |   48215 |  48205 |      0 |       |       |          |         |
-----------------------------------------------------------------------------------------------------------------------------------------------

Looking at the Used-Tmp column it appears this didn’t use much temp space, only 385K for a sort that has a Used-Mem of 100M, hey that’s really great!  But how can that be?  Well it can’t is the short answer.  There appears to be a bug here. 

The data used by this function is coming from V$SQL_PLAN_STATISTICS_ALL.  If we look at that view for this query we can see that value is in the LAST_TEMPSEG_SIZE column (394240/1024 = 385K).  The documentation says that all these column are in bytes.  But It certainly appears that LAST_TEMPSEG_SIZE isn’t.

SQL> SELECT SQL_ID, ESTIMATED_OPTIMAL_SIZE, ESTIMATED_ONEPASS_SIZE, LAST_MEMORY_USED, LAST_TEMPSEG_SIZE
  2  FROM v$sql_plan_statistics_all
  3  WHERE SQL_ID = 'g4tr51k11z5a0';

SQL_ID        ESTIMATED_OPTIMAL_SIZE ESTIMATED_ONEPASS_SIZE LAST_MEMORY_USED LAST_TEMPSEG_SIZE
------------- ---------------------- ---------------------- ---------------- -----------------
g4tr51k11z5a0
g4tr51k11z5a0              453454848                7027712        104879104            394240
g4tr51k11z5a0

How is it that I can say with any level of certainty that this isn’t in bytes?  One thing is it certainly seems odd that a sort that used 100M would only use a couple hundred bytes of temp space.  But also if we look at a different view V$SQL_WORKAREA we see:

SQL> SELECT SQL_ID, ESTIMATED_OPTIMAL_SIZE, ESTIMATED_ONEPASS_SIZE, LAST_MEMORY_USED, LAST_TEMPSEG_SIZE
  2  FROM V$SQL_WORKAREA
  3  WHERE SQL_ID = 'g4tr51k11z5a0';

SQL_ID        ESTIMATED_OPTIMAL_SIZE ESTIMATED_ONEPASS_SIZE LAST_MEMORY_USED LAST_TEMPSEG_SIZE
------------- ---------------------- ---------------------- ---------------- -----------------
g4tr51k11z5a0              453454848                7027712        104879104         403701760

This appears to be in bytes.  Note that 40370176/1024 = 394240 the number we saw in V$SQL_PLAN_STATISTICS_ALL.  

So it sure looks like the view V$SQL_PLAN_STATISTICS_ALL is already converting the temp segment size into Kilobytes, but the function DBMS_XPLAN.DISPLAY_CURSOR thinks it’s in bytes and covert it to Kilobytes.  This actually makes it Megabytes, so it wasn’t using 385K it was using 385M.

Wednesday, June 4, 2014

ANSI or Classic?



I’m an old dog and I have yet to embrace ANSI syntax for writing SQL.  There is coming a day that I will likely have to move to ANSI and it appears to be coming sooner rather than later.  So I’ve started on this path.  While look around on the web the other day I stumbled on to a post saying that the old syntax is “bad” and the ANSI syntax is better (http://www.orafaq.com/node/2618).  So just for fun I pulled the queries used to see what the difference was.  

There isn’t any.

The author had stated that the classic syntax “is generating a cartesian product, and then filtering the result set with a predicate.”

The reality is that both the classic and the ANSI syntax create exactly the same plan.  Running both I then looked at V$SQL to see the plan created:

SQL> SELECT *
  2  FROM   emp,
  3         dept
  4  WHERE  emp.deptno = dept.deptno
  5         AND dept.dname = 'SALES';

SQL> SELECT *
  2  FROM   emp
  3         join dept USING(deptno)
  4  WHERE  dname = 'SALES';

SQL> select sql_id, child_number,plan_hash_value, sql_text from v$sql where sql_text like 'SELECT * FROM   emp%'

SQL_ID           CHILD_NUMBER PLAN_HASH_VALUE
------------- --------------- ---------------
SQL_TEXT
----------------------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------------------------------
4ug91aycb85jh               0      1688427947
SELECT * FROM   emp        join dept USING(deptno) WHERE  dname = 'SALES'

6snrnnz2qfwms               0      1688427947
SELECT * FROM   emp,        dept WHERE  emp.deptno = dept.deptno        AND dept.dname = 'SALES'

Notice they both have the exact same PLAN_HASH_VALUE, this means they both use the exact same plan:
SQL> SELECT PLAN_TABLE_OUTPUT
  2      FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR
  3      ('4ug91aycb85jh',0,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------------------------------
SQL_ID  4ug91aycb85jh, child number 0
-------------------------------------
SELECT * FROM   emp        join dept USING(deptno) WHERE  dname =
'SALES'

Plan hash value: 1688427947

-------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |      1 |        |      6 |00:00:00.01 |      12 |
|   1 |  NESTED LOOPS                |              |      1 |        |      6 |00:00:00.01 |      12 |
|   2 |   NESTED LOOPS               |              |      1 |      4 |      6 |00:00:00.01 |      10 |
|*  3 |    TABLE ACCESS FULL         | DEPT         |      1 |      1 |      1 |00:00:00.01 |       8 |
|*  4 |    INDEX RANGE SCAN          | EMP_DEPT_IDX |      1 |      5 |      6 |00:00:00.01 |       2 |
|   5 |   TABLE ACCESS BY INDEX ROWID| EMP          |      6 |      4 |      6 |00:00:00.01 |       2 |
-------------------------------------------------------------------------------------------------------

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

   3 - filter("DEPT"."DNAME"='SALES')
   4 - access("EMP"."DEPTNO"="DEPT"."DEPTNO")
       filter("EMP"."DEPTNO" IS NOT NULL)

SQL> SELECT PLAN_TABLE_OUTPUT
  2      FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR
  3      ('6snrnnz2qfwms',0,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------------------------------
SQL_ID  6snrnnz2qfwms, child number 0
-------------------------------------
SELECT * FROM   emp,        dept WHERE  emp.deptno = dept.deptno
AND dept.dname = 'SALES'

Plan hash value: 1688427947

-------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |      1 |        |      6 |00:00:00.01 |      12 |
|   1 |  NESTED LOOPS                |              |      1 |        |      6 |00:00:00.01 |      12 |
|   2 |   NESTED LOOPS               |              |      1 |      4 |      6 |00:00:00.01 |      10 |
|*  3 |    TABLE ACCESS FULL         | DEPT         |      1 |      1 |      1 |00:00:00.01 |       8 |
|*  4 |    INDEX RANGE SCAN          | EMP_DEPT_IDX |      1 |      5 |      6 |00:00:00.01 |       2 |
|   5 |   TABLE ACCESS BY INDEX ROWID| EMP          |      6 |      4 |      6 |00:00:00.01 |       2 |
-------------------------------------------------------------------------------------------------------

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

   3 - filter("DEPT"."DNAME"='SALES')
   4 - access("EMP"."DEPTNO"="DEPT"."DEPTNO")
       filter("EMP"."DEPTNO" IS NOT NULL)

Is this going to be true for all statement?  I certainly doubt it, there are always exceptions.  My inclination is that switching between the two syntax types is likely to produce the same plan more times than not.    Of course a test is worth 1000 opinions. 

Database used for this test was:
Oracle Database 12c Enterprise Edition Release 12.1.0.1.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options
Running on Windows 7 Professional. 

Tuesday, April 1, 2014

Hash THIS! A look at HASH_VALUE and PLAN_HASH_VALUE.



Way back in Oracle time, before SQL_ID there was just HASH_VALUE to identify statements in the shared pool.  Oracle used a technique that basically takes some number of charters of the statement and using a magical hashing algorithm computes a hexadecimal number to represent the statement in the shared pool.  What the optimizer would do at parse time is use this value to see if the statement was already in the shared pool.  But, since no hash algorithm is perfect, there would be collisions where two different statements would have the same hash value.  So the optimizer would then compare character by character to verify they were the same. 

This worked fine but as databases got bigger and SQL statements got longer, the collision rate went up and the optimizer was spending too much time looking for queries, so SQL_ID came along in version 10. This really is much like HASH_VALUE, but uses more characters of the statement and is also in base 32 numbering.  The SQL_ID looks a lot more like a string then a number, but it’s a number. 

Then in 10.2 we started to see PLAN_HASH_VALUE.  What is this?  

One of the goals of the folk writing the optimizer is to make it smarter and faster.  This cascades into the run time of the SQL.  If we can either parse or find the already parsed plan faster than we can run faster.  Also why have multiple plans that really are the same BUT have slightly different statements?  Wouldn't it be nice if two (or more) statements that “look different” but generate the same plan, just have ONE plan to use?   

Yes it would be, and that is where PLAN_HASH_VALUE comes in.  

Take a look at this very simple example:

SQL> @empno_test
SQL> alter system flush shared_pool;
System altered.
SQL> set echo on feed on
SQL> exec dbms_application_info.set_module('LAB1','EMPNO1');

PL/SQL procedure successfully completed.

SQL> select ename, job from emp where empno = 7902;
ENAME      JOB
---------- ---------
FORD       ANALYST

1 row selected.

SQL> exec dbms_application_info.set_module('LAB1','EMPNO2');

PL/SQL procedure successfully completed.

SQL> select ename, job from emp where 7902 = empno;
ENAME      JOB
---------- ---------
FORD       ANALYST

1 row selected.

SQL>
SQL> exec dbms_application_info.set_module(null,null);

PL/SQL procedure successfully completed.

SQL> set lines 10000
SQL> column action format a10
SQL> column executions heading EXEC format 9999
SQL> column version_count heading VERSIONS format 9999
SQL> column hash_value format 99999999999
SQL> column sql_text format a50
SQL>
SQL> select action, executions, version_count, hash_value, sql_id, plan_hash_value, sql_text
  2    from v$sqlarea
  3   where module = 'LAB1' and command_type != 47
  4   order by hash_value;
ACTION      EXEC VERSIONS   HASH_VALUE SQL_ID        PLAN_HASH_VALUE SQL_TEXT
---------- ----- -------- ------------ ------------- --------------- --------------------------------------------------
EMPNO2         1        1     77702346 ay1h1g42a396a      4120447789 select ename, job from emp where 7902 = empno
EMPNO1         1        1    116025303 1cvmsb83fntyr      4120447789 select ename, job from emp where empno = 7902

2 rows selected.

Notice each statement has its own unique HASH_VALUE and SQL_ID.  And both have the same PLAN_HASH_VALUE.   This means that although they are truly two different statements in the view of the optimizer, but they share the same plan.  And that plan is:

SQL> select /*+ gather_plan_statistics*/ ename, job from emp where 7902 = empno;
ENAME      JOB
---------- ---------
FORD       ANALYST

1 row selected.

SQL> select * from table(dbms_xplan.display_cursor());
PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------
-----------------------------------------------------------------------------------------------
SQL_ID  8nuj6ncwusvdt, child number 0
-------------------------------------
select /*+ gather_plan_statistics*/ ename, job from emp where 7902 =
empno

Plan hash value: 4120447789

--------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |              |       |       |     1 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| EMP          |     1 |    18 |     1   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | EMP_EMPNO_PK |     1 |       |     0   (0)|          |
--------------------------------------------------------------------------------------------

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

   2 - access("EMPNO"=7902)

20 rows selected.

A key point is that the two statements are DIFFERENT.  They will each take up some space of their own in the shared pool in the SGA, but the good news is they do share the same plan. 

The HASH_VALUE and the PLAN_HASH_VALUE are different numbers used differently.  The explain plan (see above) shows the PLAN_HASH_VALUE not the HASH_VALUE, be careful not to confuse the two.

Pretty cool, eh?