1 2 Previous Next 28 Replies Latest reply on Jun 2, 2008 6:47 PM by Aravind N

    Query Hangs while Parsing

    Aravind N
      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
          Srinivas.R
          >>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
            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....
              Enable 10046 for the query and paste the raw file results here.
              Aman....
              • 4. Re: Query Hangs while Parsing
                Aravind N
                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
                  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....
                    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
                      orawarebyte
                      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
                        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
                          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
                            orawarebyte
                            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
                              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
                                orawarebyte
                                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
                                  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
                                    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