Re: A potential bug (infinite loop) in Oracle: querying v$access
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=0pw=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