当前位置: 首页 > EVENT, systemstate > 正文

SQL语法错误导致library cache lock/library cache:mutex X

下面测试来至于群里面一位兄弟数据库出来大量的library cache lock/library cache:mutex X,原以为是BUG导致,最后确认是由于sql语法错误导致的,下面是在11.2.0.3环境中模拟现象

欢迎大家加入QQ群ORACLE数据库超级群 讨论

1DBOS版本

www.htz.pw > select * from v$version;

 

BANNER

——————————————————————————–

Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 – 64bit Production

PL/SQL Release 11.2.0.3.0 – Production

CORE    11.2.0.3.0      Production

TNS for Linux: Version 11.2.0.3.0 – Production

NLSRTL Version 11.2.0.3.0 – Production

 

www.htz.pw > !lsb_release -a

LSB Version:    :core-3.0-amd64:core-3.0-ia32:core-3.0-noarch:graphics-3.0-amd64:graphics-3.0-ia32:graphics-3.0-noarch

Distributor ID: RedHatEnterpriseAS

Description:    Red Hat Enterprise Linux AS release 4 (Nahant Update 8)

Release:        4

Codename:       NahantUpdate8

2,测试脚本

[oracle@www.htz.pw sql]$cat /tmp/total1.sh

#!/bin/bash

for i in {1..1000}

do

nohup /tmp/runsql.sh &

echo $i

done

 

[oracle@www.htz.pw sql]$cat /tmp/total.sh

#!/bin/bash

for b in {1..100}

do

nohup /tmp/total1.sh >/tmp/total$b &

echo $b

done

 

[oracle@www.htz.pw sql]$cat /tmp/runsql.sh

sqlplus -s / as sysdba <<EOF

SELECT rowid,distinct ename from scott.emp;

SELECT rowid,distinct ename from scott.emp;

……………………………..

SELECT rowid,distinct ename from scott.emp;

exit

下面脚本用于生成trace文件用于分析

[oracle@www.htz.pw ~]$cat /tmp/manual.sh

sqlplus -s / as sysdba <<EOF

exec DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT();

oradebug setmypid

oradebug tracefile_name;

oradebug event 10046 trace name context forever,level 12;

SELECT rowid,distinct ename from scott.emp;

oradebug event 10046 trace name context off;

exec DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT();

oradebug dump systemstate 266

exit

3 现象模拟

[oracle@www.htz.pw sql]$sh -x /tmp/total.sh

+ for b in ‘{1..100}’

+ nohup /tmp/total1.sh

+ echo 1

1

+ for b in ‘{1..100}’

+ nohup /tmp/total1.sh

+ echo 2

2

+ for b in ‘{1..100}’

+ nohup /tmp/total1.sh

+ echo 3

3

+ for b in ‘{1..100}’

+ echo 4

4

+ for b in ‘{1..100}’

+ nohup /tmp/total1.sh

+ echo 5

5

+ for b in ‘{1..100}’

+ nohup /tmp/total1.sh

+ echo 6

…………………

运行/tmp/total.sh脚本。

3.1 查看等待事件

 I SQL_ID             COMMAND           COUNT(*)

— —————— ————— ———-

 1 19z6y6frqctwj      UNKNOWN                665

   6256zq0nau5g2      PL/SQL EXECUTE           1

   5v4ww7bb9y4hp      SELECT                   1

 

 

 I EVENT                                    SQL_ID               COUNT(*)

— —————————————- —————— ———-

 1 SQL*Net message to client                81prbu1ddkd5c               1

   library cache lock                       19z6y6frqctwj             506

   library cache: mutex X                   19z6y6frqctwj             159

   pipe get                                 6256zq0nau5g2               1

 

 

 I EVENT                                      COUNT(*)

— —————————————- ———-

 1 library cache: mutex X                          401

   library cache lock                              264

   pipe get                                          1

   SQL*Net message to client                         1

这里已经现出了library cache lock,library cache: mutex X等待事件,并且blocking_session一直在变化。这里虽然能找到sqlid,但是在v$sqlsql_fulltext为空

3.2 执行manual脚本

执行manual脚本,生成分析信息

[oracle@www.htz.pw ~]$./manual.sh

 

PL/SQL procedure successfully completed.

 

Elapsed: 00:00:02.72

Statement processed.

/oracle/app/oracle/diag/rdbms/orcl1123/orcl1123/trace/orcl1123_ora_16859.trc

Statement processed.

SELECT rowid,distinct ename from scott.emp

             *

ERROR at line 1:

ORA-00936: missing expression

SQL用时3分钟

Elapsed: 00:03:53.71

Statement processed.

 

PL/SQL procedure successfully completed.

 

Elapsed: 00:00:02.06

Statement processed.

3.3 trace文件分析

*** 2014-09-04 23:39:55.421

WAIT #182938303856: nam=’library cache lock’ ela= 167078 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845195421813

WAIT #182938303856: nam=’library cache lock’ ela= 176379 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845195598493

WAIT #182938303856: nam=’library cache: mutex X’ ela= 93014 idn=2293619106 value=1915555414016 where=82 obj#=-1 tim=1409845195857160

WAIT #182938303856: nam=’library cache lock’ ela= 165443 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845195857160

WAIT #182938303856: nam=’library cache: mutex X’ ela= 57730 idn=2293619106 value=1808181231616 where=82 obj#=-1 tim=1409845196013600

WAIT #182938303856: nam=’library cache lock’ ela= 98517 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845196013600

WAIT #182938303856: nam=’library cache: mutex X’ ela= 75987 idn=2293619106 value=1103806595072 where=82 obj#=-1 tim=1409845196169888

WAIT #182938303856: nam=’library cache lock’ ela= 80150 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845196169888

 

*** 2014-09-04 23:39:56.356

WAIT #182938303856: nam=’library cache: mutex X’ ela= 102519 idn=2293619106 value=2576980377600 where=82 obj#=-1 tim=1409845196356195

WAIT #182938303856: nam=’library cache lock’ ela= 83678 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845196356195

WAIT #182938303856: nam=’library cache: mutex X’ ela= 71324 idn=2293619106 value=2843268349952 where=82 obj#=-1 tim=1409845196492361

WAIT #182938303856: nam=’library cache lock’ ela= 64693 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845196492361

WAIT #182938303856: nam=’library cache: mutex X’ ela= 103586 idn=2293619106 value=2959232466944 where=82 obj#=-1 tim=1409845196678232

WAIT #182938303856: nam=’library cache lock’ ela= 82175 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845196678232

WAIT #182938303856: nam=’library cache: mutex X’ ela= 85254 idn=2293619106 value=2113123909632 where=82 obj#=-1 tim=1409845196820340

WAIT #182938303856: nam=’library cache lock’ ela= 56746 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845196820340

WAIT #182938303856: nam=’library cache: mutex X’ ela= 54560 idn=2293619106 value=601295421440 where=82 obj#=-1 tim=1409845196937515

WAIT #182938303856: nam=’library cache lock’ ela= 62518 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845196937515

WAIT #182938303856: nam=’library cache: mutex X’ ela= 93347 idn=2293619106 value=2388001816576 where=82 obj#=-1 tim=1409845197141569

WAIT #182938303856: nam=’library cache lock’ ela= 110615 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845197141569

WAIT #182938303856: nam=’library cache: mutex X’ ela= 120893 idn=2293619106 value=1314259992576 where=82 obj#=-1 tim=1409845197331918

WAIT #182938303856: nam=’library cache lock’ ela= 69317 handle address=3731290056 lock address=2689821752 100*mode+namespace=5373954 obj#=-1 tim=1409845197331918

3.4 awr部分数据

              Snap Id      Snap Time      Sessions Curs/Sess

            ——— ——————- ——– ———

Begin Snap:       254 04-Sep-14 23:39:51       694       1.0

  End Snap:       255 04-Sep-14 23:43:48       696       1.0

   Elapsed:                3.94 (mins)

   DB Time:            2,600.59 (mins)

  

……

Top 5 Timed Foreground Events

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

                                                           Avg

                                                          wait   % DB

Event                                 Waits     Time(s)   (ms)   time Wait Class

—————————— ———— ———– —— —— ———-

library cache lock                1,202,096     102,479     85   65.7 Concurrenc

library cache: mutex X              979,370      54,345     55   34.8 Concurrenc

cursor: mutex S                      15,437         240     16     .2 Concurrenc

DB CPU                                              159            .1

ksdxexeotherwait                        235          19     79     .0 Other

 

 

Time Model Statistics               DB/Inst: ORCL1123/orcl1123  Snaps: 254-255

-> Total time in database user-calls (DB Time): 156035.1s

-> Statistics including the word "background" measure background process

   time, and so do not contribute to the DB time statistic

-> Ordered by % or DB time desc, Statistic name

 

Statistic Name                                       Time (s) % of DB Time

—————————————— —————— ————

failed parse elapsed time                           161,298.8        103.4

parse time elapsed                                  155,974.7        100.0

DB CPU                                                  158.6           .1

sql execute elapsed time                                  6.7           .0

hard parse elapsed time                                   1.4           .0

connection management call elapsed time                   0.4           .0

hard parse (sharing criteria) elapsed time                0.2           .0

PL/SQL execution elapsed time                             0.2           .0

hard parse (bind mismatch) elapsed time                   0.2           .0

PL/SQL compilation elapsed time                           0.0           .0

repeated bind elapsed time                                0.0           .0

sequence load elapsed time                                0.0           .0

DB time                                             156,035.1

background elapsed time                                   8.2

background cpu time                                       1.8

                                                    % of Waits

                                 ———————————————–

                           Total

Event                      Waits  <1ms  <2ms  <4ms  <8ms <16ms <32ms  <=1s   >1s

————————– —– —– —– —– —– —– —– —– —–

Disk file operations I/O       7 100.0

LGWR wait for redo copy        3        66.7        33.3

SQL*Net break/reset to cli  3605  90.6   1.1   1.1    .8   4.4   2.1

SQL*Net message to client   7210 100.0    .0

asynch descriptor resize     187 100.0

control file parallel writ   106  39.6  24.5   2.8   7.5  12.3   8.5   4.7

control file sequential re   563  99.8                      .2

cursor: mutex S            15.4K   1.3   1.8   2.4   5.2  51.9  33.1   4.3

db file async I/O submit     356  79.2   3.4   1.1   5.6   6.2   4.2    .3

db file scattered read         2                                50.0  50.0

db file sequential read        8  62.5                    37.5

ksdxexeotherwait             231                                16.5  83.5

library cache lock         1199.    .0    .0    .0    .0    .0   8.8  91.2    .0

library cache: mutex X     977.3    .6    .1    .1    .2   1.5  22.1  75.4    .0

 

Instance Activity Stats     DB/Inst: ORCL1123/orcl1123  Snaps: 254-255

-> Ordered by statistic name

 

Statistic                                     Total     per Second     per Trans

——————————– —————— ————– ————-

parse count (describe)                           10            0.0           0.4

parse count (failures)                        1,802            7.6          69.3

parse count (hard)                            2,251            9.5          86.6

parse count (total)                           1,535            6.5          59.0

parse time cpu                               14,768           62.5         568.0

parse time elapsed                       16,139,949       68,262.4     620,767.3

可以看到,全是分析失败的信息

3.5 分析systemstate数据

格式化后的数据

     LOCK: Handle=0xde66f7c8   579: waiting for ‘library cache lock’

     LOCK: Handle=0xde66f7c8   588: 588: is waiting for 248:

     LOCK: Handle=0xde66f7c8   603: 603: is waiting for 248:

     LOCK: Handle=0xde66f7c8   604: 604: is waiting for 248:

     LOCK: Handle=0xde66f7c8   609: 609: is waiting for 248:

     LOCK: Handle=0xde66f7c8   656: 656: is waiting for 248:

     LOCK: Handle=0xde66f7c8   670: 670: is waiting for 248:

     LOCK: Handle=0xde66f7c8   686: waiting for ‘library cache lock’

              Mutex 88b5d9a2   248: 248: is waiting for 24: 52: 58: 71: 82: 83: 98: 107: 113: 114: 137: 157: 171: 176: 185: 187: 197: 200: 203: 213: 214: 222: 223: 224: 232: 244: 257: 270: 273: 275: 279: 283: 292: 300: 302: 304: 321: 324: 326: 333: 334: 338: 340: 341: 361: 373: 398: 402: 409: 410: 418: 420: 421: 437: 438: 456: 462: 482: 496: 507: 508: 522: 528: 533: 543: 548: 570: 571: 577: 579: 588: 603: 604: 609: 656: 670: 686:

 

Warning: The following processes have multiple session state objects and

may not be properly represented above :

    42:   45:   50:   52:   58:   66:   67:   71:   72:   80:   82:   83:   89:

    90:   98:  100:  105:  107:  110:  114:  135:  137:  140:  156:  171:  182:

   185:  187:  188:  192:  195:  197:  200:  203:  205:  213:  214:  215:  218:

   222:  224:  229:  232:  244:  250:  251:  257:  272:  275:  279:  281:  282:

   288:  292:  293:  299:  300:  302:  304:  307:  308:  321:  324:  326:  333:

   334:  335:  338:  341:  351:  358:  361:  367:  373:  377:  385:  393:  398:

   402:  404:  405:  410:  421:  426:  434:  437:  438:  439:  440:  446:  454:

   456:  462:  479:  482:  507:  508:  513:  528:  533:  542:  543:  565:  570:

   571:  588:  595:  597:  600:  603:  604:  609:  633:  639:  641:  650:  655:

   656:  657:  658:  670:  683:  692:                                         

 

Object Names

~~~~~~~~~~~~

LOCK: Handle=0xde66f7c8                                      

Mutex 88b5d9a2                                               

 

End of report. 324493 Lines Processed.

systemstate中,可以得到248导致后面的进程发生了阻塞,其实上前面我们也说明blocking_session一直在发生变化

3.5.1 分析de66f7c8对象与进程

library*handle*0xde66f7c8来搜索,可以发现如下内容

 13933       LibraryHandle:  Address=0xde66f7c8 Hash=88b5d9a2 LockMode=S PinMode=0 LoadLockMode=0 Status=0

……………相同的内容

119661       LibraryHandle:  Address=0xde66f7c8 Hash=88b5d9a2 LockMode=X PinMode=0 LoadLockMode=0 Status=0

120111       LibraryHandle:  Address=0xde66f7c8 Hash=88b5d9a2 LockMode=S PinMode=0 LoadLockMode=0 Status=0

…………….相同的内容

这里可以看到多行有LockMode=X

这里有点没有想通的是能发现多行的LockMode=X。

进入119661查看

进入119661查看

 

能发现是一个对象在$BUILD$.14fcde33af666791    

—————————————-

      SO: 0x957d8a80, type: 78, owner: 0xc72b2858, flag: INIT/-/-/0x00 if: 0x3 c: 0x3

       proc=0xdcb18188, name=LIBRARY OBJECT LOCK, file=kgl.h LINE:8547, pg=0

 

      LibraryObjectLock:  Address=0x957d8a80 Handle=0xde66f7c8 RequestMode=S CanBeBrokenCount=1 Incarnation=1 ExecutionCount=0        

       

        User=0xd95151a0 Session=0xd95151a0 ReferenceCount=1 Flags=CNB/[0201] SavepointNum=b2

      LibraryHandle:  Address=0xde66f7c8 Hash=88b5d9a2 LockMode=X PinMode=0 LoadLockMode=0 Status=0

        ObjectName:  Name=$BUILD$.14fcde33af666791  

          FullHashValue=fa05f23d882d81d150400d1088b5d9a2 Namespace=SQL AREA BUILD(82) Type=CURSOR(00) Identifier=0 OwnerIdn=0

        Statistics:  InvalidationCount=0 ExecutionCount=0 LoadCount=0 ActiveLocks=1 TotalLockCount=17660 TotalPinCount=0

        Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=0 BucketInUse=48952 HandleInUse=48952 HandleReferenceCount=0

        Concurrency:  DependencyMutex=0xde66f878(0, 0, 0, 0) Mutex=0xde66f8f8(0, 50665262, 11175948, 0) 这里也可以看到依赖的mutex与当前对象的mutex

        Flags=RON/PIN/[00010000]

        WaitersLists: 

          Lock=0xde66f858[0xa08f6e70,0x95441758]

          Pin=0xde66f838[0xde66f838,0xde66f838]

          LoadLock=0xde66f8b0[0xde66f8b0,0xde66f8b0]

        Timestamp: 

        HandleReference:  Address=0xde66f978 Handle=(nil) Flags=[00]   

查找进程的信息

以进程  dcb18188*type=2来搜索   

121479 PROCESS 248:

       

PROCESS 248:

  —————————————-

  SO: 0xdcb1d4f8, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3

   proc=0xdcb1d4f8, name=process, file=ksu.h LINE:12616, pg=0

  (process) Oracle pid:248, ser:1, calls cur/top: 0xc72b4548/0xc72b4548

            flags : (0x0) –

            flags2: (0x0),  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 258

              last post received-location: kgl.h LINE:8666 ID:kgllkdl: in loop

              last process to post me: dcbe0588 1 0

              last post sent: 0 0 258

              last post sent-location: kgl.h LINE:8666 ID:kgllkdl: in loop

              last process posted by me: dca6af68 1 0

    (latch info) wait_event=0 bits=0

    Process Group: DEFAULT, pseudo proc: 0xdb31bde8

    O/S info: user: oracle, term: UNKNOWN, ospid: 12798

    OSD pid info: Unix process pid: 12798, image: oracle@orcl9i (TNS V1-V3)

    Short stack dump:

ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__pthread_sighandler_rt()+104<-__sighandler()<-semtimedop()+12<-skgpwwait()+160<-ksliwat()+1865<-kslwaitctx()+163<-ksfwaitctx()+14<-kglLockWait()+837<-kglUpgradeLock()+1168<-kksGetBuildLock()+321<-kksfbc()+12550<-kkspsc0()+1173<-kksParseCursor()+116<-opiosq0()+1965<-kpooprx()+274<-kpoal8()+829<-opiodr()+916<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+169<-0000000000001000

    —————————————-

    SO: 0xd9506358, type: 4, owner: 0xdcb1d4f8, flag: INIT/-/-/0x00 if: 0x3 c: 0x3

     proc=0xdcb1d4f8, name=session, file=ksu.h LINE:12624, pg=0

    (session) sid: 253 ser: 7 trans: (nil), creator: 0xdcb1d4f8

              flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/-

              flags2: (0x40009) -/-/INC

              DID: , short-term DID:

              txn branch: (nil)

              oct: 0, prv: 0, sql: 0xde8299d0, psql: 0xde6cd4a8, user: 0/SYS

    ksuxds FALSE at location: 0

    service name: SYS$USERS

    client details:

      O/S info: user: oracle, term: , ospid: 12797

      machine: orcl9i program: sqlplus@orcl9i (TNS V1-V3)

      application name: sqlplus@orcl9i (TNS V1-V3), hash value=2975165397

    Current Wait Stack:

      Not in wait; last wait ended 0.000276 sec ago

    Wait State:

      fixed_waits=0 flags=0x21 boundary=(nil)/-1

    Session Wait History:

        elapsed time of 0.000293 sec since last wait

     0: waited for ‘library cache lock’

        handle address=0xde66f7c8, lock address=0x9578ac18, 100*mode+namespace=0x520002    这里也可以计算得到是请求共享锁10100100000000000000010 16位为锁

        wait_id=12679 seq_num=18211 snap_id=1

        wait times: snap=0.176035 sec, exc=0.176035 sec, total=0.176035 sec

        wait times: max=infinite

        wait counts: calls=1 os=1

        occurred after 0.000031 sec of elapsed time

     1: waited for ‘library cache lock’

        handle address=0xde66f7c8, lock address=0x9578ac18, 100*mode+namespace=0x520002

        wait_id=12677 seq_num=18210 snap_id=2

        wait times: snap=0.000000 sec, exc=0.136501 sec, total=0.167093 sec

        wait times: max=infinite

        wait counts: calls=1 os=1

        occurred after 0.000000 sec of elapsed time 

 

www.htz.pw > @event_pin_or_lock_p3_to_type_and_mode_16.sql

Enter value for p3: 520002

 

KGLSTDSC                                                           KGLSTIDN       MODE

—————————————————————- ———- ———-

SQL AREA BUILD                                                           82          2

这里就能看是sql area build2的模式获取

并且还可以看到下面的mutex,此会话持有一个mutex

      KGL-UOL SO Cache(total=12, free=5)

      KGX Atomic Operation Log 0x95799c50

       Mutex 0xde66f8f8(253, 0) idn 88b5d9a2 oper EXCL

       Library Cache uid 253 efd 5 whr 119 slp 0

       oper=19 pt1=0xde66f7c8 pt2=0x9578ac18 pt3=(nil)

       pt4=(nil) pt5=(nil) ub4=0

 

            LibraryHandle:  Address=0xde66f7c8 Hash=88b5d9a2 LockMode=S PinMode=0 LoadLockMode=0 Status=0

              ObjectName:  Name=$BUILD$.14fcde33af666791  

                FullHashValue=fa05f23d882d81d150400d1088b5d9a2 Namespace=SQL AREA BUILD(82) Type=CURSOR(00) Identifier=0 OwnerIdn=0

这里可以看到248这个进程以x模式获取锁,但是,仍然在等待2模式获取同一个对象。

下面再选择另一个X模式的行

PROCESS 639:

  —————————————-

  SO: 0xdccb51c8, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3

   proc=0xdccb51c8, name=process, file=ksu.h LINE:12616, pg=0

  (process) Oracle pid:639, ser:1, calls cur/top: 0xc739a728/0xc739a728

            flags : (0x0) –

            flags2: (0x0),  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 259

              last post received-location: kgl.h LINE:8669 ID:kgllkdl: post after freeing latch

              last process to post me: dcb90098 1 0

              last post sent: 0 0 258

              last post sent-location: kgl.h LINE:8666 ID:kgllkdl: in loop

              last process posted by me: dcbe58f8 1 0

    (latch info) wait_event=0 bits=0

    Process Group: DEFAULT, pseudo proc: 0xdb31bde8

    O/S info: user: oracle, term: UNKNOWN, ospid: 14303

    OSD pid info: Unix process pid: 14303, image: oracle@orcl9i (TNS V1-V3)

    Short stack dump:

ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__pthread_sighandler_rt()+104<-__sighandler()<-semtimedop()+12<-skgpwwait()+160<-ksliwat()+1865<-kslwaitctx()+163<-ksfwaitctx()+14<-kglLockWait()+837<-kglUpgradeLock()+1168<-kksGetBuildLock()+321<-kksfbc()+12550<-kkspsc0()+1173<-kksParseCursor()+116<-opiosq0()+1965<-kpooprx()+274<-kpoal8()+829<-opiodr()+916<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+169<-0000000000001000

    —————————————-

    SO: 0xdaf9fa30, type: 4, owner: 0xdccb51c8, flag: INIT/-/-/0x00 if: 0x3 c: 0x3

     proc=0xdccb51c8, name=session, file=ksu.h LINE:12624, pg=0

    (session) sid: 648 ser: 1 trans: (nil), creator: 0xdccb51c8

              flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/-

              flags2: (0x40009) -/-/INC

              DID: , short-term DID:

              txn branch: (nil)

              oct: 0, prv: 0, sql: 0xde8299d0, psql: 0xde6cd4a8, user: 0/SYS

    ksuxds FALSE at location: 0

    service name: SYS$USERS

    client details:

      O/S info: user: oracle, term: , ospid: 13611

      machine: orcl9i program: sqlplus@orcl9i (TNS V1-V3)

      application name: sqlplus@orcl9i (TNS V1-V3), hash value=2975165397

    Current Wait Stack:

     1: waiting for ‘library cache: mutex X

        idn=0x88b5d9a2, value=0x15200000000, where=0x52

        wait_id=12870 seq_num=18596 snap_id=1

        wait times: snap=0.000092 sec, exc=0.000092 sec, total=0.000092 sec

        wait times: max=infinite, heur=0.000092 sec

        wait counts: calls=0 os=0

        in_wait=1 iflags=0x532

以121663        Mutex 0xde66f8f8(253, 0) idn 88b5d9a2 oper EXCL

可以发现持有者就是248这个进程

4 分析结果

这里只限本等待事件的模拟,关于SQL解析等一些其它的内容,不包括在内

1248这个会话持有mutex,阻塞了其它的会话获取mutex锁。

2248会话等待library cache lock,但是自己已经持有library cache lock

本文固定链接: http://www.htz.pw/2014/09/07/sql%e8%af%ad%e6%b3%95%e9%94%99%e8%af%af%e5%af%bc%e8%87%b4library-cache-locklibrary-cachemutex-x.html | 认真就输

该日志由 huangtingzhong 于2014年09月07日发表在 EVENT, systemstate 分类下, 你可以发表评论,并在保留原文地址及作者的情况下引用到你的网站或博客。
原创文章转载请注明: SQL语法错误导致library cache lock/library cache:mutex X | 认真就输
关键字: ,