This discussion is archived
1 2 Previous Next 28 Replies Latest reply: Jun 2, 2008 11:47 AM by Aravind N RSS

Query Hangs while Parsing

Aravind N Newbie
Currently Being Moderated
In one of our databases, one of the Select query hangs at the parsing stage. The query was working fine few days back. How and what can be traced to see the cause of this hang. Database is in 10.2.0.3 and statistics has been gathered for all the affected tables.
  • 1. Re: Query Hangs while Parsing
    639056 Newbie
    Currently Being Moderated
    >>Select query hangs at the parsing stage.

    How are you able to say that it hangs at "parsing" stage ? parsing stage is internal to Oracle. I feel its a problem with the query performance.

    Please paste the query including the execution plan.
  • 2. Re: Query Hangs while Parsing
    26741 Oracle ACE
    Currently Being Moderated
    Query V$SESSION_WAIT for SEQ#, EVENT, STATUS, P1,P2,P3 for the session
    attempting to run the query. Collect a few snapshots from v$SESSION_WAIT,
    sampling every 1-5seconds for about 30seconds. (query by SID which is the
    same as the SID in V$SESSION).
  • 3. Re: Query Hangs while Parsing
    Aman.... Oracle ACE
    Currently Being Moderated
    Enable 10046 for the query and paste the raw file results here.
    Aman....
  • 4. Re: Query Hangs while Parsing
    Aravind N Newbie
    Currently Being Moderated
    Hi,

    The Query is working when I give an ORDERED hint. I cannot take the explain plan as well because the query hangs for that as well. This is one of the reasons why i say it hangs at parse level. The wait event shows the event before the query was issued and i guess it changes only when query starts getting executed.

    The Query is

    SELECT p.modelrunseq, m.periodseq, m.NAME,
    SUM (m.VALUE) aggregation,
    MAX (m.unittypeforvalue) unittypeforvalue,
    COUNT (m.measurementseq) quantity
    FROM cs_measurement m, cs_pipelinerun p, cs_stagesummary ss
    WHERE p.pipelinerunseq = 20547673299879672
    AND p.periodseq = m.periodseq
    AND m.measurementseq < 18014398509501136
    AND m.pipelinerunseq = ss.pipelinerunseq
    AND ss.stagetypeseq = 21673573206720517
    and isactive=1
    GROUP BY p.modelrunseq, m.periodseq, ROLLUP (m.NAME)


    ---------- ---------- ---------------------------------------------------------------- ----------
    P1TEXT P2 P2TEXT
    ---------------------------------------------------------------- ---------- ----------------------------------------------------------------
    P3 P3TEXT STATE
    ---------- ---------------------------------------------------------------- -------------------
    81 23 SQL*Net message from client 1650815232
    driver id 1 #bytes
    0 WAITED KNOWN TIME
  • 5. Re: Query Hangs while Parsing
    Aravind N Newbie
    Currently Being Moderated
    I tried reducing teh values of optimizermax_permutations (currently 79999) , no help. Also tried adjusting optimizer_index_cost_adj, but didnt help.
  • 6. Re: Query Hangs while Parsing
    Aman.... Oracle ACE
    Currently Being Moderated
    If I remember correctly.OPTIMIZER_MAX_PERMUTATIONS is already set to 2000 in 10g instead of 80000 as compared to 9i.You must had not changed the value of this parameter in the first place.
    The optimizer_index_cost_adj is also not need to be touched especially in 10g.
    I am not sure that is there any relation between the hang of the query.These two are basically used to opmtimize the query.If the query is hanging,there must be some wait happening at some step in the query.That's why Hemant asked you to check V$session_wait to see that whether there is any wait happening for the session.And that's why I asked you to enable 10046 trace as it "reveals out" what's really happening in the query.
    Search this forum for 10046 trace and how to enable it.Run your query after enabling it and than post the raw trace file which will be in the user_dump_dest folder.
    Aman....
  • 7. Re: Query Hangs while Parsing
    316993 Pro
    Currently Being Moderated
    run yours sql at sql with enable trace level 12.
    SQL>alter session set events '10046 trace name context forever,level 8'
    /
    SQL>run yours query
    If it hangs then wait patiently let execute the sql completly.

    SQL>disconnect

    from OS then run tkprof result of this newly sql trace file which will be created at udump folder.
    tkprof <tracefilename.trc> <textfilename.txt> sys=no explain=username/passwd
    Paste the result of tkprof result textfilename.txt contents here.

    Khurram
  • 8. Re: Query Hangs while Parsing
    26741 Oracle ACE
    Currently Being Moderated
    If the only difference was the presence/absence of the ORDERED hint,
    then the session without the Hint would be doing something -- doing reads etc

    When querying V$SESSION_WAIT, look at this view repeatedly to see
    if the event is changing (look at SEQ#).

    OR
    use Aman's suggestion and enable 10046 trace in the session before
    you submit the query. You could run a dummy 'select x from dual' to
    ensure that oracle does start writing to the trace before actually
    submitting this query.
  • 9. Re: Query Hangs while Parsing
    Aravind N Newbie
    Currently Being Moderated
    Thanks for the info. The SEQ# is not changing in the v$session_waits. I have found a workaround for this problem. If I delete the statistics for CS_MEASUREMENT table, the query gets executed in .35 secs! If i collect stats again and runs, it hangs.

    The session trace below.

    TKPROF: Release 10.2.0.3.0 - Production on Fri May 30 11:43:02 2008

    Copyright (c) 1982, 2005, Oracle. All rights reserved.

    Trace file: css1cldr_ora_10134.trc
    Sort options: default

    ********************************************************************************
    count = number of times OCI procedure was executed
    cpu = cpu time in seconds executing
    elapsed = elapsed time in seconds executing
    disk = number of physical reads of buffers from disk
    query = number of buffers gotten for consistent read
    current = number of buffers gotten in current mode (usually for update)
    rows = number of rows processed by the fetch or execute call
    ********************************************************************************

    select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,
    i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,
    i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,
    nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),
    i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),
    nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,
    null,mod(trunc(i.pctthres$/256),256)),ist.cachedblk,ist.cachehit,
    ist.logicalread
    from
    ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,
    min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4)))
    valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where
    i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.01 0.00 0 0 0 0
    Execute 3 0.01 0.01 0 0 0 0
    Fetch 10 0.00 0.00 0 33 0 7
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 14 0.02 0.02 0 33 0 7

    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: CHOOSE
    Parsing user id: SYS (recursive depth: 1)

    Rows Row Source Operation
    ------- ---------------------------------------------------
    2 SORT ORDER BY (cr=10 pr=0 pw=0 time=2852 us)
    2 HASH JOIN OUTER (cr=10 pr=0 pw=0 time=2741 us)
    2 NESTED LOOPS OUTER (cr=7 pr=0 pw=0 time=102 us)
    2 TABLE ACCESS CLUSTER IND$ (cr=5 pr=0 pw=0 time=73 us)
    1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=29 us)(object id 3)
    0 TABLE ACCESS BY INDEX ROWID IND_STATS$ (cr=2 pr=0 pw=0 time=22 us)
    0 INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=2 pr=0 pw=0 time=18 us)(object id 711)
    2 VIEW (cr=3 pr=0 pw=0 time=361 us)
    2 SORT GROUP BY (cr=3 pr=0 pw=0 time=356 us)
    2 TABLE ACCESS CLUSTER CDEF$ (cr=3 pr=0 pw=0 time=58 us)
    1 INDEX UNIQUE SCAN I_COBJ# (cr=2 pr=0 pw=0 time=25 us)(object id 30)

    ********************************************************************************

    select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#,
    sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,
    spare1, spare2, avgcln
    from
    hist_head$ where obj#=:1 and intcol#=:2


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.00 0.00 0 0 0 0
    Execute 50 0.01 0.00 0 0 0 0
    Fetch 50 0.00 0.00 0 150 0 50
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 101 0.01 0.01 0 150 0 50

    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: RULE
    Parsing user id: SYS (recursive depth: 2)

    Rows Row Source Operation
    ------- ---------------------------------------------------
    1 TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=0 pw=0 time=81 us)
    1 INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=57 us)(object id 257)

    ********************************************************************************

    select /*+ rule */ bucket, endpoint, col#, epvalue
    from
    histgrm$ where obj#=:1 and intcol#=:2 and row#=:3 order by bucket


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.00 0.00 0 0 0 0
    Execute 60 0.03 0.01 0 0 0 0
    Fetch 60 0.01 0.00 0 206 0 973
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 121 0.04 0.02 0 206 0 973

    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: RULE
    Parsing user id: SYS (recursive depth: 2)

    Rows Row Source Operation
    ------- ---------------------------------------------------
    3 SORT ORDER BY (cr=3 pr=0 pw=0 time=130 us)
    3 TABLE ACCESS CLUSTER HISTGRM$ (cr=3 pr=0 pw=0 time=66 us)
    1 INDEX UNIQUE SCAN I_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=27 us)(object id 252)


    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total Waited
    ---------------------------------------- Waited ---------- ------------
    SQL*Net message to client 1 0.00 0.00
    SQL*Net message from client 1 10.13 10.13
    ********************************************************************************

    select pos#,intcol#,col#,spare1,bo#,spare2
    from
    icol$ where obj#=:1


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.00 0.00 0 0 0 0
    Execute 7 0.01 0.00 0 0 0 0
    Fetch 25 0.00 0.00 0 50 0 18
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 33 0.01 0.00 0 50 0 18

    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: CHOOSE
    Parsing user id: SYS (recursive depth: 1)

    Rows Row Source Operation
    ------- ---------------------------------------------------
    2 TABLE ACCESS BY INDEX ROWID ICOL$ (cr=6 pr=0 pw=0 time=36 us)
    2 INDEX RANGE SCAN I_ICOL1 (cr=4 pr=0 pw=0 time=38 us)(object id 40)

    ********************************************************************************

    select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,
    nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,
    scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,
    rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,
    nvl(spare3,0)
    from
    col$ where obj#=:1 order by intcol#


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.00 0.00 0 0 0 0
    Execute 3 0.00 0.01 0 0 0 0
    Fetch 87 0.00 0.00 0 11 0 84
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 91 0.00 0.01 0 11 0 84

    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: CHOOSE
    Parsing user id: SYS (recursive depth: 1)

    Rows Row Source Operation
    ------- ---------------------------------------------------
    12 SORT ORDER BY (cr=3 pr=0 pw=0 time=157 us)
    12 TABLE ACCESS CLUSTER COL$ (cr=3 pr=0 pw=0 time=79 us)
    1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=24 us)(object id 3)

    ********************************************************************************

    select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
    from
    objauth$ where obj#=:1 and col# is not null group by privilege#, col#,
    grantee# order by col#, grantee#


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.00 0.00 0 0 0 0
    Execute 3 0.00 0.00 0 0 0 0
    Fetch 3 0.00 0.00 0 6 0 0
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 7 0.00 0.00 0 6 0 0

    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: CHOOSE
    Parsing user id: SYS (recursive depth: 1)

    Rows Row Source Operation
    ------- ---------------------------------------------------
    0 SORT GROUP BY (cr=2 pr=0 pw=0 time=57 us)
    0 TABLE ACCESS BY INDEX ROWID OBJAUTH$ (cr=2 pr=0 pw=0 time=34 us)
    0 INDEX RANGE SCAN I_OBJAUTH1 (cr=2 pr=0 pw=0 time=31 us)(object id 103)

    ********************************************************************************

    select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))
    from
    objauth$ where obj#=:1 group by grantee#,privilege#,nvl(col#,0) order by
    grantee#


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.00 0.00 0 0 0 0
    Execute 3 0.00 0.00 0 0 0 0
    Fetch 18 0.00 0.00 0 12 0 15
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 22 0.00 0.00 0 12 0 15

    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: CHOOSE
    Parsing user id: SYS (recursive depth: 1)

    Rows Row Source Operation
    ------- ---------------------------------------------------
    5 SORT GROUP BY (cr=4 pr=0 pw=0 time=107 us)
    5 TABLE ACCESS BY INDEX ROWID OBJAUTH$ (cr=4 pr=0 pw=0 time=43 us)
    5 INDEX RANGE SCAN I_OBJAUTH1 (cr=2 pr=0 pw=0 time=16 us)(object id 103)

    ********************************************************************************

    select con#,obj#,rcon#,enabled,nvl(defer,0)
    from
    cdef$ where robj#=:1


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.00 0.00 0 0 0 0
    Execute 3 0.01 0.00 0 0 0 0
    Fetch 3 0.00 0.00 0 3 0 0
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 7 0.01 0.00 0 3 0 0

    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: CHOOSE
    Parsing user id: SYS (recursive depth: 1)

    Rows Row Source Operation
    ------- ---------------------------------------------------
    0 TABLE ACCESS BY INDEX ROWID CDEF$ (cr=1 pr=0 pw=0 time=22 us)
    0 INDEX RANGE SCAN I_CDEF3 (cr=1 pr=0 pw=0 time=20 us)(object id 52)

    ********************************************************************************

    select con#,type#,condlength,intcols,robj#,rcon#,match#,refact,nvl(enabled,0),
    rowid,cols,nvl(defer,0),mtime,nvl(spare1,0)
    from
    cdef$ where obj#=:1


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.00 0.00 0 0 0 0
    Execute 3 0.00 0.00 0 0 0 0
    Fetch 34 0.00 0.00 0 42 0 31
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 38 0.00 0.00 0 42 0 31

    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: CHOOSE
    Parsing user id: SYS (recursive depth: 1)

    Rows Row Source Operation
    ------- ---------------------------------------------------
    5 TABLE ACCESS CLUSTER CDEF$ (cr=9 pr=0 pw=0 time=17 us)
    1 INDEX UNIQUE SCAN I_COBJ# (cr=2 pr=0 pw=0 time=10 us)(object id 30)

    ********************************************************************************

    select intcol#,nvl(pos#,0),col#,nvl(spare1,0)
    from
    ccol$ where con#=:1


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.00 0.00 0 0 0 0
    Execute 31 0.01 0.00 0 0 0 0
    Fetch 70 0.00 0.00 0 140 0 39
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 102 0.01 0.00 0 140 0 39

    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: CHOOSE
    Parsing user id: SYS (recursive depth: 1)

    Rows Row Source Operation
    ------- ---------------------------------------------------
    2 TABLE ACCESS BY INDEX ROWID CCOL$ (cr=6 pr=0 pw=0 time=49 us)
    2 INDEX RANGE SCAN I_CCOL1 (cr=4 pr=0 pw=0 time=45 us)(object id 54)

    ********************************************************************************

    select condition
    from
    cdef$ where rowid=:1


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.00 0.00 0 0 0 0
    Execute 1 0.00 0.00 0 0 0 0
    Fetch 1 0.00 0.00 0 2 0 1
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 3 0.00 0.00 0 2 0 1

    Misses in library cache during parse: 0
    Optimizer mode: CHOOSE
    Parsing user id: SYS (recursive depth: 1)

    Rows Row Source Operation
    ------- ---------------------------------------------------
    1 TABLE ACCESS BY USER ROWID CDEF$ (cr=1 pr=0 pw=0 time=18 us)




    ********************************************************************************

    OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 0 0.00 0.00 0 0 0 0
    Execute 0 0.00 0.00 0 0 0 0
    Fetch 0 0.00 0.00 0 0 0 0
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 0 0.00 0.00 0 0 0 0

    Misses in library cache during parse: 0

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total Waited
    ---------------------------------------- Waited ---------- ------------
    SQL*Net message to client 1 0.00 0.00
    SQL*Net message from client 1 10.13 10.13


    OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 11 0.01 0.01 0 0 0 0
    Execute 167 0.08 0.07 0 0 0 0
    Fetch 361 0.01 0.01 0 655 0 1218
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 539 0.10 0.10 0 655 0 1218

    Misses in library cache during parse: 10
    Misses in library cache during execute: 10

    0 user SQL statements in session.
    167 internal SQL statements in session.
    167 SQL statements in session.
    ********************************************************************************
    Trace file: css1cldr_ora_10134.trc
    Trace file compatibility: 10.01.00
    Sort options: default

    1 session in tracefile.
    0 user SQL statements in trace file.
    167 internal SQL statements in trace file.
    167 SQL statements in trace file.
    11 unique SQL statements in trace file.
    3548 lines in trace file.
    0 elapsed seconds in trace file.
  • 10. Re: Query Hangs while Parsing
    316993 Pro
    Currently Being Moderated
    yours tkprof result contain the info of yours recursive sql not for yours own query,paste trace tkprof result which contains yours query.

    Khurram
  • 11. Re: Query Hangs while Parsing
    Aravind N Newbie
    Currently Being Moderated
    Thats Why I am suspecting that the parse goes to an infinite loop without actually executing the query, In fact, we had left the query for more than 24 hours expecting it to come out with results, but it didnt. The fact that the query works when there is no stats point to some problems with parsing/optimizing i guess.
  • 12. Re: Query Hangs while Parsing
    316993 Pro
    Currently Being Moderated
    As you said query was working fine few days back what activity goes on from those days?. what is yours optimzer mode ,indeed in 10g the mode is ALL_ROWS by default ,suspect someone changed the mode to RULE isnt?check it.

    Let them run or drop the execution abnoramlly ,atleast you will get some info with tkprof trace file.

    Khurram
  • 13. Re: Query Hangs while Parsing
    26741 Oracle ACE
    Currently Being Moderated
    The fact that the query works when there is no stats point to some problems with parsing/optimizing i guess.
    No. It points to a difference in Execution Plans.
  • 14. Re: Query Hangs while Parsing
    Tanel Poder Oracle ACE Director
    Currently Being Moderated
    In 10g+ can measure where the time is spent using V$SESS_TIME_MODEL.

    Sample it for your session (note that V$SESS_TIME_MODEL stats are normally updated about every 5 seconds) and see which stats get incremented.

    I have seen couple of such cases (bugs) where Oracle gets into a loop during parsing.

    Another way for checking whether you are in parsing codepath is getting a stack trace of that server process. When in parsing codepath, you should see kksParseCursor function in the stack trace.

    Anyway, if parsing takes minutes, it's a bug.

    --
    Tanel Poder
    http://blog.tanelpoder.com
1 2 Previous Next