DBA Manual: DBA diagnostic tool-Event 10046 and 10053

DBA Note: a dba diagnostic tool-Event 10046 and 10053 friend from an optimization tool manufacturer sent a case request to assist in diagnosis, it is unacceptable that a friend's optimization tool can produce results in 10 minutes when executing an SQL query in the customer's environment, the same query can quickly obtain the output results in other environments. The database environment is 9.2.0.8. First, I obtained a 10046 trace file. After formatting with tkprof, the SQL output results are displayed. First, the SQL code is as follows: the Elapsed time of this SQL segment exceeds 600 seconds, and the Query mode logic read is also very high. It is obviously unacceptable for an optimization tool. The following trace file shows the SQL Execution Plan:

Rows     Row Source Operation-------  ---------------------------------------------------      0  NESTED LOOPS OUTER      0   NESTED LOOPS OUTER      0    NESTED LOOPS OUTER      0     NESTED LOOPS OUTER      0      NESTED LOOPS OUTER      0       NESTED LOOPS       0        NESTED LOOPS OUTER      0         NESTED LOOPS       0          NESTED LOOPS OUTER      0           NESTED LOOPS OUTER      0            NESTED LOOPS       0             NESTED LOOPS       0              NESTED LOOPS 1935557               NESTED LOOPS    2863                NESTED LOOPS    2863                 NESTED LOOPS    2863                  NESTED LOOPS       1                   NESTED LOOPS       1                    TABLE ACCESS BY INDEX ROWID USER$      1                     INDEX UNIQUE SCAN I_USER1 (object id 44)      1                    TABLE ACCESS BY INDEX ROWID USER$      1                     INDEX UNIQUE SCAN I_USER1 (object id 44)   2863                   TABLE ACCESS FULL CDEF$   2863                  TABLE ACCESS BY INDEX ROWID CON$   2863                   INDEX UNIQUE SCAN I_CON2 (object id 49)   2863                 TABLE ACCESS CLUSTER USER$   2863                  INDEX UNIQUE SCAN I_USER# (object id 11)1935557                VIEW 1935557                 UNION-ALL PARTITION1935557                  FILTER 1935557                   NESTED LOOPS    2863                    TABLE ACCESS BY INDEX ROWID USER$   2863                     INDEX UNIQUE SCAN I_USER1 (object id 44)1935557                    TABLE ACCESS FULL OBJ$      0                   TABLE ACCESS BY INDEX ROWID IND$      0                    INDEX UNIQUE SCAN I_IND1 (object id 39)      0                  FILTER       0                   NESTED LOOPS       0                    TABLE ACCESS BY INDEX ROWID USER$      0                     INDEX UNIQUE SCAN I_USER1 (object id 44)      0                    INDEX RANGE SCAN I_LINK1 (object id 113)      0               TABLE ACCESS BY INDEX ROWID CON$1935557                INDEX UNIQUE SCAN I_CON2 (object id 49)      0              TABLE ACCESS BY INDEX ROWID CON$      0               INDEX UNIQUE SCAN I_CON1 (object id 48)      0             TABLE ACCESS BY INDEX ROWID CDEF$      0              INDEX UNIQUE SCAN I_CDEF1 (object id 50)      0            TABLE ACCESS BY INDEX ROWID CON$      0             INDEX UNIQUE SCAN I_CON2 (object id 49)      0           TABLE ACCESS CLUSTER USER$      0            INDEX UNIQUE SCAN I_USER# (object id 11)      0          TABLE ACCESS BY INDEX ROWID OBJ$      0           INDEX UNIQUE SCAN I_OBJ1 (object id 36)      0         INDEX UNIQUE SCAN I_OBJ1 (object id 36)      0        TABLE ACCESS BY INDEX ROWID OBJ$      0         INDEX UNIQUE SCAN I_OBJ1 (object id 36)      0       TABLE ACCESS BY INDEX ROWID OBJ$      0        INDEX UNIQUE SCAN I_OBJ1 (object id 36)      0      TABLE ACCESS CLUSTER USER$      0       INDEX UNIQUE SCAN I_USER# (object id 11)      0     INDEX UNIQUE SCAN I_OBJ1 (object id 36)      0    TABLE ACCESS BY INDEX ROWID OBJ$      0     INDEX UNIQUE SCAN I_OBJ1 (object id 36)      0   TABLE ACCESS CLUSTER USER$      0    INDEX UNIQUE SCAN I_USER# (object id 11)

 

In the preceding execution plan, the most suspicious part is the full table scan of OBJ $. The number of rows returned in this step is 1,935,557 rows, and this magnitude is always passed up, therefore, we first suspect that the execution plan selection here is incorrect. If you select an index, the execution performance will certainly be significantly different. However, the information displayed by 10046 of tracking events is limited and cannot be accurately located. I ask a friend to use 10053 events to generate an execution plan tracking. 10053 is very easy to use, you can capture the SQL parsing process as follows:

Alter session set events '2014 trace name context forever, level 1'; explain plan for you_select_query; for example: SQL> alter session set events '2017 trace name context forever, level 1 '; session altered. SQL> explain plan for select count (*) from obj $; explain.

 

Then, in the udump directory, you can find the trace file generated by 10053. In this file, you can find the statistics of related tables. The OBJ $ information is as follows, specifically, CDN (CarDiNality) indicates the number of records contained in the table. Here, about 0.24 million records exist in the OBJ $ table and 2941 data blocks are used:

***********************Table stats    Table: OBJ$   Alias: SYS_ALIAS_1  TOTAL ::  CDN: 245313  NBLKS:  2941  AVG_ROW_LEN:  79Column:     OWNER#  Col#: 3      Table: OBJ$   Alias: SYS_ALIAS_1    NDV: 221       NULLS: 0         DENS: 4.5249e-03 LO:  0  HI: 259    NO HISTOGRAM: #BKT: 1 #VAL: 2-- Index stats  INDEX NAME: I_OBJ1  COL#: 1    TOTAL ::  LVLS: 1   #LB: 632  #DK: 245313  LB/K: 1  DB/K: 1  CLUF: 4184  INDEX NAME: I_OBJ2  COL#: 3 4 5 12 13 6    TOTAL ::  LVLS: 2   #LB: 1904  #DK: 245313  LB/K: 1  DB/K: 1  CLUF: 180286  INDEX NAME: I_OBJ3  COL#: 15    TOTAL ::  LVLS: 1   #LB: 19  #DK: 2007  LB/K: 1  DB/K: 1  CLUF: 340_OPTIMIZER_PERCENT_PARALLEL = 0***************************************

 

In the previous 10046 trace information, OBJ $ contains about 2 million records, which is a huge difference. For the USER $ table, 2863 records are displayed, statistics show only 253 records:

***********************Table stats    Table: USER$   Alias:  U  TOTAL ::  CDN: 253  NBLKS:  16  AVG_ROW_LEN:  82Column:      USER#  Col#: 1      Table: USER$   Alias:  U    NDV: 253       NULLS: 0         DENS: 3.9526e-03 LO:  0  HI: 261    NO HISTOGRAM: #BKT: 1 #VAL: 2-- Index stats  INDEX NAME: I_USER#  COL#: 1    TOTAL ::  LVLS: 0   #LB: 1  #DK: 258  LB/K: 1  DB/K: 1  CLUF: 13  INDEX NAME: I_USER1  COL#: 2    TOTAL ::  LVLS: 0   #LB: 1  #DK: 253  LB/K: 1  DB/K: 1  CLUF: 87***********************

 

This indicates that the statistical information recorded in the data dictionary is inconsistent with the actual situation, leading to the incorrect execution plan selected by the SQL statement. This situation is extremely common in the Oracle9i database using CBO, by deleting table statistics or collecting correct statistics, SQL Execution can be restored to a normal and reasonable level. Automatic statistical information collection starting at Oracle10g is to prevent the occurrence of obsolete statistical information. The following is a simple reference for clearing and re-collecting table statistics through the dbms_stats package:

SQL> exec dbms_stats.delete_table_stats(user,'OBJ$');PL/SQL procedure successfully completed.SQL> exec dbms_stats.gather_table_stats(user,'OBJ$');PL/SQL procedure successfully completed.

 

Based on this judgment, we suggest the customer make a correction. The final customer feedback result is: According to your suggestion, after updating the statistics of OBJ $, the statement execution time is reduced from 10 minutes to 2 minutes. Next, we updated the statistical information of the tables USER $, CON $, and CDEF $ according to similar ideas. At this time, the statement execution time was reduced to a few seconds at zero. Now, the problem is solved.