Showing posts with label question. Show all posts
Showing posts with label question. Show all posts

Saturday, April 24, 2010

Learning PL/SQL

Driven by application PL/SQL troubleshooting, as the Pro*C doesn't work .  while succeeds to OPEN CURSOR for a very complex SQL in less than 1 second (manually run it takes few minutes). The processing part is taken care by PRO*C.

From http://docstore.mik.ua/orelly/oracle/langpkt/ch01_09.htm, it says,
"You must open an explicit cursor before you can fetch rows from that cursor. When the cursor is opened, the processing includes the PARSE, BIND, OPEN, and EXECUTE statements. This OPEN processing includes: determining an execution plan, associating host variables and cursor parameters with the placeholders in the SQL statement, determining the result set, and, finally, setting the current row pointer to the first row in the result set. "



However, I doubt "the processing" includes " EXECUTE . Reason being, from my 10046 tracing comparison of  without FETCH or with FETCH,  there is no EXECUTION PLAN showed for without FETCH.

alter session set events '10046 trace name context forever, level 12' ;

     OPEN emp_cv FOR SELECT first_name, salary FROM employees where employee_id < emp_id;


--WITHOUT fetch

SELECT FIRST_NAME, SALARY
FROM
 EMPLOYEES WHERE EMPLOYEE_ID < :B1


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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 33     (recursive depth: 1)
********************************************************************************

alter session set events '10046 trace name context off'

--corresponding 10046 trace file of WITHOUT FETCH processing

=====================
PARSING IN CURSOR #1 len=65 dep=1 uid=33 oct=3 lid=33 tim=1242222958636520 hv=3716011877 ad='4cd98690'
SELECT FIRST_NAME, SALARY FROM EMPLOYEES WHERE EMPLOYEE_ID < :B1
END OF STMT
PARSE #1:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1242222958636514
BINDS #1:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=f6fe60ac  bln=22  avl=03  flg=05
  value=106
EXEC #1:c=0,e=144,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1242222958636745
WAIT #3: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1242222958636793
EXEC #3:c=10000,e=3030,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=1,tim=1242222958636870
WAIT #3: nam='SQL*Net message from client' ela= 236 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1242222958637166



-- with  FETCH processing

    OPEN emp_cv FOR SELECT first_name, salary FROM employees where employee_id < emp_id;
     loop
      fetch emp_cv into emp_dataPkg.er;
     exit when emp_cv%notfound;
      dbms_output.put_line(emp_dataPkg.er.name || ' - ' || emp_dataPkg.er.sal);
    end loop;
   CLOSE emp_cv;








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

SELECT FIRST_NAME, SALARY
FROM
 EMPLOYEES WHERE EMPLOYEE_ID < :B1


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        7      0.00       0.00          0         13          0           6
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        9      0.00       0.00          0         13          0           6

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

Rows     Row Source Operation
-------  ---------------------------------------------------
      6  TABLE ACCESS BY INDEX ROWID EMPLOYEES (cr=13 pr=0 pw=0 time=104 us)
      6   INDEX RANGE SCAN EMP_EMP_ID_PK (cr=7 pr=0 pw=0 time=120 us)(object id 12082)

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

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: 2)

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

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

alter session set events '10046 trace name context off';

--corresponding 10046 trace file of WITH FETCH processing

=====================
PARSING IN CURSOR #1 len=65 dep=1 uid=33 oct=3 lid=33 tim=1242222802758295 hv=3716011877 ad='4cd98690'
SELECT FIRST_NAME, SALARY FROM EMPLOYEES WHERE EMPLOYEE_ID < :B1
END OF STMT
PARSE #1:c=0,e=548,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1242222802758286
=====================
PARSING IN CURSOR #4 len=42 dep=2 uid=0 oct=3 lid=0 tim=1242222802759562 hv=844002283 ad='4cf6f080'
select condition from cdef$ where rowid=:1
END OF STMT
PARSE #4:c=0,e=123,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=1242222802759554
BINDS #4:
kkscoacd
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=f6f62148  bln=16  avl=16  flg=05
  value=00006F44.001D.0001
EXEC #4:c=0,e=362,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=1242222802760102
FETCH #4:c=0,e=99,p=0,cr=2,cu=0,mis=0,r=1,dep=2,og=4,tim=1242222802760255
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=31 op='TABLE ACCESS BY USER ROWID CDEF$ (cr=1 pr=0 pw=0 time=67 us)'
BINDS #1:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=f6f6254c  bln=22  avl=03  flg=05
  value=106
EXEC #1:c=0,e=3997,p=0,cr=2,cu=0,mis=1,r=0,dep=1,og=1,tim=1242222802762431
FETCH #1:c=0,e=108,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,tim=1242222802762631
FETCH #1:c=0,e=24,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,tim=1242222802762862
FETCH #1:c=0,e=18,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,tim=1242222802762950
FETCH #1:c=0,e=15,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,tim=1242222802763030
FETCH #1:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,tim=1242222802763108
FETCH #1:c=0,e=15,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,tim=1242222802763185
FETCH #1:c=0,e=9,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=1,tim=1242222802763257
STAT #1 id=1 cnt=6 pid=0 pos=1 obj=12080 op='TABLE ACCESS BY INDEX ROWID EMPLOYEES (cr=13 pr=0 pw=0 time=104 us)'
STAT #1 id=2 cnt=6 pid=1 pos=1 obj=12082 op='INDEX RANGE SCAN EMP_EMP_ID_PK (cr=7 pr=0 pw=0 time=120 us)'
WAIT #3: nam='SQL*Net message to client' ela= 10 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1242222802763502
EXEC #3:c=10000,e=6638,p=0,cr=15,cu=0,mis=0,r=1,dep=0,og=1,tim=1242222802763589
WAIT #3: nam='SQL*Net message from client' ela= 359 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1242222802764056
=====================

Wednesday, April 23, 2008

WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK

Hit below error, symptoms:
1. cpu 100% or server almost hang.
2. can't connect /as sysdba

solution:
ps -ef |grep -i beq
and kill those accordingly

root cause:
so far don't know. why it is ora-4031?


Sat Apr 19 03:50:02 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_cjq0_15634.trc:
ORA-07445: exception encountered: core dump [kghpir()+32] [SIGSEGV] [Address not mapped to object] [0xFFFFFFFFFFFFFFD0] [] []
Sat Apr 19 03:51:15 2008
Restarting dead background process CJQ0
CJQ0 started with pid=10, OS id=18756
Sat Apr 19 04:00:32 2008
Thread 1 advanced to log sequence 9558
Current log# 2 seq# 9558 mem# 0: /bkp003/oradata/CUST33B/redoCUST33B02a.log
Current log# 2 seq# 9558 mem# 1: /bkp003/oradata/CUST33B/redoCUST33B02b.log
Sat Apr 19 04:16:46 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_mmon_15636.trc:
ORA-00600: internal error code, arguments: [17148], [0xC0000004C22A2648], [], [], [], [], [], []
Sat Apr 19 04:17:13 2008
ORA-600 encountered when generating server alert SMG-3503
Sat Apr 19 04:42:18 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_j000_22062.trc:
ORA-00600: internal error code, arguments: [17148], [0xC0000004C2604248], [], [], [], [], [], []
Sat Apr 19 05:23:14 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_s000_15642.trc:
ORA-00600: internal error code, arguments: [17148], [0xC0000004C37E10E0], [], [], [], [], [], []
Sat Apr 19 06:03:54 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_j000_29503.trc:
ORA-12012: error on auto execute of job 23935
ORA-04031: unable to allocate ORA-04031: unable to allocate 61912 bytes of shared memory ("shared pool","DBMS_STATS","PL/SQL MPCODE","BAMIMA: Bam Buffer")
bytes of shared memory ("","","","")
Sat Apr 19 07:21:52 2008
Thread 1 advanced to log sequence 9559
Current log# 3 seq# 9559 mem# 0: /bkp003/oradata/CUST33B/redoCUST33B03a.log
Current log# 3 seq# 9559 mem# 1: /bkp003/oradata/CUST33B/redoCUST33B03b.log
Sat Apr 19 07:51:32 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_mmon_15636.trc:
ORA-00600: internal error code, arguments: [17148], [0xC0000004C3D88198], [], [], [], [], [], []
Sat Apr 19 07:51:44 2008
ORA-600 encountered when generating server alert SMG-3503
Sat Apr 19 08:04:08 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_q000_15727.trc:
ORA-00600: internal error code, arguments: [17148], [0xC0000004C2D63BD0], [], [], [], [], [], []
Sat Apr 19 08:04:37 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_q000_15727.trc:
ORA-00600: internal error code, arguments: [17148], [0xC0000004C2D63BD0], [], [], [], [], [], []
Sat Apr 19 08:09:41 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_m000_13077.trc:
ORA-07445: exception encountered: core dump [kghpir()+32] [SIGSEGV] [Address not mapped to object] [0xFFFFFFFFFFFFFFD0] [] []
Sat Apr 19 08:32:51 2008
System State dumped to trace file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc
Sat Apr 19 08:34:38 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc:
ORA-00604: error occurred at recursive SQL level 2
ORA-44203: timeout waiting for lock on cursor
Sat Apr 19 09:23:09 2008
System State dumped to trace file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc
Sat Apr 19 09:24:35 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc:
ORA-00604: error occurred at recursive SQL level 2
ORA-44203: timeout waiting for lock on cursor
Sat Apr 19 10:13:17 2008
System State dumped to trace file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc
Sat Apr 19 10:14:50 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc:
ORA-00604: error occurred at recursive SQL level 2
ORA-44203: timeout waiting for lock on cursor
Sat Apr 19 11:03:24 2008
System State dumped to trace file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc
Sat Apr 19 11:04:34 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc:
ORA-00604: error occurred at recursive SQL level 2
ORA-44203: timeout waiting for lock on cursor
Sat Apr 19 11:53:29 2008
System State dumped to trace file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc
Sat Apr 19 11:54:38 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc:
ORA-00604: error occurred at recursive SQL level 2
ORA-44203: timeout waiting for lock on cursor
Sat Apr 19 12:43:15 2008
System State dumped to trace file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc
Sat Apr 19 12:44:27 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc:
ORA-00604: error occurred at recursive SQL level 2
ORA-44203: timeout waiting for lock on cursor
Sat Apr 19 13:33:12 2008
System State dumped to trace file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc
Sat Apr 19 13:34:34 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc:
ORA-00604: error occurred at recursive SQL level 2
ORA-44203: timeout waiting for lock on cursor

Sun Apr 20 13:05:58 2008
Errors in file /software/oracle/admin/CUST33B/bdump/cust33b_reco_15630.trc:
ORA-00604: error occurred at recursive SQL level 2
ORA-44203: timeout waiting for lock on cursor
Sun Apr 20 13:11:11 2008
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=23
System State dumped to trace file /software/oracle/admin/CUST33B/udump/cust33b_ora_22232.trc

Mon Apr 21 11:38:25 2008
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=27
dev07:B.11:CUST33B:/software/oracle/admin/CUST33B/bdump> ps -ef |grep CUST33B
oracle 15636 1 0 Apr 13 ? 64:47 ora_mmon_CUST33B
oracle 15620 1 0 Apr 13 ? 5:18 ora_dbw0_CUST33B
oracle 15640 1 255 Apr 13 ? 2627:20 ora_d000_CUST33B
oracle 13858 13857 0 Apr 20 ? 2:26 oracleCUST33B (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle 16786 16783 0 10:48:08 ? 0:47 oracleCUST33B (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle 26564 26563 0 14:51:25 ? 1:36 oracleCUST33B (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle 15614 1 0 Apr 13 ? 4:16 ora_psp0_CUST33B
oracle 127 1 0 13:00:36 ? 0:01 ora_q000_CUST33B
oracle 13246 1 0 Apr 19 ? 1:27 ora_q002_CUST33B
oracle 7012 16816 0 14:12:11 pts/2 0:00 grep CUST33B
oracle 18756 1 0 Apr 19 ? 54:59 ora_cjq0_CUST33B
oracle 15676 1 0 Apr 13 ? 2:08 ora_qmnc_CUST33B
oracle 3746 3742 0 Apr 20 ? 2:03 oracleCUST33B (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle 9931 1 255 Apr 20 ? 841:35 oracleCUST33B (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle 15730 1 0 Apr 13 ? 7:29 ora_q001_CUST33B
oracle 15638 1 0 Apr 13 ? 20:15 ora_mmnl_CUST33B
oracle 15628 1 0 Apr 13 ? 19:33 ora_smon_CUST33B
oracle 22232 1 0 Apr 20 ? 2:01 oracleCUST33B (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle 15630 1 0 Apr 13 ? 48:06 ora_reco_CUST33B
oracle 15624 1 0 Apr 13 ? 5:25 ora_lgwr_CUST33B
oracle 15618 1 0 Apr 13 ? 3:23 ora_mman_CUST33B
oracle 28226 1 0 15:04:15 ? 1:47 oracleCUST33B (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle 15626 1 0 Apr 13 ? 10:31 ora_ckpt_CUST33B
oracle 7404 1 255 Apr 19 ? 2063:13 ora_j000_CUST33B
oracle 15612 1 255 Apr 13 ? 2045:52 ora_pmon_CUST33B
dev07:B.11:CUST33B:/software/oracle/admin/CUST33B/bdump> kill 3746 9931 22232 2822613858 16786 26564