Questions & Answers
|
QA-56
|
"cursor: mutex X"
|
Oracle - Database Tuning
|
Open
|
Major
|
UNRESOLVED
|
ubTools Support
|
ubTools Support
|
27/Jul/13 10:25 AM
|
28/Jul/13 05:36 PM
|
|
|
0
|
|
|
|
The customer has upgraded from Oracle 10.2.0.5 to Oracle 11.2.0.3.7. They encountered _library cache lock_ problem.
Some excerpt from the AWR:
{noformat}
Elapsed: 15.01 (mins)
DB Time: 6,548.72 (mins)
.....
Top 5 Timed Foreground Events
Event Waits Time(s) Avg wait (ms) % DB time Wait Class
library cache lock 425 364,186 856909 92.69 Concurrency
enq: TX - row lock contention 288 11,500 39930 2.93 Application
TCP Socket (KGAS) 136,317 9,552 70 2.43 Network
DB CPU 4,167 1.06
db file sequential read 742,541 2,176 3 0.55 User I/O
{noformat}
|
11.2.0.3.7
|
Solaris
|
.
|
.
|
|
|
|
|
Questions & Answers
|
QA-49
|
ORA-4031: High Allocation for "Oracle Text Commit new id" in Shared Pool.
|
Oracle - Database Tuning
|
Closed
|
Major
|
Answered
|
ubTools Support
|
ubTools Support
|
05/Nov/10 10:01 PM
|
05/Nov/10 10:47 PM
|
|
|
0
|
|
|
|
The customer encountered ORA-4031 and trace file generated. SGA is an ASMM SGA. The application uses Oracle Text.
|
10.2.0.4
|
Solaris
|
.
|
.
|
|
|
|
|
Questions & Answers
|
QA-44
|
TNS connection lost for big SQL*Net packets, and slow performance for small SQL*Net packets.
|
Oracle - Database Tuning
|
Closed
|
Major
|
Answered
|
ubTools Support
|
ubTools Support
|
26/Nov/08 12:28 PM
|
26/Nov/08 01:38 PM
|
|
|
0
|
|
|
|
The customer has the following errors in SQ*Net SERVER trace:
{noformat}
[17-KAS-2008 06:02:33:866] nspsend: transport write error
[17-KAS-2008 06:02:33:867] nserror: nsres: id=0, op=67, ns=12547, ns2=12560; nt[0]=517, nt[1]=32, nt[2]=0; ora[
0]=0, ora[1]=0, ora[2]=0
[17-KAS-2008 06:02:33:868] nsdo: nsctxrnk=0
[17-KAS-2008 06:02:33:869] nioqsn: send failed: bl = 47, nicbl = 59
[17-KAS-2008 06:02:33:870] nioqper: error from nioqsn
[17-KAS-2008 06:02:33:871] nioqper: nr err code: 0
[17-KAS-2008 06:02:33:872] nioqper: ns main err code: 12547
[17-KAS-2008 06:02:33:873] nioqper: ns (2) err code: 12560
[17-KAS-2008 06:02:33:875] nioqper: nt main err code: 517
[17-KAS-2008 06:02:33:876] nioqper: nt (2) err code: 32
[17-KAS-2008 06:02:33:877] nioqper: nt OS err code: 0
[17-KAS-2008 06:02:33:878] nioqer: entry
[17-KAS-2008 06:02:33:879] nioqce: entry
[17-KAS-2008 06:02:33:880] nioqce: exit
[17-KAS-2008 06:02:33:881] nioqer: exit
[17-KAS-2008 06:02:33:882] nioqsn: returning error: 3113
{noformat}
nt[1]=32 is Operating System Dependent(OSD) error code.
An excerpt from truss output of SERVER process:
{noformat}
531245: lseek(7, 0, SEEK_CUR) = 501528
531245: write(7, " [ 1 7 - K A S - 2 0 0 8".., 34) = 34
531245: lseek(7, 0, SEEK_CUR) = 501562
531245: write(7, " e n t r y\n", 6) = 6
531245: write(12, "07DB\0\006\0\0\0\0\002C2".., 2011) Err#32 Broken pipe
531245: Received signal #13, SIGPIPE [ignored]
531245: siginfo: SIGPIPE
531245: lseek(8, 69632, SEEK_SET) = 69632
531245: read(8, "12\0DB0F\0\0 t\0DC0F\0\0".., 512) = 512
531245: lseek(8, 13312, SEEK_SET) = 13312
531245: read(8, "19\0A203\0\09E\0A303\0\0".., 512) = 512
531245: gettimeofday(0x000000011FFF7A90, 0x00000000) = 0
531245: lseek(7, 0, SEEK_CUR) = 501568
{noformat}
OSD error is Err#32 Broken pipe. This OSD error is also defined in errno.h:
- #define EPIPE 32 /* Broken pipe */
Client side SQL*Net trace shows that client is waiting for a response from server on nttrd() call.
Since the server process is lost connection, it's not able to send a message to the client side. Since the client side is not getting a response, his screen waits in "Not Responding" state in Windows.
|
Oracle 9i
|
TRU64
|
|
|
|
|
|
|
Questions & Answers
|
QA-43
|
Slow performance while navigating on the forms items.
|
Oracle - Database Tuning
|
Closed
|
Major
|
Answered
|
ubTools Support
|
ubTools Support
|
26/Nov/08 11:56 AM
|
26/Nov/08 12:10 PM
|
|
|
0
|
|
|
|
The customer encountered slow performance while navigating on their forms items. The problem occured sporadically. When it occurs it takes 3-4 seconds, which are not acceptable.
An excerpt from EVENT 10046 trace file:
{noformat}
*** [ Windows thread id: 5580 ]
*** 2008-11-24 21:27:20.390
RPC CALL:...(stament removed);
=====================
PARSING IN CURSOR #5 len=56 dep=1 uid=78 oct=3 lid=78 tim=1420397928
hv=3822139714 ad='57c1a3bc'
SELECT ...(stament removed)
END OF STMT
PARSE #5:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1420397924
EXEC #5:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1420398028
FETCH #5:c=0,e=14,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=1,tim=1420398156
RPC EXEC:c=0,e=0
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1297371904
#bytes=1 p3=0 obj#=-1 tim=1420398646
*** 2008-11-24 21:27:20.765
WAIT #0: nam='SQL*Net message from client' ela= 3 driver id=1297371904
#bytes=1 p3=0 obj#=-1 tim=1420772565
RPC CALL:...(stament removed);
EXEC #5:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1420773632
FETCH #5:c=0,e=14,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=1,tim=1420773671
RPC EXEC:c=0,e=0
WAIT #0: nam='SQL*Net message to client' ela= 5 driver id=1297371904
#bytes=1 p3=0 obj#=-1 tim=1420774146
*** [ Windows thread id: 4416 ]
*** 2008-11-24 21:27:24.765
WAIT #0: nam='SQL*Net message from client' ela= 6 driver id=1297371904
#bytes=1 p3=0 obj#=-1 tim=1424766291
RPC CALL:...(stament removed);
=====================
PARSING IN CURSOR #7 len=70 dep=1 uid=78 oct=3 lid=78 tim=1424767161
hv=2516830579 ad='5af8ae9c'
SELECT ...(stament removed)
END OF STMT
PARSE #7:c=0,e=78,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1424767156
EXEC #7:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1424767987
FETCH #7:c=0,e=94,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,tim=1424768238
RPC EXEC:c=0,e=0
WAIT #0: nam='SQL*Net message to client' ela= 7 driver id=1297371904
#bytes=1 p3=0 obj#=-1 tim=1424768583
PUT: vc (659FD948), msg (5CF1D5B0), size (90), flgs (3)
*** [ Windows thread id: 5580 ]
*** 2008-11-24 21:27:24.765
WAIT #0: nam='SQL*Net message from client' ela= 4 driver id=1297371904
#bytes=1 p3=0 obj#=-1 tim=1424771121
RPC CALL:...(stament removed);
=====================
PARSING IN CURSOR #8 len=90 dep=1 uid=78 oct=3 lid=78 tim=1424772412
hv=1036237733 ad='5d1575f0'
SELECT ...(stament removed)
END OF STMT
PARSE #8:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1424772407
EXEC #8:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1424772567
FETCH #8:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1424772608
RPC EXEC:c=0,e=0
WAIT #0: nam='SQL*Net message to client' ela= 6 driver id=1297371904
#bytes=4 p3=0 obj#=-1 tim=1424773339
{noformat}
|
Oracle 10g 10.2.0.4
|
Windows
|
|
|
|
2003
|
|
|
Questions & Answers
|
QA-39
|
Database hangs on "cursor: pin S wait on X" wait events.
|
Oracle - Database Tuning
|
Closed
|
Major
|
Answered
|
ubTools Support
|
ubTools Support
|
07/Jun/08 05:35 PM
|
07/Jun/08 07:05 PM
|
|
|
0
|
|
|
|
The Database hangs.
The ASH report shows the activity on _cursor: pin S wait on X_ wait event.
{noformat}
Top User Events
Event Event Class % Activity Avg Active Sessions
cursor: pin S wait on X Concurrency 98.90 13.74
{noformat}
An excerpt from SYSTEMSTATE (level 10) dump
{noformat}
PROCESS 23:
...
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=42033 wait_time=0 seconds since wait started=0
idn=ec048ba, value=137000000000, where|sleeps=5007f3271
...
----------------------------------------
KGX Atomic Operation Log 7000000d44f4280
Mutex 7000000d92bce40(4976, 0) idn ec048ba oper GET_SHRD
Cursor Pin uid 4939 efd 0 whr 5 slp 44251
opr=2 pso=7000000cefa5df0 flg=0
pcs=7000000d92bce40 nxt=7000000cb6ed710 flg=35 cld=0 hd=7000000fc8611f0 par=7000000d94637a0
ct=4 hsh=0 unp=0 unn=0 hvl=cb6eda00 nhv=1 ses=7000000f78e0770
hep=7000000d92bcec0 flg=80 ld=1 ob=7000000d9c1b3a8 ptr=7000000991e6108 fex=7000000991e5418
----------------------------------------
...
PROCESS 33:
...
----------------------------------------
SO: 7000000f78e0770, type: 4, owner: 7000000fa8bbcf8, flag: INIT/-/-/0x00
(session) sid: 4976 trans: 7000000f10ce318, creator: 7000000fa8bbcf8, flag: (8100041) USR/- BSY/-/-/-/-/-
DID: 0001-0021-000193D1, short-term DID: 0000-0000-00000000
txn branch: 0
oct: 3, prv: 0, sql: 7000000fc179fa8, psql: 7000000fc68f018, user: 0/SYS
O/S info: user: orapaky0, term: , ospid: 5099938, machine: akmenkulp2
program: sqlplus@akmenkulp2 (TNS V1-V3)
application name: sqlplus@akmenkulp2 (TNS V1-V3), hash value=0
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=27479 wait_time=0 seconds since wait started=0
idn=ec048ba, value=137000000000, where|sleeps=5007f33be
...
----------------------------------------
KGX Atomic Operation Log 7000000fc64adb8
Mutex 7000000d92bce40(4976, 0) idn ec048ba oper GET_SHRD
Cursor Pin uid 4976 efd 0 whr 5 slp 15527
opr=2 pso=7000000d86f7d88 flg=0
pcs=7000000d92bce40 nxt=7000000cb6ed710 flg=35 cld=0 hd=7000000fc8611f0 par=7000000d94637a0
ct=4 hsh=0 unp=0 unn=0 hvl=cb6eda00 nhv=1 ses=7000000f78e0770
hep=7000000d92bcec0 flg=80 ld=1 ob=7000000d9c1b3a8 ptr=7000000991e6108 fex=7000000991e5418
----------------------------------------
...
----------------------------------------
KGX Atomic Operation Log 7000000fc64ad80
Mutex 7000000d92bce40(4976, 0) idn ec048ba oper EXCL
Cursor Pin uid 4976 efd 0 whr 1 slp 0
opr=3 pso=7000000cee2b2c0 flg=0
pcs=7000000d92bce40 nxt=7000000cb6ed710 flg=35 cld=0 hd=7000000fc8611f0 par=7000000d94637a0
ct=4 hsh=0 unp=0 unn=0 hvl=cb6eda00 nhv=1 ses=7000000f78e0770
hep=7000000d92bcec0 flg=80 ld=1 ob=7000000d9c1b3a8 ptr=7000000991e6108 fex=7000000991e5418
----------------------------------------
...
PROCESS 34:
...
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=63882 wait_time=0 seconds since wait started=0
idn=ec048ba, value=137000000000, where|sleeps=5007f348e
...
----------------------------------------
KGX Atomic Operation Log 7000000fdd75c30
Mutex 7000000d92bce40(4976, 0) idn ec048ba oper GET_SHRD
Cursor Pin uid 4693 efd 0 whr 5 slp 62048
opr=2 pso=7000000e7548610 flg=0
pcs=7000000d92bce40 nxt=7000000cb6ed710 flg=35 cld=0 hd=7000000fc8611f0 par=7000000d94637a0
ct=4 hsh=0 unp=0 unn=0 hvl=cb6eda00 nhv=1 ses=7000000f78e0770
hep=7000000d92bcec0 flg=80 ld=1 ob=7000000d9c1b3a8 ptr=7000000991e6108 fex=7000000991e5418
----------------------------------------
...
PROCESS 39:
...
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=12512 wait_time=0 seconds since wait started=0
idn=ec048ba, value=137000000000, where|sleeps=5007f36cf
...
----------------------------------------
KGX Atomic Operation Log 7000000fd857ad8
Mutex 7000000d92bce40(4976, 0) idn ec048ba oper GET_SHRD
Cursor Pin uid 4970 efd 0 whr 5 slp 12395
opr=2 pso=7000000cea1c250 flg=0
pcs=7000000d92bce40 nxt=7000000cb6ed710 flg=35 cld=0 hd=7000000fc8611f0 par=7000000d94637a0
ct=4 hsh=0 unp=0 unn=0 hvl=cb6eda00 nhv=1 ses=7000000f78e0770
hep=7000000d92bcec0 flg=80 ld=1 ob=7000000d9c1b3a8 ptr=7000000991e6108 fex=7000000991e5418
----------------------------------------
...
PROCESS 47:
...
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=48746 wait_time=0 seconds since wait started=0
idn=16a1ebe6, value=132e00000000, where|sleeps=5002494fe
...
----------------------------------------
KGX Atomic Operation Log 7000000c5ca4690
Mutex 7000000d71fd6b0(4910, 0) idn 16a1ebe6 oper GET_SHRD
Cursor Pin uid 4896 efd 0 whr 5 slp 48634
opr=2 pso=7000000e24f7e30 flg=0
pcs=7000000d71fd6b0 nxt=0 flg=35 cld=0 hd=7000000fda5fc00 par=7000000d71fdaa0
ct=0 hsh=0 unp=0 unn=0 hvl=d71fdd78 nhv=1 ses=7000000f78b5cc0
hep=7000000d71fd730 flg=80 ld=1 ob=7000000d76d3848 ptr=70000008a8ff478 fex=70000008a8fe788
----------------------------------------
...
PROCESS 53:
...
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=38686 wait_time=0 seconds since wait started=0
idn=16a1ebe6, value=132e00000000, where|sleeps=500249647
...
----------------------------------------
KGX Atomic Operation Log 7000000db1dee98
Mutex 7000000d71fd6b0(4910, 0) idn 16a1ebe6 oper GET_SHRD
Cursor Pin uid 4828 efd 0 whr 5 slp 38647
opr=2 pso=7000000e7f58940 flg=0
pcs=7000000d71fd6b0 nxt=0 flg=35 cld=0 hd=7000000fda5fc00 par=7000000d71fdaa0
ct=0 hsh=0 unp=0 unn=0 hvl=d71fdd78 nhv=1 ses=7000000f78b5cc0
hep=7000000d71fd730 flg=80 ld=1 ob=7000000d76d3848 ptr=70000008a8ff478 fex=70000008a8fe788
----------------------------------------
...
PROCESS 54:
...
(session) sid: 4910 trans: 0, creator: 7000000d81123c0, flag: (e1) USR/- BSY/-/-/-/-/-
DID: 0001-002F-00044CCF, short-term DID: 0000-0000-00000000
txn branch: 0
oct: 3, prv: 0, sql: 7000000dbd12ce0, psql: 7000000dbb98da0, user: 55/SYSMAN
O/S info: user: orapaky0, term: unknown, ospid: 1234, machine: akmenkulp2
program: OMS
client info: akmenkulp2_Management_Service
application name: OEM.DefaultPool, hash value=3997945242
action name: /database/instance/sitemap, hash value=105676648
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=54571 wait_time=0 seconds since wait started=0
idn=ec048ba, value=137000000000, where|sleeps=5007f3abc
...
----------------------------------------
KGX Atomic Operation Log 7000000dcd36f50
Mutex 7000000d92bce40(4976, 0) idn ec048ba oper GET_SHRD
Cursor Pin uid 4910 efd 0 whr 5 slp 53641
opr=2 pso=7000000e7c7f338 flg=0
pcs=7000000d92bce40 nxt=7000000cb6ed710 flg=35 cld=0 hd=7000000fc8611f0 par=7000000d94637a0
ct=4 hsh=0 unp=0 unn=0 hvl=cb6eda00 nhv=1 ses=7000000f78e0770
hep=7000000d92bcec0 flg=80 ld=1 ob=7000000d9c1b3a8 ptr=7000000991e6108 fex=7000000991e5418
----------------------------------------
...
----------------------------------------
KGX Atomic Operation Log 7000000dcd36e38
Mutex 7000000d71fd6b0(4910, 0) idn 16a1ebe6 oper EXCL
Cursor Pin uid 4910 efd 0 whr 1 slp 0
opr=3 pso=7000000e79b9030 flg=0
pcs=7000000d71fd6b0 nxt=0 flg=35 cld=0 hd=7000000fda5fc00 par=7000000d71fdaa0
ct=0 hsh=0 unp=0 unn=0 hvl=d71fdd78 nhv=1 ses=7000000f78b5cc0
hep=7000000d71fd730 flg=80 ld=1 ob=7000000d76d3848 ptr=70000008a8ff478 fex=70000008a8fe788
----------------------------------------
...
PROCESS 55:
...
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=39147 wait_time=0 seconds since wait started=0
idn=16a1ebe6, value=132e00000000, where|sleeps=5002496e9
...
----------------------------------------
KGX Atomic Operation Log 7000000dbb57a10
Mutex 7000000d71fd6b0(4910, 0) idn 16a1ebe6 oper GET_SHRD
Cursor Pin uid 4973 efd 0 whr 5 slp 39118
opr=2 pso=7000000ce4e6fe8 flg=0
pcs=7000000d71fd6b0 nxt=0 flg=35 cld=0 hd=7000000fda5fc00 par=7000000d71fdaa0
ct=0 hsh=0 unp=0 unn=0 hvl=d71fdd78 nhv=1 ses=7000000f78b5cc0
hep=7000000d71fd730 flg=80 ld=1 ob=7000000d76d3848 ptr=70000008a8ff478 fex=70000008a8fe788
----------------------------------------
...
PROCESS 62:
...
(session) sid: 4805 trans: 0, creator: 7000000eab6d018, flag: (e1) USR/- BSY/-/-/-/-/-
DID: 0001-003E-00010563, short-term DID: 0000-0000-00000000
txn branch: 0
oct: 3, prv: 0, sql: 7000000dce39e08, psql: 7000000dc0fc240, user: 72/MENKUL2008
O/S info: user: akbank, term: L1058, ospid: 3468:3428, machine: AA\L1058
program: toad.exe
application name: TOAD 9.1.0.62, hash value=3156025525
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=41562 wait_time=0 seconds since wait started=0
idn=ec048ba, value=137000000000, where|sleeps=5007f3dc4
...
----------------------------------------
KGX Atomic Operation Log 7000000db0f6b20
Mutex 7000000d92bce40(4976, 0) idn ec048ba oper GET_SHRD
Cursor Pin uid 4805 efd 0 whr 5 slp 41523
opr=2 pso=7000000ce1b0070 flg=0
pcs=7000000d92bce40 nxt=7000000cb6ed710 flg=35 cld=0 hd=7000000fc8611f0 par=7000000d94637a0
ct=4 hsh=0 unp=0 unn=0 hvl=cb6eda00 nhv=1 ses=7000000f78e0770
hep=7000000d92bcec0 flg=80 ld=1 ob=7000000d9c1b3a8 ptr=7000000991e6108 fex=7000000991e5418
----------------------------------------
...
----------------------------------------
KGX Atomic Operation Log 7000000db0f6ae8
Mutex 7000000e51cde60(4805, 0) idn 7a99f649 oper EXCL
Cursor Pin uid 4805 efd 0 whr 1 slp 0
opr=3 pso=7000000d8b887e8 flg=0
pcs=7000000e51cde60 nxt=0 flg=35 cld=0 hd=7000000dcd2b108 par=7000000d9991e20
ct=0 hsh=0 unp=0 unn=0 hvl=d99920f8 nhv=1 ses=7000000f88942e0
hep=7000000e51cdee0 flg=80 ld=1 ob=7000000e59bf060 ptr=7000000882ed3d8 fex=7000000882ec6e8
----------------------------------------
...
PROCESS 65:
...
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=35648 wait_time=0 seconds since wait started=0
idn=7a99f649, value=12c500000000, where|sleeps=500028b22
...
----------------------------------------
KGX Atomic Operation Log 7000000fd34bbf8
Mutex 7000000e51cde60(4805, 0) idn 7a99f649 oper GET_SHRD
Cursor Pin uid 4570 efd 0 whr 5 slp 35618
opr=2 pso=7000000d898d0c0 flg=0
pcs=7000000e51cde60 nxt=0 flg=35 cld=0 hd=7000000dcd2b108 par=7000000d9991e20
ct=0 hsh=0 unp=0 unn=0 hvl=d99920f8 nhv=1 ses=7000000f88942e0
hep=7000000e51cdee0 flg=80 ld=1 ob=7000000e59bf060 ptr=7000000882ed3d8 fex=7000000882ec6e8
----------------------------------------
...
PROCESS 68:
...
(session) sid: 4698 trans: 0, creator: 7000000f98a7320, flag: (41) USR/- BSY/-/-/-/-/-
DID: 0001-0044-00000344, short-term DID: 0000-0000-00000000
txn branch: 0
oct: 3, prv: 0, sql: 7000000c5281eb8, psql: 7000000d4d7e910, user: 72/MENKUL2008
O/S info: user: geneks, term: AKYGM011, ospid: 3168:3148, machine: AKYATIRIM\AKYGM011
program:
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=44607 wait_time=0 seconds since wait started=0
idn=ec048ba, value=137000000000, where|sleeps=5007f3dfe
...
----------------------------------------
KGX Atomic Operation Log 7000000dc155c48
Mutex 7000000d92bce40(4976, 0) idn ec048ba oper GET_SHRD
Cursor Pin uid 4698 efd 0 whr 5 slp 8722
opr=2 pso=7000000cea6fce8 flg=0
pcs=7000000d92bce40 nxt=7000000cb6ed710 flg=35 cld=0 hd=7000000fc8611f0 par=7000000d94637a0
ct=4 hsh=0 unp=0 unn=0 hvl=cb6eda00 nhv=1 ses=7000000f78e0770
hep=7000000d92bcec0 flg=80 ld=1 ob=7000000d9c1b3a8 ptr=7000000991e6108 fex=7000000991e5418
----------------------------------------
...
----------------------------------------
KGX Atomic Operation Log 7000000dc155c10
Mutex 7000000e5f9cd90(4698, 0) idn 651e7adb oper EXCL
Cursor Pin uid 4698 efd 0 whr 1 slp 0
opr=3 pso=7000000cef62b68 flg=0
pcs=7000000e5f9cd90 nxt=0 flg=34 cld=1 hd=7000000dcea52a8 par=7000000e5f9d708
ct=1 hsh=0 unp=0 unn=0 hvl=e5f9d098 nhv=1 ses=7000000f782cbe0
hep=7000000e5f9ce10 flg=80 ld=1 ob=7000000e53207c8 ptr=700000099b3ef88 fex=700000099b3e298
----------------------------------------
...
PROCESS 70:
...
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=34939 wait_time=0 seconds since wait started=0
idn=ec048ba, value=137000000000, where|sleeps=5007f3e0f
...
----------------------------------------
KGX Atomic Operation Log 7000000fc176d20
Mutex 7000000d92bce40(4976, 0) idn ec048ba oper GET_SHRD
Cursor Pin uid 4784 efd 0 whr 5 slp 33075
opr=2 pso=7000000ceb24778 flg=0
pcs=7000000d92bce40 nxt=7000000cb6ed710 flg=35 cld=0 hd=7000000fc8611f0 par=7000000d94637a0
ct=4 hsh=0 unp=0 unn=0 hvl=cb6eda00 nhv=1 ses=7000000f78e0770
hep=7000000d92bcec0 flg=80 ld=1 ob=7000000d9c1b3a8 ptr=7000000991e6108 fex=7000000991e5418
----------------------------------------
...
PROCESS 73:
...
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=24155 wait_time=0 seconds since wait started=0
idn=651e7adb, value=125a00000000, where|sleeps=5000121e2
...
----------------------------------------
KGX Atomic Operation Log 7000000dc4eba08
Mutex 7000000e5f9cd90(4698, 0) idn 651e7adb oper GET_SHRD
Cursor Pin uid 4637 efd 0 whr 5 slp 8674
opr=2 pso=7000000cef8dcb0 flg=0
pcs=7000000e5f9cd90 nxt=0 flg=34 cld=1 hd=7000000dcea52a8 par=7000000e5f9d708
ct=1 hsh=0 unp=0 unn=0 hvl=e5f9d098 nhv=1 ses=7000000f782cbe0
hep=7000000e5f9ce10 flg=80 ld=1 ob=7000000e53207c8 ptr=700000099b3ef88 fex=700000099b3e298
----------------------------------------
...
PROCESS 76:
...
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=35688 wait_time=0 seconds since wait started=0
idn=ec048ba, value=137000000000, where|sleeps=5007f3ed4
...
----------------------------------------
KGX Atomic Operation Log 7000000fc655c80
Mutex 7000000d92bce40(4976, 0) idn ec048ba oper GET_SHRD
Cursor Pin uid 4806 efd 0 whr 5 slp 35673
opr=2 pso=7000000ce702c90 flg=0
pcs=7000000d92bce40 nxt=7000000cb6ed710 flg=35 cld=0 hd=7000000fc8611f0 par=7000000d94637a0
ct=4 hsh=0 unp=0 unn=0 hvl=cb6eda00 nhv=1 ses=7000000f78e0770
hep=7000000d92bcec0 flg=80 ld=1 ob=7000000d9c1b3a8 ptr=7000000991e6108 fex=7000000991e5418
----------------------------------------
...
PROCESS 142:
...
waiting for 'cursor: pin S wait on X' blocking sess=0x0 seq=48159 wait_time=0 seconds since wait started=0
idn=16a1ebe6, value=132e00000000, where|sleeps=5002499ac
...
----------------------------------------
KGX Atomic Operation Log 7000000db235510
Mutex 7000000d71fd6b0(4910, 0) idn 16a1ebe6 oper GET_SHRD
Cursor Pin uid 4592 efd 0 whr 5 slp 48111
opr=2 pso=7000000e2252830 flg=0
pcs=7000000d71fd6b0 nxt=0 flg=35 cld=0 hd=7000000fda5fc00 par=7000000d71fdaa0
ct=0 hsh=0 unp=0 unn=0 hvl=d71fdd78 nhv=1 ses=7000000f78b5cc0
hep=7000000d71fd730 flg=80 ld=1 ob=7000000d76d3848 ptr=70000008a8ff478 fex=70000008a8fe788
----------------------------------------
...
{noformat}
|
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
|
IBM-AIX
|
|
|
|
|
|
|
Questions & Answers
|
QA-36
|
Who is the inventor of Response Time Analysis(RTA) in Oracle ?
|
Oracle - Database Tuning
|
Closed
|
Major
|
Answered
|
ubTools Support
|
ubTools Support
|
08/Apr/08 09:14 AM
|
01/May/08 06:43 AM
|
|
|
0
|
|
|
|
This issue moved to http://www.ubtools.com/web/public/resources/logs/rta_inventor.
|
X
|
Generic
|
|
|
|
|
|
|
Questions & Answers
|
QA-16
|
Does commit cause checkpoint ?
|
Oracle - Database Tuning
|
Closed
|
Major
|
Answered
|
ubTools Support
|
ubTools Support
|
15/Jul/07 02:33 PM
|
16/Sep/07 04:28 PM
|
|
|
0
|
|
|
|
Does commit cause checkpoint ?
|
Generic
|
Generic
|
|
|
|
|
|
|
Questions & Answers
|
QA-15
|
SQ enqueue problem.
|
Oracle - Database Tuning
|
Closed
|
Major
|
Answered
|
ubTools Support
|
ubTools Support
|
15/Jul/07 02:18 PM
|
16/Sep/07 04:28 PM
|
|
|
0
|
|
|
|
Other than SYSDBA, no new connections allowed to the database.
|
10.1.0.3
|
Generic
|
|
|
|
|
|
|
Questions & Answers
|
QA-14
|
is the current CPU breakdown formula correct ?
|
Oracle - Database Tuning
|
Closed
|
Major
|
Answered
|
ubTools Support
|
ubTools Support
|
15/Jul/07 01:49 PM
|
19/Sep/07 12:13 PM
|
|
|
0
|
|
|
|
is the current CPU breakdown formula correct ?
bq.{color:red} CPU used by this session = parse time cpu + recursive cpu usage + others{color}
|
Generic
|
Generic
|
|
|
|
|
|
|
Questions & Answers
|
QA-13
|
Dumping a stack trace is too slow in 10g.
|
Oracle - Database Tuning
|
Closed
|
Major
|
Answered
|
ubTools Support
|
ubTools Support
|
15/Jul/07 01:45 PM
|
16/Sep/07 04:29 PM
|
|
|
0
|
|
|
|
h4.Error code:
ORA-4031 (may not be seen by end users).
h4.Error code definition:
The CPU usage reaches 98% in *KERNEL* mode. _strace_ utility on linux reports that the process spins on *read()* system call.
h4.System calls:
An excerpt from _strace -p <OSPID>_ output:
{noformat}
read(29, "<\345&\0\1\0\21\0\330Wk\10\0\0\0@\30\0\0\0\0\0\0\0", 24) = 24
read(29, "I\345&\0\1\0\22\0\230\226\217\10\0\0\0@\30\0\0\0\0\0\0"..., 24) = 24
read(29, "\20\1\0\0\1\0\24\0\260\n3\0\0\0\0`\20\0\0\0\0\0\0\0", 24) = 24
read(29, "\34\1\0\0\1\0\34\0`\200\353\0\0\0\0`\10\0\0\0\0\0\0\0", 24) = 24
read(29, "\'\1\0\0\1\0\34\0h\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24
read(29, "3\1\0\0\1\0\34\0l\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24
read(29, "V\345&\0\4\0\361\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 24) = 24
read(29, "`\345&\0\1\0\f\0\300XF\4\0\0\0@\4\0\0\0\0\0\0\0", 24) = 24
read(29, "k\345&\0\1\0\21\0\20Xk\10\0\0\0@\30\0\0\0\0\0\0\0", 24) = 24
read(29, "y\345&\0\1\0\22\0\260\226\217\10\0\0\0@\30\0\0\0\0\0\0"..., 24) = 24
read(29, "\20\1\0\0\1\0\24\0\300\n3\0\0\0\0`\20\0\0\0\0\0\0\0", 24) = 24
read(29, "\34\1\0\0\1\0\34\0p\200\353\0\0\0\0`\10\0\0\0\0\0\0\0", 24) = 24
read(29, "\'\1\0\0\1\0\34\0x\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24
read(29, "3\1\0\0\1\0\34\0|\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24
{noformat}
The file descriptor is 29(the first argument in read() system call). By linux _lsof_ command, the descriptor#29 is 1081732 _/oracle/product/10.1.0/bin/oracle_. In other words, the process is reading Oracle executable.
_strace -c -p <OSPID>_ output for 1 minute:
{noformat}
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00 21.570914 40 543060 read
0.00 0.000016 2 7 lseek
0.00 0.000003 3 1 getpid
0.00 0.000001 1 1 open
0.00 0.000001 1 1 readlink
------ ----------- ----------- --------- --------- ----------------
100.00 21.570935 543070 total
{noformat}
_read()_ system call had been called 543,060 times per minute. That's why CPU utilization in KERNEL mode is high.
An excerpt from stack trace by OS debugger:
{noformat}
#0 0x200000000137fa81 in read () from /lib/tls/libpthread.so.0
#1 0x4000000004d7a7e0 in sskgds_getsnm ()
#2 0x4000000002766160 in skdsttpcs ()
#3 0x4000000001131920 in ksedst ()
#4 0x40000000011b0140 in ksm_4031_dump ()
{noformat}
_ksm_4031_dump()_ function of Oracle dumps ORA-4031 traces. The top of the stack includes _read()_ system calls.
h4.Problem interpretation:
The process gets ORA-4031 error, then tries to dump trace file for this error. But, while dumping the trace, it spins on _read()_ system calls.
h4.Workaround:
Set the following parameters in pfile/spfile:
{noformat}
_4031_dump_bitvec = 0
_4031_max_dumps = 0
{noformat}
h4.Bug:
Ref: Oracle Note:3964602 DUMPING A CALL STACK TRACE IS SLOW.
|
10.1.0.2
|
Generic
|
|
|
|
|
|
|
|