enq: UL – contention

今天在测试着ASSM管理下的insert操作的时候,出现了一个小插曲,开的几个会话窗口都hang在那里。使用tanel poder的snapper进行查看当前用户的状态信息,意外的发现enq: UL – contention这个等待事件,mos上搜索了一下,发现了这个等待事件是有关dbms_lock的,测试程序里也确实使用了这个package。
本文不对实验的场景进行reproduce的步骤说明,单纯对这个等待事件进行简单的记录。

SQL> @snapper ash,stats 5 1 username=blue
Sampling SID username=blue with interval 5 seconds, taking 1 snapshots...

-- Session Snapper v4.24 - by Tanel Poder ( http://blog.tanelpoder.com/snapper ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet! 🙂

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 SID @INST, USERNAME  , TYPE, STATISTIC                                                 ,         DELTA, HDELTA/SEC,    %TIME, GRAPH       , NUM_WAITS,  WAITS/SEC,   AVERAGES
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
     2  @1, BLUE      , STAT, application wait time                                     ,           551,     102.53,         ,             ,          ,           ,          ~ per execution
     2  @1, BLUE      , STAT, non-idle wait time                                        ,           552,     102.72,         ,             ,          ,           ,          ~ per execution
     2  @1, BLUE      , STAT, non-idle wait count                                       ,            11,       2.05,         ,             ,          ,           ,          ~ per execution
     2  @1, BLUE      , TIME, PL/SQL execution elapsed time                             ,       6012794,      1.12s,   111.9%, [##########],          ,           ,
     2  @1, BLUE      , TIME, sql execute elapsed time                                  ,       6012794,      1.12s,   111.9%, [##########],          ,           ,
     2  @1, BLUE      , TIME, DB time                                                   ,       6012794,      1.12s,   111.9%, [##########],          ,           ,     -11.89 % unaccounted time
     2  @1, BLUE      , WAIT, enq: UL - contention                                      ,      11010759,      2.05s,   204.9%, [WWWWWWWWWW],         0,          0,     11.01s average wait

   104  @1, BLUE      , STAT, Requests to/from client                                   ,             1,        .19,         ,             ,          ,           ,          0 per execution
   104  @1, BLUE      , STAT, opened cursors cumulative                                 ,           415,      77.22,         ,             ,          ,           ,       1.99 per execution
   104  @1, BLUE      , STAT, opened cursors current                                    ,             1,        .19,         ,             ,          ,           ,          1 actual value in end of snapshot
   104  @1, BLUE      , STAT, user commits                                              ,           202,      37.59,         ,             ,          ,           ,        .97 per execution
   104  @1, BLUE      , STAT, user calls                                                ,             1,        .19,         ,             ,          ,           ,          0 per execution
   104  @1, BLUE      , STAT, recursive calls                                           ,           616,     114.63,         ,             ,          ,           ,     48.7us recursive CPU per recursive call
   104  @1, BLUE      , STAT, recursive cpu usage                                       ,             3,        .56,         ,             ,          ,           ,       30ms total recursive CPU usage
   104  @1, BLUE      , STAT, pinned cursors current                                    ,            -1,       -.19,         ,             ,          ,           ,         -1 actual value in end of snapshot
   104  @1, BLUE      , STAT, session logical reads                                     ,           694,     129.14,         ,             ,          ,           ,        703 total buffer visits
   104  @1, BLUE      , STAT, CPU used when call started                                ,           283,      52.66,         ,             ,          ,           ,      2.83s total CPU used when call started
   104  @1, BLUE      , STAT, CPU used by this session                                  ,            10,       1.86,         ,             ,          ,           ,      100ms total CPU used by this session
   104  @1, BLUE      , STAT, DB time                                                   ,          5776,      1.07k,         ,             ,          ,           ,      27.64 per execution
   104  @1, BLUE      , STAT, non-idle wait time                                        ,             1,        .19,         ,             ,          ,           ,          0 per execution
   104  @1, BLUE      , STAT, non-idle wait count                                       ,            39,       7.26,         ,             ,          ,           ,        .19 per execution
   104  @1, BLUE      , STAT, in call idle wait time                                    ,           215,      40.01,         ,             ,          ,           ,       1.03 per execution
   104  @1, BLUE      , STAT, messages sent                                             ,           232,      43.17,         ,             ,          ,           ,       1.11 per execution
   104  @1, BLUE      , STAT, enqueue requests                                          ,           435,      80.95,         ,             ,          ,           ,       2.08 per execution
   104  @1, BLUE      , STAT, enqueue releases                                          ,           435,      80.95,         ,             ,          ,           ,       2.08 per execution
   104  @1, BLUE      , STAT, global enqueue gets sync                                  ,           419,      77.97,         ,             ,          ,           ,          2 per execution
   104  @1, BLUE      , STAT, global enqueue releases                                   ,           426,      79.27,         ,             ,          ,           ,       2.04 per execution
   104  @1, BLUE      , STAT, gcs messages sent                                         ,            16,       2.98,         ,             ,          ,           ,        .08 per execution
   104  @1, BLUE      , STAT, db block gets                                             ,           678,     126.16,         ,             ,          ,           ,       3.24 per execution
   104  @1, BLUE      , STAT, db block gets from cache                                  ,           678,     126.16,         ,             ,          ,           ,       3.24 per execution
   104  @1, BLUE      , STAT, db block gets from cache (fastpath)                       ,             9,       1.67,         ,             ,          ,           ,        .04 per execution
   104  @1, BLUE      , STAT, consistent gets                                           ,            16,       2.98,         ,             ,          ,           ,        .08 per execution
   104  @1, BLUE      , STAT, consistent gets from cache                                ,            16,       2.98,         ,             ,          ,           ,        .08 per execution
   104  @1, BLUE      , STAT, consistent gets from cache (fastpath)                     ,             6,       1.12,         ,             ,          ,           ,        .03 per execution
   104  @1, BLUE      , STAT, consistent gets - examination                             ,            10,       1.86,         ,             ,          ,           ,        .05 per execution
   104  @1, BLUE      , STAT, logical read bytes from cache                             ,       5685248,      1.06M,         ,             ,          ,           ,      27.2k per execution
   104  @1, BLUE      , STAT, db block changes                                          ,           877,     163.19,         ,             ,          ,           ,        4.2 per execution
   104  @1, BLUE      , STAT, free buffer requested                                     ,            20,       3.72,         ,             ,          ,           ,         .1 per execution
   104  @1, BLUE      , STAT, commit cleanouts                                          ,           212,      39.45,         ,             ,          ,           ,       1.01 per execution
   104  @1, BLUE      , STAT, commit cleanouts successfully completed                   ,           212,      39.45,         ,             ,          ,           ,       1.01 per execution
   104  @1, BLUE      , STAT, calls to kcmgcs                                           ,            14,       2.61,         ,             ,          ,           ,        .07 per execution
   104  @1, BLUE      , STAT, calls to kcmgas                                           ,           217,      40.38,         ,             ,          ,           ,       1.04 per execution
   104  @1, BLUE      , STAT, calls to get snapshot scn: kcmgss                         ,           424,       78.9,         ,             ,          ,           ,       2.03 per execution
   104  @1, BLUE      , STAT, redo entries                                              ,           453,      84.29,         ,             ,          ,           ,       2.17 per execution
   104  @1, BLUE      , STAT, redo size                                                 ,        121952,     22.69k,         ,             ,          ,           ,     603.72 bytes per user commit
   104  @1, BLUE      , STAT, redo ordering marks                                       ,             5,        .93,         ,             ,          ,           ,        .02 per execution
   104  @1, BLUE      , STAT, redo synch time (usec)                                    ,             1,        .19,         ,             ,          ,           ,          0 per execution
   104  @1, BLUE      , STAT, redo synch time overhead (usec)                           ,          3861,     718.46,         ,             ,          ,           ,     3.86ms FG wakeup overhead per log file sync
   104  @1, BLUE      , STAT, redo synch time overhead count (<8 msec)                  ,             1,        .19,         ,             ,          ,           ,          0 per execution
   104  @1, BLUE      , STAT, redo synch writes                                         ,             1,        .19,         ,             ,          ,           ,          0 per execution
   104  @1, BLUE      , STAT, redo synch long waits                                     ,             1,        .19,         ,             ,          ,           ,          0 per execution
   104  @1, BLUE      , STAT, redo write info find                                      ,             1,        .19,         ,             ,          ,           ,          0 per execution
   104  @1, BLUE      , STAT, gc local grants                                           ,             4,        .74,         ,             ,          ,           ,        .02 per execution
   104  @1, BLUE      , STAT, gc remote grants                                          ,            16,       2.98,         ,             ,          ,           ,        .08 per execution
   104  @1, BLUE      , STAT, undo change vector size                                   ,         29424,      5.48k,         ,             ,          ,           ,     140.78 per execution
   104  @1, BLUE      , STAT, deferred (CURRENT) block cleanout applications            ,           112,      20.84,         ,             ,          ,           ,        .54 per execution
   104  @1, BLUE      , STAT, index fetch by key                                        ,            10,       1.86,         ,             ,          ,           ,        .05 per execution
   104  @1, BLUE      , STAT, HSC Heap Segment Block Changes                            ,           211,      39.26,         ,             ,          ,           ,       1.01 per execution
   104  @1, BLUE      , STAT, session cursor cache hits                                 ,           408,      75.92,         ,             ,          ,           ,        407 softparses avoided thanks to cursor cache
   104  @1, BLUE      , STAT, buffer is pinned count                                    ,             9,       1.67,         ,             ,          ,           ,       1.28 % buffer gets avoided thanks to buffer pin caching
   104  @1, BLUE      , STAT, buffer is not pinned count                                ,             9,       1.67,         ,             ,          ,           ,        .04 per execution
   104  @1, BLUE      , STAT, parse count (total)                                       ,             1,        .19,         ,             ,          ,           ,          ~ softparses per hardparse
   104  @1, BLUE      , STAT, execute count                                             ,           209,      38.89,         ,             ,          ,           ,        209 executions per parse
   104  @1, BLUE      , STAT, bytes sent via SQL*Net to client                          ,           300,      55.82,         ,             ,          ,           ,        150 bytes per roundtrip
   104  @1, BLUE      , STAT, bytes received via SQL*Net from client                    ,           331,      61.59,         ,             ,          ,           ,      165.5 bytes per roundtrip
   104  @1, BLUE      , STAT, SQL*Net roundtrips to/from client                         ,             2,        .37,         ,             ,          ,           ,        .01 per execution
   104  @1, BLUE      , TIME, repeated bind elapsed time                                ,            54,    10.05us,      .0%, [          ],          ,           ,
   104  @1, BLUE      , TIME, parse time elapsed                                        ,            75,    13.96us,      .0%, [          ],          ,           ,
   104  @1, BLUE      , TIME, PL/SQL execution elapsed time                             ,          4875,   907.15us,      .1%, [          ],          ,           ,
   104  @1, BLUE      , TIME, DB CPU                                                    ,        132981,    24.75ms,     2.5%, [@         ],          ,           ,
   104  @1, BLUE      , TIME, sql execute elapsed time                                  ,        130128,    24.21ms,     2.4%, [#         ],          ,           ,
   104  @1, BLUE      , TIME, DB time                                                   ,        130659,    24.31ms,     2.4%, [#         ],          ,           ,      -6.88 % unaccounted time
   104  @1, BLUE      , TIME, sequence load elapsed time                                ,          4421,   822.67us,      .1%, [          ],          ,           ,
   104  @1, BLUE      , WAIT, row cache lock                                            ,          1460,   271.68us,      .0%, [          ],         7,        1.3,   208.57us average wait
   104  @1, BLUE      , WAIT, SQL*Net message to client                                 ,             5,      .93us,      .0%, [          ],         2,        .37,      2.5us average wait
   104  @1, BLUE      , WAIT, SQL*Net message from client                               ,       4005779,    745.4ms,    74.5%, [WWWWWWWW  ],         1,        .19,      4.01s average wait
   104  @1, BLUE      , WAIT, PL/SQL lock timer                                         ,       1607548,   299.13ms,    29.9%, [WWW       ],       152,      28.28,    10.58ms average wait

   379  @1, BLUE      , STAT, application wait time                                     ,           551,     102.53,         ,             ,          ,           ,          ~ per execution
   379  @1, BLUE      , STAT, non-idle wait time                                        ,           552,     102.72,         ,             ,          ,           ,          ~ per execution
   379  @1, BLUE      , STAT, non-idle wait count                                       ,            11,       2.05,         ,             ,          ,           ,          ~ per execution
   379  @1, BLUE      , TIME, PL/SQL execution elapsed time                             ,       6011767,      1.12s,   111.9%, [##########],          ,           ,
   379  @1, BLUE      , TIME, DB CPU                                                    ,          1000,   186.08us,      .0%, [          ],          ,           ,
   379  @1, BLUE      , TIME, sql execute elapsed time                                  ,       6011767,      1.12s,   111.9%, [##########],          ,           ,
   379  @1, BLUE      , TIME, DB time                                                   ,       6011767,      1.12s,   111.9%, [##########],          ,           ,     -11.87 % unaccounted time
   379  @1, BLUE      , WAIT, enq: UL - contention                                      ,      10511240,      1.96s,   195.6%, [WWWWWWWWWW],         0,          0,     10.51s average wait

   404  @1, BLUE      , STAT, application wait time                                     ,           501,      93.23,         ,             ,          ,           ,          ~ per execution
   404  @1, BLUE      , STAT, non-idle wait time                                        ,           501,      93.23,         ,             ,          ,           ,          ~ per execution
   404  @1, BLUE      , STAT, non-idle wait count                                       ,            10,       1.86,         ,             ,          ,           ,          ~ per execution
   404  @1, BLUE      , TIME, PL/SQL execution elapsed time                             ,       6012198,      1.12s,   111.9%, [##########],          ,           ,
   404  @1, BLUE      , TIME, sql execute elapsed time                                  ,       6012198,      1.12s,   111.9%, [##########],          ,           ,
   404  @1, BLUE      , TIME, DB time                                                   ,       6012198,      1.12s,   111.9%, [##########],          ,           ,     -11.88 % unaccounted time
   404  @1, BLUE      , WAIT, enq: UL - contention                                      ,      10009985,      1.86s,   186.3%, [WWWWWWWWWW],         0,          0,     10.01s average wait

   428  @1, BLUE      , WAIT, SQL*Net message from client                               ,       5000000,   930.41ms,    93.0%, [WWWWWWWWWW],         0,          0,         5s average wait

   681  @1, BLUE      , STAT, application wait time                                     ,           551,     102.53,         ,             ,          ,           ,          ~ per execution
   681  @1, BLUE      , STAT, non-idle wait time                                        ,           551,     102.53,         ,             ,          ,           ,          ~ per execution
   681  @1, BLUE      , STAT, non-idle wait count                                       ,            11,       2.05,         ,             ,          ,           ,          ~ per execution
   681  @1, BLUE      , TIME, PL/SQL execution elapsed time                             ,       6011961,      1.12s,   111.9%, [##########],          ,           ,
   681  @1, BLUE      , TIME, sql execute elapsed time                                  ,       6011961,      1.12s,   111.9%, [##########],          ,           ,
   681  @1, BLUE      , TIME, DB time                                                   ,       6011961,      1.12s,   111.9%, [##########],          ,           ,     -11.87 % unaccounted time
   681  @1, BLUE      , WAIT, enq: UL - contention                                      ,      10511004,      1.96s,   195.6%, [WWWWWWWWWW],         0,          0,     10.51s average wait

--  End of Stats snap 1, end=2016-08-04 09:08:36, seconds=5.4


---------------------------------------------------------------------------------------------------------------
  ActSes   %Thread | INST | SQL_ID          | SQL_CHILD | EVENT                               | WAIT_CLASS
---------------------------------------------------------------------------------------------------------------
    1.00    (100%) |    1 | 7ca807d052k9q   | 0         | enq: UL - contention                | Application
    1.00    (100%) |    1 | g3p0w4rbfqbyu   | 0         | enq: UL - contention                | Application
    1.00    (100%) |    1 | 9fx5233jmx5v5   | 0         | enq: UL - contention                | Application
    1.00    (100%) |    1 | 3kz18qxxbfg5u   | 0         | enq: UL - contention                | Application
     .05      (5%) |    1 | cp9kyzxf6g15z   | 0         | ON CPU                              | ON CPU

--  End of ASH snap 1, end=2016-08-04 09:08:36, seconds=5, samples_taken=41, AAS=4


PL/SQL procedure successfully completed.

查询下阻塞的具体信息
SELECT l.*, s.username
FROM v$lock l, v$session s
WHERE l.TYPE = ‘UL’
AND s.sid = l.sid;

output:

ADDR             KADDR                   SID TYPE          ID1        ID2      LMODE    REQUEST      CTIME      BLOCK USERNAME
---------------- ---------------- ---------- ------ ---------- ---------- ---------- ---------- ---------- ---------- ----------
00000002CA69A6D0 00000002CA69A728        428 UL              1          0          6          0        404          1 BLUE
00000002CA692FF0 00000002CA693048          2 UL              1          0          0          4        401          0 BLUE
00000002CA690A08 00000002CA690A60        404 UL              1          0          0          4        397          0 BLUE
00000002CA68ECF8 00000002CA68ED50        681 UL              1          0          0          4        403          0 BLUE
00000002CA67BA68 00000002CA67BAC0        379 UL              1          0          0          4        400          0 BLUE

退出sid=428的会话,阻塞消失。

Have a good day!继续学习。

此条目发表在Uncategorized分类目录。将固定链接加入收藏夹。

发表评论

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / 更改 )

Twitter picture

You are commenting using your Twitter account. Log Out / 更改 )

Facebook photo

You are commenting using your Facebook account. Log Out / 更改 )

Google+ photo

You are commenting using your Google+ account. Log Out / 更改 )

Connecting to %s