有客户反馈一个问题,业务中有一张表无论是查询还是dml操作都非常慢,让我们介入分析
数据库版本
打上了170814比较新的psu
[oracle@xffdb1 ~]$ $ORACLE_HOME/OPatch/opatch lsinventory
Oracle 中间补丁程序安装程序版本 11.2.0.3.15
版权所有 (c) 2018, Oracle Corporation。保留所有权利。
Oracle Home : /u01/app/oracle/product/11.2.0/db_1
Central Inventory : /u01/app/oraInventory
from : /u01/app/oracle/product/11.2.0/db_1/oraInst.loc
OPatch version : 11.2.0.3.15
OUI version : 11.2.0.4.0
Log file location : /u01/app/oracle/product/11.2.0/db_1/cfgtoollogs/opatch/opatch2018-01-06_16-20-22下午_1.log
--------------------------------------------------------------------------------
Local Machine Information::
Hostname: xffdb1
ARU platform id: 226
ARU platform description:: Linux x86-64
已安装的顶级产品 (1):
Oracle Database 11g 11.2.0.4.0
此 Oracle 主目录中已安装 1 个产品。
中间补丁程序 (2) :
Patch 26609929 : applied on Fri Sep 15 14:28:51 CST 2017
Unique Patch ID: 21482966
Patch description: "OCW Patch Set Update : 11.2.0.4.170814 (26609929)"
Patch 26609445 : applied on Fri Sep 15 14:28:04 CST 2017
Unique Patch ID: 21482382
Patch description: "Database Patch Set Update : 11.2.0.4.170814 (26609445)"
awr数据结果
这里显示大量的library cache lock等待
做systemstate分析
Resource Holder State
LOCK: Handle=0x325d938e08 74: 74: is waiting for PIN: Handle=0x325d938e08
Enq TX-00E0001B-000004D3 488: 488: is waiting for 74:
Mutex 1e7fbf6c 322: 322: is waiting for 74:
Enq TX-02850009-00000086 630: 630: is waiting for 74:
Enq TX-02BC000A-0000009E ??? Blocker
Enq TX-0075000E-000010BE ??? Blocker
PIN: Handle=0x325d938e08 ??? Blocker
Enq TX-049A000C-00000002 ??? Blocker
Enq TX-034C001D-00000038 ??? Blocker
Enq TX-052C0012-00000002 669: 669: is waiting for 74:
Enq TX-04620004-00000003 ??? Blocker
Enq TX-009B0020-00000DA6 ??? Blocker
Mutex af4db5a8 242: 242: is waiting for 74:
Enq TX-041E0002-00000005 ??? Blocker
Mutex 663b253d 727: 727: is waiting for 74:
Enq TX-04FA0008-00000003 124: 124: is waiting for 69:
Enq TX-031D0010-0000005B ??? Blocker
Enq TX-02BB0004-000000A2 ??? Blocker
Enq TX-0248001A-000000CD 69: 69: is waiting for Enq TX-02BC000A-0000009E
Enq TX-03D70008-00000002 ??? Blocker
Enq TX-02B1001D-00000081 ??? Blocker
Enq TX-0423001A-00000003 ??? Blocker
Enq TX-051A0007-00000003 506: 506: is waiting for 74:
Mutex 2aceb8e9 602: 602: is waiting for 74:
Mutex c6b2e0f4 196: 196: is waiting for 74:
Enq TX-00A30020-0000055A ??? Blocker
Enq TX-00D70015-00000315 ??? Blocker
Enq TX-03B30006-00000012 ??? Blocker
Enq TX-008C0003-00001005 ??? Blocker
Enq TX-05470014-00000006 219: 219: is waiting for 74:
Enq TX-054E0018-00000006 673: 673: is waiting for 74:
Mutex f28c06f8 279: 279: is waiting for 74:
Enq TX-03D30012-00000002 ??? Blocker
Enq TX-055C001B-00000005 333: 333: is waiting for Enq TX-01CF000B-00000B2F
Mutex 2ff03da9 276: 276: is waiting for 74:
Enq TX-030A000A-000000B6 ??? Blocker
Enq TX-00530004-000023DF 212: 212: is waiting for 74:
Enq TX-05550017-00000002 469: 469: is waiting for 74:
Mutex 724ba5e3 177: 177: is waiting for 74:
Enq TX-03C10007-00000015 ??? Blocker
Enq TX-02E30006-00000079 ??? Blocker
IPC 6 6 Blocker
Enq TX-0289000B-0000005F 449: 449: is waiting for 74:
Enq TX-021E0002-000001DA ??? Blocker
Mutex a9fcc7b8 131: 131: is waiting for 74:
Enq TX-0483001F-00000009 ??? Blocker
Enq TX-00800010-00000BA0 ??? Blocker
Mutex c0af249e 666: 666: is waiting for 74:
Mutex 94389ed4 78: 78: is waiting for 74:
Mutex 4ac40611 143: 143: is waiting for 74:
Mutex 24c1c387 168: 168: is waiting for 74:
Mutex 930636c9 752: 752: is waiting for 74:
Enq TX-04660001-00000003 ??? Blocker
Enq TX-01B6000A-00000022 ??? Blocker
Enq TX-0166000F-000002C7 ??? Blocker
Enq TX-02FF0008-000000A1 ??? Blocker
Enq TX-01E10001-00000023 ??? Blocker
Enq TX-0327000E-0000009E ??? Blocker
Enq TX-05120016-00000002 615: 615: is waiting for 74:
Enq TX-039F001D-00000011 ??? Blocker
Enq TX-01CF000B-00000B2F ??? Blocker
Enq TX-01130020-000001B6 ??? Blocker
Enq TX-052A0021-00000002 635: 635: is waiting for 74:
Mutex ebf68fee 579: 579: is waiting for 74:
Enq TX-02350017-000000D6 ??? Blocker
Enq TX-00BB0000-00000598 ??? Blocker
Enq TX-0443000E-00000003 ??? Blocker
Mutex e7bae014 344: 344: is waiting for 74:
Mutex fe251793 616: 616: is waiting for 74:
Mutex 750494ae 180: 180: is waiting for 74:
Enq TX-01230010-000001C0 ??? Blocker
Enq TX-0543001C-00000003 119: 119: is waiting for 124:
Enq TX-04E60014-00000005 ??? Blocker
Enq TX-00F1000A-000002AB ??? Blocker
Mutex aa83fbd7 651: 651: is waiting for 74:
Enq TX-058A0002-00000003 ??? Blocker
Enq TX-03B00016-0000000F ??? Blocker
Mutex 26e065a4 150: 150: is waiting for 74:
Enq TX-0219001B-000001BE ??? Blocker
Enq TX-00B9001D-00000069 ??? Blocker
Enq TX-01110020-00000198 ??? Blocker
Enq TX-04F3001B-00000002 ??? Blocker
Enq TX-04A60015-00000002 ??? Blocker
Enq TX-02D30015-0000008A ??? Blocker
Enq TX-01540018-000001B7 ??? Blocker
Enq TX-02240019-0000001C ??? Blocker
Mutex e595002d 502: 502: is waiting for 74:
Mutex 1661a4cb 732: 732: is waiting for 74:
Enq TX-00320010-00003A12 ??? Blocker
Enq TX-020F001F-00000027 ??? Blocker
Enq TX-0387000A-0000004D 515: 515: is waiting for 74:
Enq TX-01260014-0000012D ??? Blocker
Enq TX-02EE001D-0000005F ??? Blocker
Enq TX-004A0001-00000882 603: 603: is waiting for Enq TX-02240019-0000001C
Mutex 4a18a781 258: 258: is waiting for 74:
LOCK: Handle=0x325aa4c428 643: 643: is waiting for 74:
Enq TX-037A0002-0000006E 118: 118: is waiting for 74:
Enq TX-02460020-0000006D 493: 493: is waiting for Enq TX-00F1000A-000002AB
PROCESS 74: J000
----------------------------------------
SO: 0x31a2b2e440, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x31a2b2e440, name=process, file=ksu.h LINE:12721, pg=0
(process) Oracle pid:74, ser:153, calls cur/top: 0x305d24c378/0x305f3f5eb0
flags : (0x0) -
flags2: (0x10), flags3: (0x10)
intr error: 0, call error: 0, sess error: 0, txn error 0
intr queue: empty
ksudlp FALSE at location: 0
(post info) last post received: 0 0 80
last post received-location: kji.h LINE:3691 ID:kjata: wake up enqueue owner
last process to post me: 0x3182a6fca0 1 6
last post sent: 0 0 26
last post sent-location: ksa2.h LINE:285 ID:ksasnd
last process posted by me: 0x3182a75038 2 6
(latch info) wait_event=0 bits=0x0
Process Group: DEFAULT, pseudo proc: 0x3162ddbe90
O/S info: user: oracle, term: UNKNOWN, ospid: 103036
OSD pid info: Unix process pid: 103036, image: oracle@xffdb1 (J000)
Short stack dump:
ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-semtimedop()+10
<-skgpwwait()+178<-ksliwat()+2046<-kslwaitctx()+163<-kjusuc()+3400
<-ksipgetctxi()+1759<-kqlmPin()+2943<-kqlmClusterLock()+237<-kglpnal()+4072
<-kglpin()+1381<-qostobkglcrt1()+640<-qostobkglcrt()+255<-qospsts()+1639
<-spefcmpa()+196<-spefmccallstd()+235<-pextproc()+41<-peftrusted()+150
<-psdexsp()+255<-rpiswu2()+1776<-psdextp()+700<-pefccal()+726<-pefcal()+224
<-pevm_FCAL()+169<-pfrinstr_FCAL()+75<-pfrrun_no_tool()+63<-pfrrun()+627
<-plsql_run()+649<-peidxr_run()+263<-peidxexe()+79<-kkxdexe()+338
<-kkxmpexe()+241<-kgmexwi()+605<-kgmexec()+2193<-evapls()+813
<-evaopn2()+808<-kkxmexcs()+133<-opiexe()+20880<-kpoal8()+2380
<-opiodr()+917<-kpoodr()+1401<-upirtrc()+2436<-kpurcsc()+98
<-kpuexec()+10790<-OCIStmtExecute()+39<-jslvec_execcb1()+672
<-jslvswu()+56<-jslve_execute0()+2257<-jslve_execute()+332
<-rpiswu2()+1776<-kkjex1e()+379<-kkjsexe()+711<-kkjrdp()+694
<-opirip()+958<-opidrv()+603<-sou2o()+103<-opimai_real()+250
<-ssthrdmain()+265<-main()+201<-__libc_start_main()+253
SO: 0x31c382f010, type: 4, owner: 0x31a2b2e440, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x31a2b2e440, name=session, file=ksu.h LINE:12729, pg=0
(session) sid: 6001 ser: 679 trans: 0x311e36fa28, creator: 0x31a2b2e440
flags: (0x8010041) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x40009) -/-/INC
DID: , short-term DID:
txn branch: (nil)
edition#: 100 oct: 170, prv: 0, sql: 0x323de178e8, psql: 0x32b5d0fc98, user: 0/SYS
ksuxds FALSE at location: 0
service name: SYS$USERS
client details:
O/S info: user: oracle, term: UNKNOWN, ospid: 103036
machine: xffdb1 program: oracle@xffdb1 (J000)
application name: DBMS_SCHEDULER, hash value=2478762354
action name: ORA$AT_OS_OPT_SY_1594, hash value=1524069073
Current Wait Stack:
0: waiting for 'library cache pin'
handle address=0x325d938e08, pin address=0x325baec3e0, 100*mode+namespace=0x850fe00010003
wait_id=46488 seq_num=46502 snap_id=1
wait times: snap=6 min 2 sec, exc=6 min 2 sec, total=6 min 2 sec
wait times: max=15 min 0 sec, heur=6 min 2 sec
wait counts: calls=727 os=727
in_wait=1 iflags=0x15a2
There are 2136 sessions blocked by this session.
发现主要是74号进程阻塞了其他的
做hanganalyze分析
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 1 (xffdb.xffdbsv1)
os id: 82310
process id: 224, oracle@xffdb1
session id: 4
session serial #: 12237
}
is waiting for 'enq: TX - row lock contention' with wait info:
{
p1: 'name|mode'=0x54580006
p2: 'usn<<16 | slot'=0x21e0002
p3: 'sequence'=0x1da
time in wait: 3 min 48 sec
timeout after: never
wait id: 1260
blocking: 0 sessions
current sql: UPDATE t_xifenfei subpartition(p201801_s32)
SET INDICATORCODE = :1,
LOWERLIMIT = :2,
UPPERLIMIT = :3,
AVGUNITPRICE = :4,
TRADEITEMNAME = :5,
short stack: ………………
wait history:
* time between current wait and wait #1: 0.000220 sec
1. event: 'gc cr block 2-way'
time waited: 0.000341 sec
wait id: 1259 p1: ''=0x6
p2: ''=0x3590
p3: ''=0x44b
* time between wait #1 and #2: 0.000284 sec
2. event: 'gc current block 3-way'
time waited: 0.000663 sec
wait id: 1258 p1: ''=0xa
p2: ''=0x3ad02
p3: ''=0x2000001
* time between wait #2 and #3: 0.000383 sec
3. event: 'gc cr block 2-way'
time waited: 0.000288 sec
wait id: 1257 p1: ''=0x5
p2: ''=0x2e20
p3: ''=0x957
}
and is blocked by
=> Oracle session identified by:
{
instance: 3 (xffdb.xffdbsv3)
os id: 39472
process id: 587, oracle@xffdb3
session id: 2215
session serial #: 8213
}
which is waiting for 'library cache lock' with wait info:
{
p1: 'handle address'=0x327f5ecea0
p2: 'lock address'=0x327a5ab660
p3: '100*mode+namespace'=0x850fe00010002
time in wait: 3 min 43 sec
timeout after: 11 min 16 sec
wait id: 2343
blocking: 3 sessions
current sql: SELECT COUNT(*) COUNT
FROM t_xifenfei subpartition(p201801_s32)
WHERE TRADEITEMID = '679EA6DE428F414D014B3D5EC8DE5E32'
short stack: ………………
wait history:
* time between current wait and wait #1: 0.000908 sec
1. event: 'SQL*Net message from client'
time waited: 0.001074 sec
wait id: 2342 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #1 and #2: 0.000033 sec
2. event: 'SQL*Net message to client'
time waited: 0.000003 sec
wait id: 2341 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #2 and #3: 0.000069 sec
3. event: 'SQL*Net message from client'
time waited: 0.001232 sec
wait id: 2340 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
}
and is blocked by
=> Oracle session identified by:
{
instance: 1 (xffdb.xffdbsv1)
os id: 103036
process id: 74, oracle@xffdb1 (J000)
session id: 6001
session serial #: 679
}
which is waiting for 'library cache pin' with wait info:
{
p1: 'handle address'=0x325d938e08
p2: 'pin address'=0x325baec3e0
p3: '100*mode+namespace'=0x850fe00010003
time in wait: 3 min 47 sec
timeout after: 11 min 12 sec
wait id: 46488
blocking: 2099 sessions
current sql: call dbms_stats.gather_database_stats_job_proc ( )
short stack: …………
wait history:
* time between current wait and wait #1: 0.000038 sec
1. event: 'library cache lock'
time waited: 0.012353 sec
wait id: 46487 p1: 'handle address'=0x325d938e08
p2: 'lock address'=0x3259aee680
p3: '100*mode+namespace'=0x850fe00010003
* time between wait #1 and #2: 0.002509 sec
2. event: 'enq: IV - contention'
time waited: 0.001079 sec
wait id: 46486 p1: 'type|mode'=0x49560005
p2: 'id1'=0x53594e43
p3: 'id2'=0x15
* time between wait #2 and #3: 0.000085 sec
3. event: 'enq: IV - contention'
time waited: 0.001817 sec
wait id: 46485 p1: 'type|mode'=0x49560005
p2: 'id1'=0x4c4f434b
p3: 'id2'=0x15
}
Chain 1 Signature: 'library cache pin'<='library cache lock'<='enq: TX - row lock contention'
Chain 1 Signature Hash: 0xa08ff7bf
到这里基本上可以确定是由于自动任务收集统计信息导致系统出现大量的library cache lock和library cache pin,另外可以确定大部分被阻塞在library cache 相关的select和dml语句都集中在t_xifenfei这个子分区表中,通过查询mos,发现相关bug:Bug 19790972 – “library cache lock” waits due to DBMS_STATS gather of stats for a subpartition
