RE: Tales Of Big Hammer #10046 (AKA event 10046)
Title: RE: Tales Of Big Hammer #10046 (AKA event 10046) Jonathan, Yes this code is inside a function inside a pl/sql package. As it is an implicit select, with (of course) no exception handler (who needs extra code anyways), I believe your hypothesis is right. Maybe next week I'll take a look at it once again. The tracefile have been moved to tape by now. Thanks for the analysis Raj __ Rajendra Jamadagni MIS, ESPN Inc. Rajendra dot Jamadagni at ESPN dot com Any opinion expressed here is personal and doesn't reflect that of ESPN Inc. QOTD: Any clod can have facts, but having an opinion is an art! -Original Message- From: Jonathan Lewis [mailto:[EMAIL PROTECTED]] Sent: Thursday, January 02, 2003 6:59 PM To: Multiple recipients of list ORACLE-L Subject: Re: Tales Of Big Hammer #10046 (AKA event 10046) I've been trying to emulate this on 9.2.0.2, but I can't. The oddity (I think) is that your WAIT #0: nam='SQL*Net break/reset to client' ela= 57 p1=675562835 p2=1 p3=0 is recorded against cursor #0, not cursor #54, so it is cursor zero (whatever that is) that has failed to return any data, not cursor 54 (which, as you can see, has fetched a row). Is this cursor inside a pl/sql function, perhaps, and could the function have some code that manages to discard the value and therefore manage to return without a return value ? Regards Jonathan Lewis *This e-mail message is confidential, intended only for the named recipient(s) above and may contain information that is privileged, attorney work product or exempt from disclosure under applicable law. If you have received this message in error, or are not the named recipient(s), please immediately notify corporate MIS at (860) 766-2000 and delete this e-mail message from your computer, Thank you.*1
Re: Tales Of Big Hammer #10046 (AKA event 10046)
I've been trying to emulate this on 9.2.0.2, but I can't. The oddity (I think) is that your WAIT #0: nam='SQL*Net break/reset to client' ela= 57 p1=675562835 p2=1 p3=0 is recorded against cursor #0, not cursor #54, so it is cursor zero (whatever that is) that has failed to return any data, not cursor 54 (which, as you can see, has fetched a row). Is this cursor inside a pl/sql function, perhaps, and could the function have some code that manages to discard the value and therefore manage to return without a return value ? Regards Jonathan Lewis http://www.jlcomp.demon.co.uk Coming soon a new one-day tutorial: Cost Based Optimisation (see http://www.jlcomp.demon.co.uk/tutorial.html ) Next Seminar dates: (see http://www.jlcomp.demon.co.uk/seminar.html ) England__January 21/23 The Co-operative Oracle Users' FAQ http://www.jlcomp.demon.co.uk/faq/ind_faq.html -Original Message- To: Multiple recipients of list ORACLE-L [EMAIL PROTECTED] Date: 31 December 2002 13:31 Tim, I don't see that ... I know this sql caused the problem ... = === === PARSING IN CURSOR #54 len=238 dep=1 uid=44 oct=3 lid=44 tim=1016624815165467 hv=2089161539 ad='24ba3ad8' SELECT b.pr_mobility_code FROM prp_requests b, prp_sr_cal_pps a WHERE b.pr_req_unit_id = :b3 AND b.pr_gr_id = a.pscp_id AND a.pscp_prp_id = :b2 AND a.pscp_prp_version = :b1 END OF STMT PARSE #54:c=0,e=1192,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,tim=1016624815165463 BINDS #54: bind 0: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=72 offset=0 bfp=11054edb0 bln=22 avl=05 flg=05 value=9044628 bind 1: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=0 offset=24 bfp=11054edc8 bln=22 avl=04 flg=01 value=586823 bind 2: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=0 offset=48 bfp=11054ede0 bln=22 avl=02 flg=01 value=2 EXEC #54:c=0,e=1681,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1016624815167288 WAIT #54: nam='global cache cr request' ela= 417 p1=32 p2=500383 p3=504403158449678016 WAIT #54: nam='db file sequential read' ela= 2816 p1=32 p2=500383 p3=1 WAIT #54: nam='global cache cr request' ela= 445 p1=33 p2=517103 p3=504403158399168096 WAIT #54: nam='db file sequential read' ela= 1858 p1=33 p2=517103 p3=1 WAIT #54: nam='db file sequential read' ela= 781221 p1=31 p2=1251231 p3=1 FETCH #54:c=0,e=787456,p=3,cr=17,cu=0,mis=0,r=1,dep=1,og=4,tim=101662481595 4763 WAIT #0: nam='SQL*Net break/reset to client' ela= 57 p1=675562835 p2=1 p3=0 WAIT #0: nam='SQL*Net break/reset to client' ela= 630 p1=675562835 p2=0 p3=0 WAIT #0: nam='SQL*Net message to client' ela= 1 p1=675562835 p2=1 p3=0 *** 2002-12-27 16:17:21.846 WAIT #0: nam='SQL*Net message from client' ela= 29596938 p1=675562835 p2=1 p3=0 = PARSING IN CURSOR #45 len=8 dep=0 uid=3318 oct=45 lid=3318 tim=1016624845553757 hv=1226881397 ad='24f0b6b8' ROLLBACK END OF STMT PARSE #45:c=0,e=412,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1016624845553752 XCTEND rlbk=1, rd_only=1 EXEC #45:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845553883 WAIT #45: nam='SQL*Net message to client' ela= 3 p1=675562835 p2=1 p3=0 WAIT #45: nam='SQL*Net message from client' ela= 13212 p1=675562835 p2=1 p3=0 = PARSING IN CURSOR #45 len=8 dep=0 uid=3318 oct=45 lid=3318 tim=1016624845567343 hv=1226881397 ad='24f0b6b8' ROLLBACK END OF STMT PARSE #45:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845567339 XCTEND rlbk=1, rd_only=1 EXEC #45:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845567450 WAIT #45: nam='SQL*Net message to client' ela= 1 p1=675562835 p2=1 p3=0 WAIT #45: nam='SQL*Net message from client' ela= 6733 p1=675562835 p2=1 p3=0 STAT #43 id=1 cnt=1 pid=0 pos=1 obj=29433 op='TABLE ACCESS BY INDEX ROWID SELLING_ROTATIONS (cr=3 r=1 w=0 time=14786 us)' STAT #43 id=2 cnt=1 pid=1 pos=1 obj=422698 op='INDEX UNIQUE SCAN SR_PK_PRIM (cr=2 r=0 w=0 time=27 us)' Thanks for the explanation ... Raj -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Jonathan Lewis INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in the message BODY, include a line containing: UNSUB ORACLE-L (or the name of mailing list you want to be removed from). You may also send the HELP command for other information (like subscribing).
RE: Tales Of Big Hammer #10046 (AKA event 10046)
I saw this thread for some time and wanted to add something that could help but was not sure if I remember correctly or not. This was in Forms 3.0 where I remember it had its own PL/SQL engine. So my guess things will be different when traced on the server side. Is it still the same in the new releases of Oracle Forms? Waleed -Original Message- Sent: Thursday, January 02, 2003 6:59 PM To: Multiple recipients of list ORACLE-L I've been trying to emulate this on 9.2.0.2, but I can't. The oddity (I think) is that your WAIT #0: nam='SQL*Net break/reset to client' ela= 57 p1=675562835 p2=1 p3=0 is recorded against cursor #0, not cursor #54, so it is cursor zero (whatever that is) that has failed to return any data, not cursor 54 (which, as you can see, has fetched a row). Is this cursor inside a pl/sql function, perhaps, and could the function have some code that manages to discard the value and therefore manage to return without a return value ? Regards Jonathan Lewis http://www.jlcomp.demon.co.uk Coming soon a new one-day tutorial: Cost Based Optimisation (see http://www.jlcomp.demon.co.uk/tutorial.html ) Next Seminar dates: (see http://www.jlcomp.demon.co.uk/seminar.html ) England__January 21/23 The Co-operative Oracle Users' FAQ http://www.jlcomp.demon.co.uk/faq/ind_faq.html -Original Message- To: Multiple recipients of list ORACLE-L [EMAIL PROTECTED] Date: 31 December 2002 13:31 Tim, I don't see that ... I know this sql caused the problem ... = === === PARSING IN CURSOR #54 len=238 dep=1 uid=44 oct=3 lid=44 tim=1016624815165467 hv=2089161539 ad='24ba3ad8' SELECT b.pr_mobility_code FROM prp_requests b, prp_sr_cal_pps a WHERE b.pr_req_unit_id = :b3 AND b.pr_gr_id = a.pscp_id AND a.pscp_prp_id = :b2 AND a.pscp_prp_version = :b1 END OF STMT PARSE #54:c=0,e=1192,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,tim=1016624815165463 BINDS #54: bind 0: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=72 offset=0 bfp=11054edb0 bln=22 avl=05 flg=05 value=9044628 bind 1: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=0 offset=24 bfp=11054edc8 bln=22 avl=04 flg=01 value=586823 bind 2: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=0 offset=48 bfp=11054ede0 bln=22 avl=02 flg=01 value=2 EXEC #54:c=0,e=1681,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1016624815167288 WAIT #54: nam='global cache cr request' ela= 417 p1=32 p2=500383 p3=504403158449678016 WAIT #54: nam='db file sequential read' ela= 2816 p1=32 p2=500383 p3=1 WAIT #54: nam='global cache cr request' ela= 445 p1=33 p2=517103 p3=504403158399168096 WAIT #54: nam='db file sequential read' ela= 1858 p1=33 p2=517103 p3=1 WAIT #54: nam='db file sequential read' ela= 781221 p1=31 p2=1251231 p3=1 FETCH #54:c=0,e=787456,p=3,cr=17,cu=0,mis=0,r=1,dep=1,og=4,tim=101662481595 4763 WAIT #0: nam='SQL*Net break/reset to client' ela= 57 p1=675562835 p2=1 p3=0 WAIT #0: nam='SQL*Net break/reset to client' ela= 630 p1=675562835 p2=0 p3=0 WAIT #0: nam='SQL*Net message to client' ela= 1 p1=675562835 p2=1 p3=0 *** 2002-12-27 16:17:21.846 WAIT #0: nam='SQL*Net message from client' ela= 29596938 p1=675562835 p2=1 p3=0 = PARSING IN CURSOR #45 len=8 dep=0 uid=3318 oct=45 lid=3318 tim=1016624845553757 hv=1226881397 ad='24f0b6b8' ROLLBACK END OF STMT PARSE #45:c=0,e=412,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1016624845553752 XCTEND rlbk=1, rd_only=1 EXEC #45:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845553883 WAIT #45: nam='SQL*Net message to client' ela= 3 p1=675562835 p2=1 p3=0 WAIT #45: nam='SQL*Net message from client' ela= 13212 p1=675562835 p2=1 p3=0 = PARSING IN CURSOR #45 len=8 dep=0 uid=3318 oct=45 lid=3318 tim=1016624845567343 hv=1226881397 ad='24f0b6b8' ROLLBACK END OF STMT PARSE #45:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845567339 XCTEND rlbk=1, rd_only=1 EXEC #45:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845567450 WAIT #45: nam='SQL*Net message to client' ela= 1 p1=675562835 p2=1 p3=0 WAIT #45: nam='SQL*Net message from client' ela= 6733 p1=675562835 p2=1 p3=0 STAT #43 id=1 cnt=1 pid=0 pos=1 obj=29433 op='TABLE ACCESS BY INDEX ROWID SELLING_ROTATIONS (cr=3 r=1 w=0 time=14786 us)' STAT #43 id=2 cnt=1 pid=1 pos=1 obj=422698 op='INDEX UNIQUE SCAN SR_PK_PRIM (cr=2 r=0 w=0 time=27 us)' Thanks for the explanation ... Raj -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Jonathan Lewis INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (note EXACT
Re: Tales Of Big Hammer #10046 (AKA event 10046)
Brings to mind some of the great hammer quotes: When all you have is a hammer, everything tends to look like a nail When all you have is a hammer, maybe brain surgery is not for you :-) Connor --- Tim Gorman [EMAIL PROTECTED] wrote: Tales Of Big Hammer #10046 (AKA event 10046)Generally you won't find err=1403 text in the raw .trc file. Instead, if you carefully examine the FETCH lines, you'll see r=0 (i.e. zero rows returned) in amongst all the other statistics. Very very difficult to catch and often requires a Vulcan mind-meld to the application over several hours of careful perusal (something best left to Vulcans)... Great job! - Original Message - From: Jamadagni, Rajendra To: Multiple recipients of list ORACLE-L Sent: Monday, December 30, 2002 10:43 AM Subject: Tales Of Big Hammer #10046 (AKA event 10046) On Friday our application support person called me and said User is getting a ORA-1403 error in one form. I should mention that this is complex. And I need a solution immediately. So, I gave them the hammer (with the sql string to put in pre-form trigger in the form for the 546th time, they never save their emails, especially from a DBA). They set the event and ran the form. Now the entire support group recently had to face me for an hour-long discussion on TKPROF (AKA the Hammer) and debugging techniques, so they read the tracefile and obediently tried to find a line with 'ERR=1043' but couldn't find any. So I looked at the trace file, and sure it was, it didn't show the error, but after one SQL it showed a 'SQL*Net break/reset to client' event followed by a ROLLBACK. I directed them to that statement. This person was happy that they found the culprit statement, but couldn't find what was going wrong. So they went through the presentation notes and used dbms_support.start_trace(true,true); statement and ran the form again. This time, as the trace dumped the bind values, they found the set of values on which the query returned 1403, and got back to the developer with a solid case. So, once again ... if you have 10046 hammer, most problems are like nails. Raj __ Rajendra Jamadagni MIS, ESPN Inc. Rajendra dot Jamadagni at ESPN dot com Any opinion expressed here is personal and doesn't reflect that of ESPN Inc. QOTD: Any clod can have facts, but having an opinion is an art! = Connor McDonald http://www.oracledba.co.uk http://www.oaktable.net GIVE a man a fish and he will eat for a day. But TEACH him how to fish, and...he will sit in a boat and drink beer all day __ Do You Yahoo!? Everything you'll ever need on one web page from News and Sport to Email and Music Charts http://uk.my.yahoo.com -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: =?iso-8859-1?q?Connor=20McDonald?= INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in the message BODY, include a line containing: UNSUB ORACLE-L (or the name of mailing list you want to be removed from). You may also send the HELP command for other information (like subscribing).
RE: Tales Of Big Hammer #10046 (AKA event 10046)
Title: Tales Of Big Hammer #10046 (AKA event 10046) Tim, I don't see that ... I know this sql caused the problem ... === PARSING IN CURSOR #54 len=238 dep=1 uid=44 oct=3 lid=44 tim=1016624815165467 hv=2089161539 ad='24ba3ad8'SELECT b.pr_mobility_code FROM prp_requests b, prp_sr_cal_pps a WHERE b.pr_req_unit_id = :b3 AND b.pr_gr_id = a.pscp_id AND a.pscp_prp_id = :b2 AND a.pscp_prp_version = :b1END OF STMTPARSE #54:c=0,e=1192,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,tim=1016624815165463BINDS #54:bind 0: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=72 offset=0 bfp=11054edb0 bln=22 avl=05 flg=05 value=9044628bind 1: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=0 offset=24 bfp=11054edc8 bln=22 avl=04 flg=01 value=586823bind 2: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=0 offset=48 bfp=11054ede0 bln=22 avl=02 flg=01 value=2EXEC #54:c=0,e=1681,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1016624815167288WAIT #54: nam='global cache cr request' ela= 417 p1=32 p2=500383 p3=504403158449678016WAIT #54: nam='db file sequential read' ela= 2816 p1=32 p2=500383 p3=1WAIT #54: nam='global cache cr request' ela= 445 p1=33 p2=517103 p3=504403158399168096WAIT #54: nam='db file sequential read' ela= 1858 p1=33 p2=517103 p3=1WAIT #54: nam='db file sequential read' ela= 781221 p1=31 p2=1251231 p3=1FETCH #54:c=0,e=787456,p=3,cr=17,cu=0,mis=0,r=1,dep=1,og=4,tim=1016624815954763WAIT #0: nam='SQL*Net break/reset to client' ela= 57 p1=675562835 p2=1 p3=0WAIT #0: nam='SQL*Net break/reset to client' ela= 630 p1=675562835 p2=0 p3=0WAIT #0: nam='SQL*Net message to client' ela= 1 p1=675562835 p2=1 p3=0*** 2002-12-27 16:17:21.846WAIT #0: nam='SQL*Net message from client' ela= 29596938 p1=675562835 p2=1 p3=0=PARSING IN CURSOR #45 len=8 dep=0 uid=3318 oct=45 lid=3318 tim=1016624845553757 hv=1226881397 ad='24f0b6b8'ROLLBACKEND OF STMTPARSE #45:c=0,e=412,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1016624845553752XCTEND rlbk=1, rd_only=1EXEC #45:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845553883WAIT #45: nam='SQL*Net message to client' ela= 3 p1=675562835 p2=1 p3=0WAIT #45: nam='SQL*Net message from client' ela= 13212 p1=675562835 p2=1 p3=0=PARSING IN CURSOR #45 len=8 dep=0 uid=3318 oct=45 lid=3318 tim=1016624845567343 hv=1226881397 ad='24f0b6b8'ROLLBACKEND OF STMTPARSE #45:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845567339XCTEND rlbk=1, rd_only=1EXEC #45:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845567450WAIT #45: nam='SQL*Net message to client' ela= 1 p1=675562835 p2=1 p3=0WAIT #45: nam='SQL*Net message from client' ela= 6733 p1=675562835 p2=1 p3=0STAT #43 id=1 cnt=1 pid=0 pos=1 obj=29433 op='TABLE ACCESS BY INDEX ROWID SELLING_ROTATIONS (cr=3 r=1 w=0 time=14786 us)'STAT #43 id=2 cnt=1 pid=1 pos=1 obj=422698 op='INDEX UNIQUE SCAN SR_PK_PRIM (cr=2 r=0 w=0 time=27 us)' Thanks for the explanation ... Raj __ Rajendra Jamadagni MIS, ESPN Inc. Rajendra dot Jamadagni at ESPN dot com Any opinion expressed here is personal and doesn't reflect that of ESPN Inc. QOTD: Any clod can have facts, but having an opinion is an art! -Original Message-From: Tim Gorman [mailto:[EMAIL PROTECTED]]Sent: Monday, December 30, 2002 7:49 PMTo: Multiple recipients of list ORACLE-LSubject: Re: Tales Of Big Hammer #10046 (AKA event 10046) Generally you won't find "err=1403" text in the raw ".trc" file. Instead, if you carefully examine the FETCH lines, you'll see "r=0" (i.e. zero rows returned) in amongst all the other statistics. Very very difficult to catch and often requires a Vulcan mind-meld to the application over several hours of careful perusal(something best left to Vulcans)... Great job! *This e-mail message is confidential, intended only for the named recipient(s) above and may contain information that is privileged, attorney work product or exempt from disclosure under applicable law. If you have received this message in error, or are not the named recipient(s), please immediately notify corporate MIS at (860) 766-2000 and delete this e-mail message from your computer, Thank you.*1
Re: Tales Of Big Hammer #10046 (AKA event 10046)
Title: Tales Of Big Hammer #10046 (AKA event 10046)
Raj,
Thanks for sharing this with us. In your original
post you mentioned that you saw a "rollback" right after the "SQL*Net
break/reset to client" and that was how you figured out the 1403 error. I don't
see that in this excerpt from the raw trace file, though. How did you determine
it was this particulat SQL? Also the FETCH#54 line you have highlighted has r=1,
not r=0; what's special about that line?
Thanks in advance.
Arup
- Original Message -
From:
Jamadagni, Rajendra
To: Multiple recipients of list ORACLE-L
Sent: Tuesday, December 31, 2002 7:58
AM
Subject: RE: Tales Of Big Hammer #10046
(AKA event 10046)
Tim,
I don't see that ... I know this sql caused the problem
...
===
PARSING IN CURSOR #54 len=238 dep=1 uid=44 oct=3 lid=44
tim=1016624815165467 hv=2089161539 ad='24ba3ad8'SELECT
b.pr_mobility_code FROM
prp_requests
b,
prp_sr_cal_pps a WHERE
b.pr_req_unit_id =
:b3 AND
b.pr_gr_id =
a.pscp_id AND
a.pscp_prp_id =
:b2 AND a.pscp_prp_version =
:b1END OF STMTPARSE
#54:c=0,e=1192,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,tim=1016624815165463BINDS
#54:bind 0: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1
size=72 offset=0 bfp=11054edb0 bln=22 avl=05
flg=05 value=9044628bind 1: dty=2 mxl=22(21) mal=00
scl=00 pre=00 oacflg=03 oacfl2=1 size=0 offset=24
bfp=11054edc8 bln=22 avl=04 flg=01 value=586823bind
2: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=0
offset=48 bfp=11054ede0 bln=22 avl=02 flg=01
value=2EXEC
#54:c=0,e=1681,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1016624815167288WAIT
#54: nam='global cache cr request' ela= 417 p1=32 p2=500383
p3=504403158449678016WAIT #54: nam='db file sequential read' ela= 2816
p1=32 p2=500383 p3=1WAIT #54: nam='global cache cr request' ela= 445 p1=33
p2=517103 p3=504403158399168096WAIT #54: nam='db file sequential read'
ela= 1858 p1=33 p2=517103 p3=1WAIT #54: nam='db file sequential read' ela=
781221 p1=31 p2=1251231 p3=1FETCH
#54:c=0,e=787456,p=3,cr=17,cu=0,mis=0,r=1,dep=1,og=4,tim=1016624815954763WAIT
#0: nam='SQL*Net break/reset to client' ela= 57 p1=675562835 p2=1 p3=0WAIT
#0: nam='SQL*Net break/reset to client' ela= 630 p1=675562835 p2=0
p3=0WAIT #0: nam='SQL*Net message to client' ela= 1 p1=675562835 p2=1
p3=0*** 2002-12-27 16:17:21.846WAIT #0: nam='SQL*Net message from
client' ela= 29596938 p1=675562835 p2=1
p3=0=PARSING IN CURSOR #45 len=8 dep=0 uid=3318
oct=45 lid=3318 tim=1016624845553757 hv=1226881397
ad='24f0b6b8'ROLLBACKEND OF STMTPARSE
#45:c=0,e=412,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1016624845553752XCTEND
rlbk=1, rd_only=1EXEC
#45:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845553883WAIT
#45: nam='SQL*Net message to client' ela= 3 p1=675562835 p2=1 p3=0WAIT
#45: nam='SQL*Net message from client' ela= 13212 p1=675562835 p2=1
p3=0=PARSING IN CURSOR #45 len=8 dep=0 uid=3318
oct=45 lid=3318 tim=1016624845567343 hv=1226881397
ad='24f0b6b8'ROLLBACKEND OF STMTPARSE
#45:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845567339XCTEND
rlbk=1, rd_only=1EXEC
#45:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1016624845567450WAIT
#45: nam='SQL*Net message to client' ela= 1 p1=675562835 p2=1 p3=0WAIT
#45: nam='SQL*Net message from client' ela= 6733 p1=675562835 p2=1
p3=0STAT #43 id=1 cnt=1 pid=0 pos=1 obj=29433 op='TABLE ACCESS BY INDEX
ROWID SELLING_ROTATIONS (cr=3 r=1 w=0 time=14786 us)'STAT #43 id=2 cnt=1
pid=1 pos=1 obj=422698 op='INDEX UNIQUE SCAN SR_PK_PRIM (cr=2 r=0 w=0 time=27
us)'
Thanks for the explanation ...
Raj
__
Rajendra
Jamadagni
MIS, ESPN Inc.
Rajendra dot Jamadagni at ESPN
dot com
Any opinion expressed here is
personal and doesn't reflect that of ESPN Inc.
QOTD: Any clod can have facts,
but having an opinion is an
art!
-Original Message-From: Tim Gorman
[mailto:[EMAIL PROTECTED]]Sent: Monday, December 30, 2002 7:49
PMTo: Multiple recipients of list ORACLE-LSubject: Re:
Tales Of Big Hammer #10046 (AKA event 10046)
Generally you won't find "err=1403" text in the
raw ".trc" file. Instead, if you carefully examine the FETCH lines,
you'll see "r=0" (i.e. zero rows returned) in amongst all the other
statistics. Very very difficult to catch and often requires a Vulcan
mind-meld to the application over several hours of careful
perusal(something best left to Vulcans)...
Great
job!
RE: Tales Of Big Hammer #10046 (AKA event 10046)
Title: Tales Of Big Hammer #10046 (AKA event 10046) Arup, Since I didn't see a line reporting error 1403, I was puzzled for a bit. But here is the application knowledge came handy. I should have see a commit for a successful operation. I didn't and instead saw a ROLLBACK. Immediately before the rollback I also saw a 'SQLNet Break' event so I put 2 and 2 togather and concluded that this caused the problem. when I looked up the code, this was a implicit cursor, so it basically confirmed that this was the culprit. Also we took the bind values and the statement from sqlplus, and it *did* return two rows. I highlighted the row with r=1 because according to Tim's explanation, I should have seen r=0. So I got confused and replied with excerpt from the tracefile. I know he will have some explanation about it. For rollback look at Cursor# 45 ... Raj __ Rajendra Jamadagni MIS, ESPN Inc. Rajendra dot Jamadagni at ESPN dot com Any opinion expressed here is personal and doesn't reflect that of ESPN Inc. QOTD: Any clod can have facts, but having an opinion is an art! -Original Message-From: Arup Nanda [mailto:[EMAIL PROTECTED]]Sent: Tuesday, December 31, 2002 8:59 AMTo: Multiple recipients of list ORACLE-LSubject: Re: Tales Of Big Hammer #10046 (AKA event 10046) Raj, Thanks for sharing this with us. In your original post you mentioned that you saw a "rollback" right after the "SQL*Net break/reset to client" and that was how you figured out the 1403 error. I don't see that in this excerpt from the raw trace file, though. How did you determine it was this particulat SQL? Also the FETCH#54 line you have highlighted has r=1, not r=0; what's special about that line? Thanks in advance. Arup *This e-mail message is confidential, intended only for the named recipient(s) above and may contain information that is privileged, attorney work product or exempt from disclosure under applicable law. If you have received this message in error, or are not the named recipient(s), please immediately notify corporate MIS at (860) 766-2000 and delete this e-mail message from your computer, Thank you.*1
RE: Tales Of Big Hammer #10046 (AKA event 10046)
Raj, The application may have interpreted this as ORA-01403, but I've no clue as to why the SQL*Net break/reset to client occurred. You can see about 7 seconds of wait for response from the client, after which a rollback occurs... The FETCH shows r=1 indicating that at least one row was returned. Was the application doing array fetches for that statement? Was a row returned? Is this PL/SQL or ??? It is interesting how these traces feel very much like archaeology; just have to use a delicate hammer to knock the bits loose... -Tim Tim, I don't see that ... I know this sql caused the problem .. == == === PARSING IN CURSOR #54 len=238 dep=1 uid=44 oct=3 lid=44 tim=1016624815165467 hv=2089161539 ad='24ba3ad8' SELECT b.pr_mobility_code FROM prp_requests b, prp_sr_cal_pps a WHERE b.pr_req_unit_id = :b3 AND b.pr_gr_id = a.pscp_id AND a.pscp_prp_id = :b2 AND a.pscp_prp_version = :b1 END OF STMT PARSE #54:c=0,e=1192,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,tim=1016 624815165463 BINDS #54: bind 0: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=72 offset=0 bfp=11054edb0 bln=22 avl=05 flg=05 value=9044628 bind 1: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=0 offset=24 bfp=11054edc8 bln=22 avl=04 flg=01 value=586823 bind 2: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=0 offset=48 bfp=11054ede0 bln=22 avl=02 flg=01 value=2 EXEC #54:c=0,e=1681,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1016 624815167288 WAIT #54: nam='global cache cr request' ela= 417 p1=32 p2=500383 p3=504403158449678016 WAIT #54: nam='db file sequential read' ela= 2816 p1=32 p2=500383 p3=1 WAIT #54: nam='global cache cr request' ela= 445 p1=33 p2=517103 p3=504403158399168096 WAIT #54: nam='db file sequential read' ela= 1858 p1=33 p2=517103 p3=1 WAIT #54: nam='db file sequential read' ela= 781221 p1=31 p2=1251231 p3=1 FETCH #54:c=0,e=787456,p=3,cr=17,cu=0,mis=0,r=1,dep=1,og=4,tim=1 016624815954763 WAIT #0: nam='SQL*Net break/reset to client' ela= 57 p1=675562835 p2=1 p3=0 WAIT #0: nam='SQL*Net break/reset to client' ela= 630 p1=675562835 p2=0 p3=0 WAIT #0: nam='SQL*Net message to client' ela= 1 p1=675562835 p2=1 p3=0 *** 2002-12-27 16:17:21.846 WAIT #0: nam='SQL*Net message from client' ela= 29596938 p1=675562835 p2=1 p3=0 = PARSING IN CURSOR #45 len=8 dep=0 uid=3318 oct=45 lid=3318 tim=1016624845553757 hv=1226881397 ad='24f0b6b8' ROLLBACK END OF STMT PARSE #45:c=0,e=412,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=10166 24845553752 XCTEND rlbk=1, rd_only=1 EXEC #45:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=101662 4845553883 WAIT #45: nam='SQL*Net message to client' ela= 3 p1=675562835 p2=1 p3=0 WAIT #45: nam='SQL*Net message from client' ela= 13212 p1=675562835 p2=1 p3=0 = PARSING IN CURSOR #45 len=8 dep=0 uid=3318 oct=45 lid=3318 tim=1016624845567343 hv=1226881397 ad='24f0b6b8' ROLLBACK END OF STMT PARSE #45:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=101662 4845567339 XCTEND rlbk=1, rd_only=1 EXEC #45:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=101662 4845567450 WAIT #45: nam='SQL*Net message to client' ela= 1 p1=675562835 p2=1 p3=0 WAIT #45: nam='SQL*Net message from client' ela= 6733 p1=675562835 p2=1 p3=0 STAT #43 id=1 cnt=1 pid=0 pos=1 obj=29433 op='TABLE ACCESS BY INDEX ROWID SELLING_ROTATIONS (cr=3 r=1 w=0 time=14786 us)' STAT #43 id=2 cnt=1 pid=1 pos=1 obj=422698 op='INDEX UNIQUE SCAN SR_PK_PRIM (cr=2 r=0 w=0 time=27 us)' Thanks for the explanation ... Raj __ Rajendra Jamadagni MIS, ESPN Inc. Rajendra dot Jamadagni at ESPN dot com Any opinion expressed here is personal and doesn't reflect that of ESPN Inc. QOTD: Any clod can have facts, but having an opinion is an art! -Original Message- Sent: Monday, December 30, 2002 7:49 PM To: Multiple recipients of list ORACLE-L Generally you won't find err=1403 text in the raw .trc file. Instead, if you carefully examine the FETCH lines, you'll see r=0 (i.e. zero rows returned) in amongst all the other statistics. Very very difficult to catch and often requires a Vulcan mind-meld to the application over several hours of careful perusal (something best left to Vulcans)... Great job! [Attachment: ESPN_Disclaimer.txt] -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (note EXACT
RE: Tales Of Big Hammer #10046 (AKA event 10046)
Title: RE: Tales Of Big Hammer #10046 (AKA event 10046) Hmmm Tim, you really got me thinking ... 1. Support person ran the form. 2. Hit the error 3. Exited the form. Now point 3, will issue a rollback (Oracle Forms) so is that why we see two rollbacks in the trace file? The SQL is part of a DB package used by the form. I seem to remember that Oracle Forms had a bug, that returned ORA-1403 when either there actually was ORA-1403 or there wasn't any error but DBMS_ERROR_CODE() returned 1403 error. The probably have fixed the bug by now. But in this case, developer isn't checking the value of DBMS_ERROR_CODE(), for that matter developer is checking for no errors at all, and completely relying on Oracle to report these errors in the most obsecure way (sorry IMHO that's how Forms return server errors). They don't want to do too much coding (especially when it comes to exception handling). That being said, this SQL is executed as implicit cursor, so that might explain more than one row fetch and thus 1403. The worst part is I don't see the second fetch in the trace file. Slightly off topic: I'd also like to take this opportunity to say that today we have for the 2nd time (two separate issues) logged a bug report to fix the patch that OWS provided to fix a bug that we reported earlier. So we are requesting a patch to fix a patch to fix a bug ... to quote Yogi Berra ... It's Deja vu all over again !! I get to go home 1/2 day today conditions permitting ... but my boss is on vacation, so conditions are perfect. Raj __ Rajendra Jamadagni MIS, ESPN Inc. Rajendra dot Jamadagni at ESPN dot com Any opinion expressed here is personal and doesn't reflect that of ESPN Inc. QOTD: Any clod can have facts, but having an opinion is an art! -Original Message- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED]] Sent: Tuesday, December 31, 2002 9:24 AM To: Multiple recipients of list ORACLE-L Subject: RE: Tales Of Big Hammer #10046 (AKA event 10046) Raj, The application may have interpreted this as ORA-01403, but I've no clue as to why the SQL*Net break/reset to client occurred. You can see about 7 seconds of wait for response from the client, after which a rollback occurs... The FETCH shows r=1 indicating that at least one row was returned. Was the application doing array fetches for that statement? Was a row returned? Is this PL/SQL or ??? It is interesting how these traces feel very much like archaeology; just have to use a delicate hammer to knock the bits loose... -Tim *This e-mail message is confidential, intended only for the named recipient(s) above and may contain information that is privileged, attorney work product or exempt from disclosure under applicable law. If you have received this message in error, or are not the named recipient(s), please immediately notify corporate MIS at (860) 766-2000 and delete this e-mail message from your computer, Thank you.*1
Re: Tales Of Big Hammer #10046 (AKA event 10046)
Title: Tales Of Big Hammer #10046 (AKA event 10046) Generally you won't find "err=1403" text in the raw ".trc" file. Instead, if you carefully examine the FETCH lines, you'll see "r=0" (i.e. zero rows returned) in amongst all the other statistics. Very very difficult to catch and often requires a Vulcan mind-meld to the application over several hours of careful perusal(something best left to Vulcans)... Great job! - Original Message - From: Jamadagni, Rajendra To: Multiple recipients of list ORACLE-L Sent: Monday, December 30, 2002 10:43 AM Subject: Tales Of Big Hammer #10046 (AKA event 10046) On Friday our application support person called me and said "User is getting a ORA-1403 error in one form. I should mention that this is complex. And I need a solution immediately." So, I gave them the hammer (with the sql string to put in pre-form trigger in the form for the 546th time, they never save their emails, especially from a DBA). They set the event and ran the form. Now the entire support group recently had to face me for an hour-long discussion on TKPROF (AKA the Hammer) and debugging techniques, so they read the tracefile and obediently tried to find a line with 'ERR=1043' but couldn't find any. So I looked at the trace file, and sure it was, it didn't show the error, but after one SQL it showed a "'SQL*Net break/reset to client'" event followed by a ROLLBACK. I directed them to that statement. This person was happy that they found the culprit statement, but couldn't find what was going wrong. So they went through the presentation notes and used "dbms_support.start_trace(true,true);" statement and ran the form again. This time, as the trace dumped the bind values, they found the set of values on which the query returned 1403, and got back to the developer with a solid case. So, once again ... if you have 10046 hammer, most problems are like nails. Raj __ Rajendra Jamadagni MIS, ESPN Inc. Rajendra dot Jamadagni at ESPN dot com Any opinion expressed here is personal and doesn't reflect that of ESPN Inc. QOTD: Any clod can have facts, but having an opinion is an art!
