Monthly Archives: July 2012

Tracing SPM’s and Datapump (Tracing Series-I)

Oracle July 27, 2012

Some of  the complex issues that we face in our day-day operations can be resolved by tracing with or without Oracle support.  It depends on how much you want to grind yourself as understanding some of the trace files are not for faint hearts.  I always end up spending time googling for appropriate  syntax or trace number. Sometimes you  are lucky enough to get  to the intended document but sometimes you end up at wrong place.   So here I am compiling a one stop shop for all tracing needs as series.  In  Part-I , I will be discussing SPM tracing and Datapump tracing.  SPM and datapump have nothing in common , just  picked them randomly

—
SPM Tracing: There may be many  reasons why one would trace SPM.  Few of the reasons I can think of is to diagnose SPM’s not being created or to see more information of plan evolution.  SPM Tracing can be enabled either of following ways

  •     exec dbms_spm.configure(‘spm_tracing’,1);

I could not find documentation about spm_tracing option  in 11gR2. Two documented parameters supported by dbms_spm.configure procedure are  space_budget_percent and plan_retention_weeks.  Only references for parameter spm_tracing was found in metalink with values 0 (disable tracing) and 1(enable tracing). The actual command however takes any values you provide.  You can query sys.smb$config to verify tracing is enabled or disabled

SQL> exec dbms_spm.configure('spm_tracing',1); 

PL/SQL procedure successfully completed.

SQL> 
SQL>  select parameter_name, parameter_value from sys.smb$config;

PARAMETER_NAME                 PARAMETER_VALUE
------------------------------ ---------------
SPACE_BUDGET_PERCENT                        25
PLAN_RETENTION_WEEKS                       523
SPM_TRACING                                  1
  •     alter session set events ‘trace [sql_planmanagement.*]’;

Noticed the 2nd command; If does not look familiar then you are not  alone. This is the new syntax introduced with 11g also referred to as universal tracing.  Unfortunately I was not able to get this working after trying different options. I will follow-up with Oracle on this command.
SQL>
SQL> alter session set events ‘trace [sql_planmanagement.*]’;
ERROR:
ORA-49100: Failed to process event statement [trace [sql_planmanagement.*]]
ORA-48904: String [SQL_PLANMANAGEMENT] is not a valid component name

SQL> alter session set events ‘trace {sql_plan_management.*}’;
ERROR:
ORA-49100: Failed to process event statement [trace {sql_plan_management.*}]
ORA-49109: Library Name [SQL_PLAN_MANAGEMENT] not found

SQL>

—

DataPump Tracing:  Datapump can be traced in multiple ways either at database level or at command level or with 10046 trace.  With datapump , tracing is as complex as analyzing the trace files.  Never understood the reasoning behind  exposing hexadecimals to users unless this was intended for Oracle support. Datapump tracing  is enabled with  TRACE parameter using 7 digit hexadecimal. The first three digits enable the trace  while last four digits are usually “0300”
At the database level, datapump tracing can be enabled with initialization parameter EVENT 39089.  Again you have to find the correct  hexadecimal value and  bounce the database.

—

Example:(Init.ora setting)

EVENT=”39089 trace name context forever,level 0x300″ .

—

Example (alter system ,10046 trace)
alter system set events ‘sql_trace {process : pname = dw | pname = dm} level=12’; Just replace 12 with off to disable tracing. Be aware of this command , it will take any argument for process name.

—
SQL> alter system set events ‘sql_trace {process : pname = dw } level=12’;

System altered.

—

SQL> alter system set events ‘sql_trace {process : pname =djsljl} level=12′;  ==> Incorrect value

System altered.

SQL>
—-

—

Example (Command level)
expdp system/manager DIRECTORY=mydata_dir DUMPFILE=full_db.dmp LOGFILE=full_db.log full=y TRACE=480300

—

—

Here is information about  the hexadecimals supported trace levels supported.  Oracle also supports combination of these values

================================================================================
Hex     | Purpose
================================================================================
10300   |  SHDW: To trace the Shadow process (API) (expdp/impdp)
20300   |  KUPV: To trace Fixed table
40300   |  'div' To trace Process services
80300   |  KUPM: To trace Master Control Process (MCP,DM)
100300  |  KUPF: To trace File Manager
200300  |  KUPC: To trace Queue services
400300  |  KUPW: To trace Worker process(DW)
800300  |  KUPD: To trace Data Package
1000300 |  META: To trace Metadata Package
1FF0300 |  'all' To trace all components(full tracing)
================================================================================

Unnesting Nested Loops

Oracle July 21, 2012

Lately I have been trying to help my non-DBA colleague to understand optimizer operations. Now that I am putting this effort , why not add it to my blog. I will be writing a series of blogs discussing optimizer operations.  Let me start the honors with NESTED LOOPS.

NESTED LOOPS:  As the name implies, this operation works similar to nested loops in programming language aka a loop within a loop.   For example, let’s use PL/SQL language that most of us are familiar

SQL> BEGIN

2       FOR  OuterLoop IN 1..2 LOOP

3            FOR InnerLoop  IN 1..3 LOOP

4                 DBMS_OUTPUT.PUT_LINE(‘OuterLoop=> ‘|| OuterLoop  || ‘   ‘||  ‘ InnerLoop=> ‘ || InnerLoop);

5            END LOOP;

6       END LOOP;

7  END;

8  /

OuterLoop=> 1    InnerLoop=> 1

OuterLoop=> 1    InnerLoop=> 2

OuterLoop=> 1    InnerLoop=> 3

OuterLoop=> 2    InnerLoop=> 1

OuterLoop=> 2    InnerLoop=> 2

OuterLoop=> 2    InnerLoop=> 3

 PL/SQL procedure successfully completed.

In this example, the outer loop executes 2 times and for each execution of the outer loop, the inner loop executes 3 times. Switching gears to nested loop between let’s say tables A and B; Assume table A has 50 rows and table B has 1000 rows.  If table A is used as the outer table, then for every row accessed in table a, inner table B will be accessed 1000 times.

So who makes the choice of deciding the outer and inner table? Well the Oracle optimizer does. Generally the rule of thumb is the table with less number of rows is used in the outer loop and table will more number of rows is used in the inner table.   This is where table statistics plays an important role, actually up-to-date statistics.  Number of IO operations and blocks retrieved also influences the decision in choosing the appropriate outer and inner tables. None of what is mentioned in this article is always true  as most of us don’t have access to actual Oracle logic .

A nested loops join is  very effective if the outer input is small and the inner input is indexed and large.  Generally nested loops perform better in OLTP environment where the result set tends to be small.

Changes in 11g

Execution plans with 11G might look different because of  changes in nested loop implementation. The change was introduced  to reduce overall latency for physical I/O  when the required data for nested loop join is not in the buffer cache.  Oracle reduces the overall physical I/O request latency by batching multiple physical I/O requests  improving the  performance (most likely). You can see the new batching operation with a  10053 trace or  DBMS_XPLAN.DISPLAY_CURSOR.

You will notice  two NESTED LOOPS  operations  in the execution plan instead of one because of this implementation change.   Two nested loop are required for

  1.   1st nested loop to  join data from outer loop table  and index on the inner loop table.
  2.   2nd nested loop to join the result set of  1st nested loop and table  data on the inner side of the join.

The above implementation change can be controlled with init.ora parameter optimizer_features_enable or  with a new hint “no_nlj_batching”

For example, Let us run the a query with optimizer_features_enable set to Oracle version 11 and then again rerun the same query with Oracle version 10.

Case-1 : optimizer_features_enable=11.2.0.2

In this case you will see 2  nested loops in the execution plan and new operation NLJ_BATCHING in the outline_data.

SQL> SELECT *   FROM   TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'ADVANCED'));
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  apzagcxrnwka8, child number 0
-------------------------------------
SELECT   A.OBJECT_NAME ,  A. LAST_DDL_TIME , B.CREATED FROM A, B WHERE
b.OBJECT_ID=a.OBJECT_ID  AND  a.OBJECT_ID BETWEEN 1 AND 30

Plan hash value: 1521750179

----------------------------------------------------------------------------------------
| Id  | Operation                     | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |        |       |       |     5 (100)|          |
|   1 |  NESTED LOOPS                 |        |       |       |            |          |
|   2 |   NESTED LOOPS                |        |     3 |   135 |     5   (0)| 00:00:01 |
|   3 |    TABLE ACCESS BY INDEX ROWID| A      |    16 |   512 |     3   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | IDX_A  |    16 |       |     2   (0)| 00:00:01 |
|*  5 |    INDEX UNIQUE SCAN          | INDX_B |     1 |       |     0   (0)|          |
|   6 |   TABLE ACCESS BY INDEX ROWID | B      |     1 |    13 |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------------

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

   1 - SEL$1
   3 - SEL$1 / A@SEL$1
   4 - SEL$1 / A@SEL$1
   5 - SEL$1 / B@SEL$1
   6 - SEL$1 / B@SEL$1

Outline Data
-------------

  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.2')
      DB_VERSION('11.2.0.2')
      OPT_PARAM('query_rewrite_enabled' 'false')
      FIRST_ROWS(10)
      OUTLINE_LEAF(@"SEL$1")
      INDEX_RS_ASC(@"SEL$1" "A"@"SEL$1" ("A"."OBJECT_ID"))
      INDEX(@"SEL$1" "B"@"SEL$1" ("B"."OBJECT_ID"))
      LEADING(@"SEL$1" "A"@"SEL$1" "B"@"SEL$1")
      USE_NL(@"SEL$1" "B"@"SEL$1")
      NLJ_BATCHING(@"SEL$1" "B"@"SEL$1")      END_OUTLINE_DATA
  */

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

   4 - access("A"."OBJECT_ID">=1 AND "A"."OBJECT_ID"<=30)
   5 - access("B"."OBJECT_ID"="A"."OBJECT_ID")
       filter(("B"."OBJECT_ID"<=30 AND "B"."OBJECT_ID">=1))

Column Projection Information (identified by operation id):
-----------------------------------------------------------

   1 - "A"."OBJECT_NAME"[VARCHAR2,128], "A"."LAST_DDL_TIME"[DATE,7],
       "B"."CREATED"[DATE,7]
   2 - "A"."OBJECT_NAME"[VARCHAR2,128], "A"."LAST_DDL_TIME"[DATE,7],
       "B".ROWID[ROWID,10]
   3 - "A"."OBJECT_NAME"[VARCHAR2,128], "A"."OBJECT_ID"[NUMBER,22],
       "A"."LAST_DDL_TIME"[DATE,7]
   4 - "A".ROWID[ROWID,10], "A"."OBJECT_ID"[NUMBER,22]
   5 - "B".ROWID[ROWID,10]
   6 - "B"."CREATED"[DATE,7]

Case-2 : optimizer_features_enable=10.2.0.3

In this case you will see 1  nested loops in the execution plan and new operation NLJ_BATCHING in missing in outline_data.

SQL> SELECT *   FROM   TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'ADVANCED'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  apzagcxrnwka8, child number 1
-------------------------------------
SELECT   A.OBJECT_NAME ,  A. LAST_DDL_TIME , B.CREATED FROM A, B WHERE
b.OBJECT_ID=a.OBJECT_ID  AND  a.OBJECT_ID BETWEEN 1 AND 30

Plan hash value: 1900124691

---------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |       |       |     5 (100)|          |
|   1 |  NESTED LOOPS                |        |     3 |   135 |     5   (0)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| A      |    16 |   512 |     3   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | IDX_A  |    16 |       |     2   (0)| 00:00:01 |
|   4 |   TABLE ACCESS BY INDEX ROWID| B      |     1 |    13 |     1   (0)| 00:00:01 |
|*  5 |    INDEX UNIQUE SCAN         | INDX_B |     1 |       |     0   (0)|          |
---------------------------------------------------------------------------------------

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

   1 - SEL$1
   2 - SEL$1 / A@SEL$1
   3 - SEL$1 / A@SEL$1
   4 - SEL$1 / B@SEL$1
   5 - SEL$1 / B@SEL$1

Outline Data
-------------

  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('10.2.0.3')
      DB_VERSION('11.2.0.2')
      OPT_PARAM('query_rewrite_enabled' 'false')
      FIRST_ROWS(10)
      OUTLINE_LEAF(@"SEL$1")
      INDEX_RS_ASC(@"SEL$1" "A"@"SEL$1" ("A"."OBJECT_ID"))
      INDEX_RS_ASC(@"SEL$1" "B"@"SEL$1" ("B"."OBJECT_ID"))
      LEADING(@"SEL$1" "A"@"SEL$1" "B"@"SEL$1")
      USE_NL(@"SEL$1" "B"@"SEL$1")
      END_OUTLINE_DATA
  */

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

   3 - access("A"."OBJECT_ID">=1 AND "A"."OBJECT_ID"<=30)
   5 - access("B"."OBJECT_ID"="A"."OBJECT_ID")
       filter(("B"."OBJECT_ID"<=30 AND "B"."OBJECT_ID">=1))

Column Projection Information (identified by operation id):
-----------------------------------------------------------

   1 - "A"."OBJECT_NAME"[VARCHAR2,128], "A"."LAST_DDL_TIME"[DATE,7],
       "B"."CREATED"[DATE,7]
   2 - "A"."OBJECT_NAME"[VARCHAR2,128], "A"."OBJECT_ID"[NUMBER,22],
       "A"."LAST_DDL_TIME"[DATE,7]
   3 - "A".ROWID[ROWID,10], "A"."OBJECT_ID"[NUMBER,22]
   4 - "B"."CREATED"[DATE,7]
   5 - "B".ROWID[ROWID,10]

63 rows selected.