Failure to Collect Fixed Object Statistics Leads to ORA-01013 or ORA-07445

9 12 2009

December 8, 2009 (note added December 9, 2009)

An interesting post from almost two years ago in the comp.databases.oracle.server Usenet group:
http://groups.google.com/group/comp.databases.oracle.server/browse_thread/thread/e0599d3e043fc199

select distinct name from all_source;

.......
SYS_YOID0000052452$
......
3196 rows selected.

Ok no problem.

select distinct owner from v$access
SQL> /
select distinct owner from v$access
                           *
ERROR at line 1:
ORA-01013: user requested cancel of current operation

I had to terminate it as it become non-terminating.

“select owner from v$access” returns a mere 193 rows, and it cannot sort it?

I suspect there is exists an infinite loop somewhere.

This was attempted on 10gR2, 11gR1 and both had the same problem.

How would someone start investigating this problem?  Find something that appears out of the ordinary, and start probing.  This is the approach that I used:

-

I was able to reproduce this problem on Oracle 10.2.0.2 with the Oracle October 2006 CPU on 64 bit Windows 2003.

From the udump trace file:

ksedmp: internal or fatal error
ORA-07445: exception encountered: core dump [ACCESS_VIOLATION]
[__intel_new_memcpy+610] [PC:0x3236532] [ADDR:0x0] [UNABLE_TO_READ] []
Current SQL statement for this session:
select distinct owner from v$access
----- Call Stack Trace -----
calling              call     entry                argument values in hex
location             type     point                (? means dubious value)
-------------------- -------- -------------------- ----------------------------
__intel_new_memcpy+           0000000000000000     000000000 000000000
0118AF5A0 610                                                7FF970C7598
000007FF95D155F0     CALL???  __intel_new_memcpy+  0000007FF 013DF42E8
001749686
                              610                  000000000
...

From a 10046 trace at level 8:

*** 2008-01-23 06:51:57.901
WAIT #3: nam='latch: library cache' ela= 8566 address=1398554576 number=214 tries=1 obj#=-1 tim=5204643696
WAIT #3: nam='latch: library cache' ela= 859 address=1398554576 number=214 tries=1 obj#=-1 tim=5205047765
WAIT #3: nam='latch: library cache' ela= 2958 address=1398554576 number=214 tries=1 obj#=-1 tim=5205183748
WAIT #3: nam='latch: library cache' ela= 551 address=1398554576 number=214 tries=1 obj#=-1 tim=5205267198
*** 2008-01-23 06:54:39.117
WAIT #3: nam='latch: library cache' ela= 813 address=1398554576 number=214 tries=1 obj#=-1 tim=5365848854
*** 2008-01-23 06:55:06.288
WAIT #3: nam='latch: library cache' ela= 30 address=1398554576 number=214 tries=1 obj#=-1 tim=5393019180
*** 2008-01-23 06:55:30.006
WAIT #3: nam='latch: library cache' ela= 68 address=1398554576 number=214 tries=1 obj#=-1 tim=5416746379
*** 2008-01-23 06:55:50.584
WAIT #3: nam='latch: library cache' ela= 33 address=1398554576 number=214 tries=1 obj#=-1 tim=5437323921
*** 2008-01-23 06:57:09.536
WAIT #3: nam='latch: library cache' ela= 111 address=1398554576 number=214 tries=1 obj#=-1 tim=5516279642
*** 2008-01-23 06:57:20.895
WAIT #3: nam='latch: library cache' ela= 77 address=1398554576 number=214 tries=1 obj#=-1 tim=5527627340
*** 2008-01-23 06:57:36.082
WAIT #3: nam='latch: library cache' ela= 246 address=1398554576 number=214 tries=1 obj#=-1 tim=5542815685
*** 2008-01-23 06:57:57.957
WAIT #3: nam='latch: library cache' ela= 123 address=1398554576 number=214 tries=1 obj#=-1 tim=5564704225
*** 2008-01-23 06:58:14.644
WAIT #3: nam='latch: library cache' ela= 63 address=1398554576 number=214 tries=1 obj#=-1 tim=5581385020
*** 2008-01-23 06:58:26.269
WAIT #3: nam='latch: library cache' ela= 62 address=1398554576 number=214 tries=1 obj#=-1 tim=5593004724
*** 2008-01-23 06:58:48.346
WAIT #3: nam='latch: library cache' ela= 42 address=1398554576 number=214 tries=1 obj#=-1 tim=5615094241
WAIT #3: nam='latch: library cache' ela= 8 address=1398554576 number=214 tries=1 obj#=-1 tim=5615168161
...

For an average 60 second interval interval, the session had the following latch statistics:

Latch         Child# Level   Gets  Misses  Sleeps  Sleeps1
LIBRARY CACHE    1       5   529418     25      0       25
LIBRARY CACHE    2       5   539720     36      0       36
LIBRARY CACHE    3       5   519189     15      0       15
LIBRARY CACHE    4       5   516501     55      0       55
LIBRARY CACHE    5       5   524907   1744      4     1740

On the waits, P1 is 13985, P2 is 214, P3 is 0, Buf is 99, SQL Hash is 3250939240.

SELECT
  SQL_TEXT
FROM
  V$SQL
WHERE
  HASH_VALUE=3250939240

SQL_TEXT
-----------------------------------
select distinct owner from v$access

 

SELECT
  ID,
  SUBSTR(OPERATION,1,12) OPERATION,
  SUBSTR(OPTIONS,1,12) OPTIONS,
  SUBSTR(OBJECT_OWNER||'.'||OBJECT_NAME,1,20) OBJECT,
  SUBSTR(OBJECT_TYPE,1,13) OBJECT_TYPE,
  PARENT_ID,
  DEPTH,
  POSITION,
  CPU_COST
FROM
  V$SQL_PLAN_STATISTICS_ALL
WHERE
  HASH_VALUE=3250939240
  AND CHILD_NUMBER=1
ORDER BY
  ID;

ID OPERATION    OPTIONS      OBJECT               OBJECT_TYPE PARENT_ID      DEPTH   POSITION   CPU_COST
-- ------------ ------------ -------------------- ------------- ---------- ---------- ---------- ----------
 1 HASH UNIQUE       .                                                  0          1          1    2142850
 2 NESTED LOOPS              .                                          1          2          1    1115000
 3 NESTED LOOPS              .                                          2          3          1    1080000
 4 MERGE JOIN CARTESIAN    .                                            3          4          1     730000
 5 FIXED TABLE  FULL         SYS.X$KSUSE          TABLE (FIXED)         4          5          1     380000
 6 BUFFER SORT         .                                                4          5          2     350000
 7 FIXED TABLE  FULL         SYS.X$KGLDP          TABLE (FIXED)         6          6          1     350000
 8 FIXED TABLE  FIXED INDEX  SYS.X$KGLLK (ind:1)  TABLE (FIXED)         3          4          2       3500
 9 FIXED TABLE  FIXED INDEX  SYS.X$KGLOB (ind:1)  TABLE (FIXED)         2          3          2       3500

 

SELECT
  ID,
  ACCESS_PREDICATES,
  FILTER_PREDICATES
FROM
  V$SQL_PLAN_STATISTICS_ALL
WHERE
  HASH_VALUE=3250939240
  AND CHILD_NUMBER=1
ORDER BY
  ID;

ID ACCESS_PREDICATES FILTER_PREDICATES
-- ----------------- -----------------
 1
 2
 3
 4
 5                   "S"."INST_ID"=USERENV('INSTANCE')
 6
 7
 8                   ("L"."KGLLKUSE"="S"."ADDR" AND "L"."KGLLKHDL"="D"."KGLHDADR" AND "L"."KGLNAHSH"="D"."KGLNAHSH")
 9                   ("O"."KGLNAHSH"="D"."KGLRFHSH" AND "O"."KGLHDADR"="D"."KGLRFHDL")


Then check a different server:

The query eventually completed on the 32 bit version of Oracle 10.2.0.2 with the Oracle October 2006 CPU.

PARSE 1|CPU S     0.000000|CLOCK S    0.006227|ROWs 0
EXEC  1|CPU S     0.000000|CLOCK S    0.000201|ROWs 0
FETCH 2|CPU S 13112.828125|CLOCK S  926.981803|ROWs 6

Row Source Execution Plan:
       (Rows 6)   HASH UNIQUE (cr=0 pr=0 pw=0 time=568347223 us)
    (Rows 3463)    NESTED LOOPS  (cr=0 pr=0 pw=0 time=3464796755 us)
    (Rows 3463)     NESTED LOOPS  (cr=0 pr=0 pw=0 time=3464592419 us)
 (Rows 1613768)      MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=21019488 us)
     (Rows 236)       FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=2376 us)
 (Rows 1613768)       BUFFER SORT (cr=0 pr=0 pw=0 time=12951356 us)
    (Rows 6838)        FIXED TABLE FULL X$KGLDP (cr=0 pr=0 pw=0 time=41073 us)
    (Rows 3463)      FIXED TABLE FIXED INDEX X$KGLLK (ind:1) (cr=0 pr=0 pw=0 time=13094082350 us)
    (Rows 3463)     FIXED TABLE FIXED INDEX X$KGLOB (ind:1) (cr=0 pr=0 pw=0 time=166548 us)

Note the merge Cartesian join between the 236 rows in X$KSUSE and the 1613768 rows from X$KGLDP.

The wait events:
0.03 seconds on latch: library cache

Then keep probing:

I may have found something that may help the OP – it hit me when I found very slow performance with the same SQL statement on 32 bit Oracle 10.2.0.3 and 11.1.0.6, after looking at the DBMS_XPLANs.

The DBMS_XPLAN on 10.2.0.3:

--------------------------------------------------------------------------­----------------------------------------------
| Id  | Operation                  | Name            | Starts | E-Rows | A-Rows |   A-Time   |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------­----------------------------------------------
|   1 |  HASH UNIQUE               |                 |      1 |    105 |      5 |00:02:51.06 |       |       |          |
|   2 |   NESTED LOOPS             |                 |      1 |    105 |   1131 |00:02:51.04 |       |       |          |
|   3 |    NESTED LOOPS            |                 |      1 |     10 |   1131 |00:02:50.39 |       |       |          |
|   4 |     MERGE JOIN CARTESIAN   |                 |      1 |    100 |    180K|00:00:01.27 |       |       |          |
|*  5 |      FIXED TABLE FULL      | X$KSUSE         |      1 |      1 |    236 |00:00:00.01 |       |       |          |
|   6 |      BUFFER SORT           |                 |    236 |    100 |    180K|00:00:00.55 | 36864 | 36864 |32768  (0)|
|   7 |       FIXED TABLE FULL     | X$KGLDP         |      1 |    100 |    763 |00:00:00.01 |       |       |          |
|*  8 |     FIXED TABLE FIXED INDEX| X$KGLLK (ind:1) |    180K|      1 |   1131 |00:02:48.31 |       |       |          |
|*  9 |    FIXED TABLE FIXED INDEX | X$KGLOB (ind:1) |   1131 |     10 |   1131 |00:00:00.64 |       |       |          |
--------------------------------------------------------------------------­----------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   5 - filter("S"."INST_ID"=USERENV('INSTANCE'))
   8 - filter(("L"."KGLLKUSE"="S"."ADDR" AND "L"."KGLLKHDL"="D"."KGLHDADR" AND "L"."KGLNAHSH"="D"."KGLNAHSH"))
   9 - filter(("O"."KGLNAHSH"="D"."KGLRFHSH" AND "O"."KGLHDADR"="D"."KGLRFHDL"))

 
Note the MERGE JOIN CARTESIAN, and how the estimated rows compares with the actual rows.

The DBMS_XPLAN on 11.1.0.6:

select distinct owner from v$access 

--------------------------------------------------------------------------­-----------------------------------------------
| Id  | Operation                   | Name            | Starts | E-Rows | A-Rows |   A-Time   |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------­-----------------------------------------------
|   1 |  HASH UNIQUE                |                 |      1 |      1 |      6 |00:00:40.28 |   951K|   951K|  860K (0)|
|   2 |   NESTED LOOPS              |                 |      1 |      1 |   2342 |00:00:40.27 |       |       |          |
|   3 |    MERGE JOIN CARTESIAN     |                 |      1 |      1 |   2842K|00:00:11.37 |       |       |          |
|   4 |     NESTED LOOPS            |                 |      1 |      1 |  16721 |00:00:00.38 |       |       |          |
|   5 |      FIXED TABLE FULL       | X$KGLDP         |      1 |    100 |  16721 |00:00:00.05 |       |       |          |
|*  6 |      FIXED TABLE FIXED INDEX| X$KGLOB (ind:1) |  16721 |      1 |  16721 |00:00:00.21 |       |       |          |
|   7 |     BUFFER SORT             |                 |  16721 |      1 |   2842K|00:00:02.91 |  4096 |  4096 | 4096  (0)|
|*  8 |      FIXED TABLE FULL       | X$KSUSE         |      1 |      1 |    170 |00:00:00.01 |       |       |          |
|*  9 |    FIXED TABLE FIXED INDEX  | X$KGLLK (ind:1) |   2842K|      1 |   2342 |00:00:15.49 |       |       |          |
--------------------------------------------------------------------------­-----------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   6 - filter(("O"."KGLNAHSH"="D"."KGLRFHSH" AND "O"."KGLHDADR"="D"."KGLRFHDL"))
   8 - filter("S"."INST_ID"=USERENV('INSTANCE'))
   9 - filter(("L"."KGLLKUSE"="S"."ADDR" AND "L"."KGLLKHDL"="D"."KGLHDADR" AND "L"."KGLNAHSH"="D"."KGLNAHSH"))

The above executed more quickly, and the plan is slightly different, but the MERGE JOIN CARTESIAN is still present, as is the difference between the estimated and actual number of rows.

The fixed object stats must be wrong (I recall having a problem with that a couple years ago when perfoming the following)…

SQL> CONNECT / AS SYSDBA
SQL> EXEC DBMS_STATS.GATHER_FIXED_OBJECTS_STATS('ALL');
BEGIN DBMS_STATS.GATHER_FIXED_OBJECTS_STATS('ALL'); END;

*
ERROR at line 1:
ORA-20000: Insufficient privileges to analyze an object in Fixed Ob
ORA-06512: at "SYS.DBMS_STATS", line 17951
ORA-06512: at "SYS.DBMS_STATS", line 18404
ORA-06512: at "SYS.DBMS_STATS", line 18951
ORA-06512: at line 1

The same error occurs on Oracle 10.2.0.2, 10.2.0.3, and 11.1.0.6 as the internal user, SYS AS SYSDBA, and SYSTEM.

There must be another way:

SQL> EXEC DBMS_STATS.GATHER_SCHEMA_STATS('SYS',GATHER_FIXED=>TRUE)

PL/SQL PROCEDURE SUCCESSFULLY COMPLETED.

The new DBMS_XPLANs:
10.2.0.3:

--------------------------------------------------------------------------­---------------------------------------------
| Id  | Operation                 | Name            | Starts | E-Rows | A-Rows |   A-Time   |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------­---------------------------------------------
|   1 |  HASH UNIQUE              |                 |      1 |      7 |      4 |00:00:00.09 |       |       |          |
|   2 |   NESTED LOOPS            |                 |      1 |   1822 |   1003 |00:00:00.08 |       |       |          |
|*  3 |    HASH JOIN              |                 |      1 |   1822 |   1003 |00:00:00.05 |   898K|   898K| 1099K (0)|
|*  4 |     HASH JOIN             |                 |      1 |   1822 |   1897 |00:00:00.03 |  1010K|  1010K|  639K (0)|
|*  5 |      FIXED TABLE FULL     | X$KSUSE         |      1 |    236 |    236 |00:00:00.01 |       |       |          |
|   6 |      FIXED TABLE FULL     | X$KGLLK         |      1 |   1822 |   1897 |00:00:00.01 |       |       |          |
|   7 |     FIXED TABLE FULL      | X$KGLDP         |      1 |   2892 |    649 |00:00:00.01 |       |       |          |
|*  8 |    FIXED TABLE FIXED INDEX| X$KGLOB (ind:1) |   1003 |      1 |   1003 |00:00:00.01 |       |       |          |
--------------------------------------------------------------------------­---------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("L"."KGLLKHDL"="D"."KGLHDADR" AND "L"."KGLNAHSH"="D"."KGLNAHSH")
   4 - access("L"."KGLLKUSE"="S"."ADDR")
   5 - filter("S"."INST_ID"=USERENV('INSTANCE'))
   8 - filter(("O"."KGLNAHSH"="D"."KGLRFHSH" AND "O"."KGLHDADR"="D"."KGLRFHDL"))

The MERGE JOIN CARTESIAN is gone and the execution time dropped from 2 minutes, 51 seconds to 0.09 seconds.

11.1.0.6:

--------------------------------------------------------------------------­----------------------------------------------
| Id  | Operation                  | Name            | Starts | E-Rows | A-Rows |   A-Time   |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------­----------------------------------------------
|   1 |  HASH UNIQUE               |                 |      1 |     19 |      1 |00:00:00.04 |  1037K|  1037K|  368K (0)|
|   2 |   NESTED LOOPS             |                 |      1 |   1139 |    134 |00:00:00.04 |       |       |          |
|   3 |    NESTED LOOPS            |                 |      1 |   1139 |    134 |00:00:00.03 |       |       |          |
|*  4 |     HASH JOIN              |                 |      1 |   1139 |   1144 |00:00:00.02 |  1010K|  1010K| 1205K (0)|
|*  5 |      FIXED TABLE FULL      | X$KSUSE         |      1 |    170 |    170 |00:00:00.01 |       |       |          |
|   6 |      FIXED TABLE FULL      | X$KGLLK         |      1 |   1139 |   1144 |00:00:00.01 |       |       |          |
|*  7 |     FIXED TABLE FIXED INDEX| X$KGLDP (ind:1) |   1144 |      1 |    134 |00:00:00.01 |       |       |          |
|*  8 |    FIXED TABLE FIXED INDEX | X$KGLOB (ind:1) |    134 |      1 |    134 |00:00:00.01 |       |       |          |
--------------------------------------------------------------------------­----------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("L"."KGLLKUSE"="S"."ADDR")
   5 - filter("S"."INST_ID"=USERENV('INSTANCE'))
   7 - filter(("L"."KGLLKHDL"="D"."KGLHDADR" AND "L"."KGLNAHSH"="D"."KGLNAHSH"))
   8 - filter(("O"."KGLNAHSH"="D"."KGLRFHSH" AND "O"."KGLHDADR"="D"."KGLRFHDL"))

The MERGE JOIN CARTESIAN is gone and the execution time dropped from 40.28 seconds to 0.04 seconds.

The OP may be able to run the same DBMS_STATS.GATHER_SCHEMA_STATS procedure to work around the problem.

How to determine if I collected statistics on the fixed tables?  A search on Metalink found this article from 2004:
https://metalink.oracle.com/metalink/plsql/f%3Fp%3D200:27:5000154048035945504::::p27_id,p27_show_header,p27_show_help:525959.996,1,1&usg=AFQjCNHJ_wI9tlazsGQ7AIUZ5RSlrp_8nw
(Edit: Note that the above link is gone in a Flash  If anyone is able to find the message on the Oracle support site -the site  formerly known as Metalink, please let me know of the address.)

In the article, Jonathan Lewis mentioned that tab_stats$ could be checked.
Test database on 64 bit Windows:

SELECT
  *
FROM
  SYS.TAB_STATS$

The above returned about 582 rows after running:

EXEC DBMS_STATS.GATHER_SCHEMA_STATS('SYS',GATHER_FIXED=>TRUE);

I then checked a production database, and found no rows returned. Using the suggestion from the Metalink article:

EXEC DBMS_STATS.GATHER_FIXED_OBJECTS_STATS(NULL);

The stats collection completed much more quickly, as it did not analyze the full SYS schema, and there were 582 rows returned by the query on SYS.TAB_STATS$.  It looks like this simple query may be used to determine if fixed object statistics need to be collected.


Actions

Information

6 responses

4 05 2011
Alexander

Hi!

Could you explain please how you found hv=3250939240 ?
Thanks.

4 05 2011
Charles Hooper

Alexander,

It has been a couple of years, but it appears that I performed the following steps:

SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
 
Session altered.
 
SQL> select distinct owner from v$access
  2  /
 
SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

Then I looked inside the 10046 trace file and found my SQL statement:

=====================
PARSING IN CURSOR #1 len=35 dep=0 uid=31 oct=3 lid=31 tim=3112364669 hv=3250939240 ad='8135a590'
select distinct owner from v$access
END OF STMT
PARSE #1:c=15625,e=10795,p=0,cr=4,cu=0,mis=1,r=0,dep=0,og=1,tim=3112364664
EXEC #1:c=0,e=138,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3112365290
WAIT #1: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3112365434
FETCH #1:c=1078125,e=1078741,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=3113444285
WAIT #1: nam='SQL*Net message from client' ela= 400 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3113445654
WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3113445934
FETCH #1:c=0,e=113,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,tim=3113446026
WAIT #1: nam='SQL*Net message from client' ela= 1938 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3113448064
WAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3113448214
FETCH #1:c=0,e=105,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,tim=3113448309
WAIT #1: nam='SQL*Net message from client' ela= 2643 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3113451047
WAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3113451191
FETCH #1:c=15625,e=132,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,tim=3113451316
WAIT #1: nam='SQL*Net message from client' ela= 2987 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3113454763
FETCH #1:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3113454938
WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3113455065
WAIT #1: nam='SQL*Net message from client' ela= 1777 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3113456919
STAT #1 id=1 cnt=46 pid=0 pos=1 obj=0 op='SORT UNIQUE (cr=0 pr=0 pw=0 time=1078756 us)'
STAT #1 id=2 cnt=42462 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=0 pr=0 pw=0 time=1142988 us)'
STAT #1 id=3 cnt=335 pid=2 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=362 us)'
STAT #1 id=4 cnt=42462 pid=2 pos=2 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=1056455 us)'
STAT #1 id=5 cnt=42462 pid=4 pos=1 obj=0 op='HASH JOIN  (cr=0 pr=0 pw=0 time=334562 us)'
STAT #1 id=6 cnt=21082 pid=5 pos=1 obj=0 op='FIXED TABLE FULL X$KGLLK (cr=0 pr=0 pw=0 time=21506 us)'
STAT #1 id=7 cnt=100382 pid=5 pos=2 obj=0 op='FIXED TABLE FULL X$KGLDP (cr=0 pr=0 pw=0 time=200900 us)'
STAT #1 id=8 cnt=42462 pid=4 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KGLOB (ind:1) (cr=0 pr=0 pw=0 time=637605 us)'
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3113457700
*** 2011-05-04 07:52:59.140
WAIT #0: nam='SQL*Net message from client' ela= 11023640 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3124481452
=====================

The first line shows: PARSING IN CURSOR #1 … hv=3250939240 ad=’8135a590′. The value that follows hv= is the hash value for the SQL statement. I just noticed that the blog article implies that the hash value is found on the WAIT lines, but that was not the intention of this comment (I worded this poorly) “On the waits, P1 is 13985, P2 is 214, P3 is 0, Buf is 99, SQL Hash is 3250939240″.

A multi-part series on 10046 trace files may be found here:

http://hoopercharles.wordpress.com/2009/12/01/10046-extended-sql-trace-interpretation/

6 05 2011
Alexander

Hi, Charles!
Thank you for reply!
Link, you gave me, was very usefull!
Let me ask you a question that I’d realy like to now. From time to time I see in my ASH reports ”latch: library cache” and “latch: shared pool”. Is it possible to track cause of such events using P1 from ASH report?
I played with “raw 10046″, dump library cache, but can’t find the way I can use P1 to find out “library cache object” waited for. Where I’ve lost ?
From your example:
WAIT #3: nam=’latch: library cache’ ela= 8566 address=1398554576 number=214 tries=1 obj#=-1 tim=5204643696
…so,
P1 = address = 1398554576
What is it use of that “address”? How can I found the root of problem?

Regards

6 05 2011
Charles Hooper

I will state up front that I do not have the final answer – other people are welcome to offer their advice.

You might try a quick SQL statement:

SELECT
  ADDR,
  LATCH#,
  NAME
FROM
  V$LATCH
WHERE
  NAME = 'library cache';

My output looks like this:

ADDR                 LATCH# NAME
---------------- ---------- -------------
00000000047A5FF0        214 library cache

I believe that you will find that if you convert the number 1398554576 found in the wait event to a hex number, it will be the same number as is what is displayed in the ADDR column of the above SQL statement. So, that probably did not help much. The wait time on that latch seems to be a little long at 0.008566 seconds – is it possible that the CPU utilization was atypically high on the server?

You might take a look at the following presentation that was created by Kyle Hailey – there are notes attached to some of the slides: http://www.perfvision.com/papers/10_libc.ppt

My notes on library cache and shared pool latches follow. The notes are mostly paraphrases from the Oracle documentation, for instance from the following page:

http://download.oracle.com/docs/cd/B19306_01/server.102/b14211/instance_tune.htm#sthref787

p1 (address) is the address of the latch, p2 (number) is the latch number, p3 (tries) is the number of times the process has slept waiting for the latch
A main cause of shared pool or library cache latch contention is parsing. For shared pool and library cache latches, possible causes include not using bind variables, insufficient size of application cursor cache, cursors closed explicitly after each execution, frequent log on/off, shared pool too small.

Examine the resource usage for related resources. For example, if the library cache latch is heavily contended for, then examine the hard and soft parse rates.
Examine the SQL statements for the sessions experiencing latch contention to see if there is any commonality.

For Shared pool,library cache
** Lack of statement reuse, Statements not using bind variables, Insufficient size of application cursor cache,
** Cursors closed explicitly after each execution, Frequent logon / logoffs,
** Underlying object structure being modified (for example truncate), Shared pool too small
* Look for:
** Sessions (in V$SESSTAT) with high:
** parse time CPU
** parse time elapsed
** Ratio of parse count (hard) / Execute Count
** Ratio of parse count (total) / Execute Count
* Cursors (in V$SQLAREA/V$SQLSTATS) with:
** High ratio of PARSE_CALLS / EXECUTIONS
** EXECUTIONS = 1 differing only in literals in the WHERE clause (that is, no bind variables used)
** High RELOADS
** High INVALIDATIONS
** Large (> 1mb) SHARABLE_MEM

You might be able to break the numbers down a little more by examining V$LATCH_CHILDREN:

SQL> DESC V$LATCH_CHILDREN
 Name
 -------------------------

 ADDR
 LATCH#
 CHILD#
 LEVEL#
 NAME
 HASH
 GETS
 MISSES
 SLEEPS
 IMMEDIATE_GETS
 IMMEDIATE_MISSES
 WAITERS_WOKEN
 WAITS_HOLDING_LATCH
 SPIN_GETS
 SLEEP1
 SLEEP2
 SLEEP3
 SLEEP4
 SLEEP5
 SLEEP6
 SLEEP7
 SLEEP8
 SLEEP9
 SLEEP10
 SLEEP11
 WAIT_TIME
10 05 2011
Alexander

Hi, Charles!
Thank you for answer!

OK, all those rules like decreasing parsing, using proper binds etc. it’s common investigation.
We can dig in it any time on running database, shooting SQLs using literals, or searching through v$sql_shared_cursors to find SQLs with non-shareable binds (due to changes in session’s nls settings etc)…
But the question, I’ve tried to understand is Why ASH reports shows us “latch: library cache” with P1, P2, P3. What use of those ones?
We are talking about events occurred in past time. How P1 could be useful for investigation? The only way I found to use it is query like:

select distinct sql_id from V$ACTIVE_SESSION_HISTORY
where sample_time between
to_timestamp(…..) and to_timestamp(…..) and
event = ‘latch: shared pool’ and
p1 = &P1 and
sql_id is not null;

But, again, what all those queries (we’ve found with above query) waiting for? Are they waiting just for allocating memory piece by P1 address? Why for this address? Short of shared memory?…

Best regards.

10 05 2011
Charles Hooper

I believe that the P1 and P2 values (p1 (address) is the address of the latch, p2 (number) is the latch number) were retained with identical meaning when the “latch free” wait event was broken into multiple wait events in Oracle Database 10g. The p1 and p2 values of the “latch free” wait event were used to identify specifically which type of latch is causing delays. From the Oracle Database 9.2 Performance Tuning Guide, a SQL statement demonstrating the use of p2:

http://download.oracle.com/docs/cd/B10500_01/server.920/a96533/instance_tune.htm#12946

SELECT n.name, SUM(w.p3) Sleeps
FROM V$SESSION_WAIT w, V$LATCHNAME n
WHERE w.event = 'latch free'
AND w.p2 = n.latch#
GROUP BY n.name;

With the consideration of the above, the only meaningful piece of information provided, other than the specific latch name, is the number of sleeps while waiting for the latch to become available (p3 (tries) is the number of times the process has slept waiting for the latch).

There are a number of causes for shared pool latch contention and library cache latch contention. A couple of resources:

http://jonathanlewis.wordpress.com/2007/01/21/shared-sql/

http://jonathanlewis.wordpress.com/2008/12/23/library-cache/

http://jonathanlewis.wordpress.com/2007/01/05/bind-variables/

Also see discussion by Mark Bobak and Jonathan Lewis:

http://forums.oracle.com/forums/thread.jspa?messageID=9432629&tstart=0

—-
I am sure that you are aware, but I thought that it would good to mention for anyone else reading this article, that access to V$ACTIVE_SESSION_HISTORY and/or access to ASH and/or access to AWR and/or access to ADDM requires an Enterprise Edition license plus a Diagnostic Pack license.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 140 other followers

%d bloggers like this: