Re: A potential bug (infinite loop) in Oracle: querying v$access

From: Charles Hooper <hooperc2000_at_yahoo.com>
Date: Wed, 23 Jan 2008 07:39:43 -0800 (PST)
Message-ID: <568ba835-3571-4fdd-8a4a-607d8b0f341b@x69g2000hsx.googlegroups.com>


On Jan 23, 7:58 am, Charles Hooper <hooperc2..._at_yahoo.com> wrote:
> On Jan 23, 12:23 am, Peter Teoh <htmldevelo..._at_gmail.com> wrote:
> > Making a long query:
>
> > 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.
>
> 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")
>
> Why are you attempting to run this SQL statement?
>
> A quick Google search finds this page:http://download-uk.oracle.com/docs/cd/B13789_01/server.101/b10755/dyn...
>
> V$ACCESS displays objects in the database that are currently locked
> and the sessions that are accessing them.
> Owner: Owner of the object
>
> Charles Hooper
> IT Manager/Oracle DBA
> K&M Machine-Fabricating, Inc.

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

Rwo 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

Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc Received on Wed Jan 23 2008 - 09:39:43 CST

Original text of this message