效能問題，AWR High Event enq: US - contention

綠茶有點甜發表於2020-11-13
ENQ

 

1.1問題現象

 應用反饋業務執行SQL響應超時，需要資料庫排除DB是否存在問題，建立AWR觀察到top event 新增enq: US - contention  ???

1.2問題分析

1） DB Time指標
2020-11-12 17:30 18:00                        DB time         3310.19
2020-11-12 18:00 18:30                        DB time        15883.77
2020-11-12 18:30 19:00                        DB time        19463.52
2020-11-12 19:00 19:30                        DB time        16001.57

2） AWR報告
Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                            Tota    Wait   % DB
Event                                 Waits Time Avg(ms)   time Wait Class
------------------------------ ------------ ---- ------- ------ ----------
latch: row cache objects         41,636,274 669.      16   57.4 Concurrenc
enq: US - contention             20,130,960 291.      14   25.0 Other
latch: ges resource hash list    11,265,725 55.8       5    4.8 Other
DB CPU                                      33.2            2.8
buffer busy waits                 3,502,842 2301       1     .2 Concurrenc
log file sync                     1,831,042 1774       1     .2 Commit
library cache: mutex X              301,887 1170       4     .1 Concurrenc
latch: cache buffers chains       1,222,834 924.       1     .1 Concurrenc
latch: enqueue hash chains          365,389 222.       1     .0 Other
latch: undo global data             505,480 116.       0     .0 Other

Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time                          1,165,594.2         99.8
PL/SQL execution elapsed time                       611,956.6         52.4
DB CPU                                               33,234.1          2.8
parse time elapsed                                       20.2           .0
connection management call elapsed time                  17.0           .0
repeated bind elapsed time                                3.2           .0
hard parse elapsed time                                   0.0           .0
sequence load elapsed time                                0.0           .0
hard parse (sharing criteria) elapsed time                0.0           .0
failed parse elapsed time                                 0.0           .0
DB time                                           1,167,811.4
background elapsed time                               1,515.8
background cpu time                                     513.7

-> Ordered by statistic name

Statistic                                     Total     per Second     per Trans
-------------------------------- ------------------ -------------- -------------
db block changes                         97,449,293       54,125.4          47.7
execute count                            14,890,901        8,270.7           7.3
gc cr block receive time                      1,277            0.7           0.0
gc cr blocks received                        28,544           15.9           0.0
gc current block receive time                24,427           13.6           0.0
gc current blocks received                   94,906           52.7           0.1
logons cumulative                             2,788            1.6           0.0
opened cursors cumulative                 3,649,945        2,027.3           1.8
parse count (total)                       2,649,940        1,471.8           1.3
parse time elapsed                            1,781            1.0           0.0
physical reads                               18,385           10.2           0.0
physical writes                           2,808,767        1,560.1           1.4
redo size                            23,166,050,528   12,866,904.3      11,345.2
session cursor cache hits                 2,292,253        1,273.2           1.1
session logical reads                 2,394,937,749    1,330,198.0       1,172.9
user calls                                8,341,907        4,633.3           4.1
user commits                              1,911,204        1,061.5           0.9
user rollbacks                              130,726           72.6           0.1
workarea executions - optimal               206,244          114.6           0.1
                          ------------------------------------------------------

3）新出現的等待事件是什麼？
enq: US - contention 參考如下文件

How to correct performance issues with enq: US - contention related to undo segments (Doc ID 1332738.1)

The wait event "enq: US Contention" is associated with contention on the latch in the row cache (dc_rollback_seg). Enqueue US - Contention can become a bottle-neck for performance if workload dictates that a lot of offlined undo segments must be onlined over a short period of time. The latch on the row cache can be unable to keep up with the workload.

This can happen for a number of reasons and some scenarios are legitimate workload demands.
Solution: ensure that peaks in onlined undo segments do not happen (see workaround #2). That is not always feasible.

從裡面我們能掌握的資訊有，UNDO的爭用, 理想化的解決方法是避免undo段的使用出現峰值？？？ 呵呵。

4）UNDO表空間的使用情況查詢

SQL> select status,sum(bytes)/1024/1024/1024,TABLESPACE_NAME from dba_undo_extents group by status,TABLESPACE_NAME;
STATUS SUM(BYTES)/1024/1024/1024 TABLESPACE_NAME
--------- ------------------------- ------------------------------
EXPIRED .194824219 UNDOTBS1
EXPIRED 2.67224121 UNDOTBS2
UNEXPIRED 29.1513672 UNDOTBS1
ACTIVE 7.76220703 UNDOTBS1
UNEXPIRED 10.0617676 UNDOTBS2

 

GROUP_NUMBER NAME TOTAL_GB FREE_GB FREE_PERCENT STATE TYPE CARE
------------ -------------------- ---------- ---------- ------------ --------------- ------ -----
1 ARCH 500.00 499.87 99.97 CONNECTED EXTERN
2 DATA 500.00 49.74 9.95 CONNECTED EXTERN *
3 OCR 30.00 29.10 96.99 MOUNTED NORMAL
4 REDO_LOG 100.00 85.87 85.87 CONNECTED EXTERN

SQL> show parameter undo

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
_gc_undo_affinity boolean FALSE
_undo_autotune boolean FALSE
undo_management string AUTO
undo_retention integer 10800
undo_tablespace string UNDOTBS1
SQL> select 10800/60/60 from dual;
10800/60/60
-----------
3

 

1.3問題處理

根據查詢到的UNDO情況，我們可以發現UNDOTBS1 第一個檔案自擴充套件，當前分配7G,最大可擴充套件31.9xxG; UNDOTBS2 第一個檔案自擴充套件，當前分配0.02G,最大可擴充套件31.9XXXG;
根據UNDO EXTENT狀態可以發現，UNDOTBS1 30G處於UNEXPIRED 未過期狀態，7G處於正在使用；只有少量數量處於已過期狀態；
                          UNDOTBS2 10G處於UNEXPIRED 未過期狀態，0G處於正在使用；2.6G已過期狀態；
由於UNDOTBS1 有2個UNDO檔案，第一個DB建好，自擴充套件，當前7，最大31.9G；  第二個DB建後，DBA新增的已完全分配，非自動擴充套件30G；
本次就是由於UNDOTBS1還有擴充套件的可能性，因此新的UNDO申請需要對UNDOTBS1的第一個自擴充套件檔案進行擴充套件時，出現嚴重的爭用；
擴容！！！

SQL> alter tablespace UNDOTBS1 add datafile '+DATA' size 30g;
SQL> alter tablespace UNDOTBS2 add datafile '+DATA' size 10g;

業務反饋突然好了！

收尾
select file_id,TABLESPACE_NAME,bytes/1024/1024/1024,MAXbytes/1024/1024/1024 from dba_data_files where tablespace_name in('UNDOTBS1','UNDOTBS2');
FILE_ID TABLESPACE_NAME BYTES/1024/1024/1024 MAXBYTES/1024/1024/1024
---------- ------------------------------ -------------------- -----------------------
3 UNDOTBS1 7.14355469 31.9999847
5 UNDOTBS2 .024414063 31.9999847
6 UNDOTBS1 30 0
7 UNDOTBS2 30 0
18 UNDOTBS1 30 0
19 UNDOTBS2 10 0
6 rows selected.

select file_name from dba_data_files where file_id in(3,5);
SQL> alter database datafile 3,5 autoextend off;
SQL> alter database datafile '+DATA/wglcta/datafile/undotbs1.258.1047648231' resize 10g;
SQL> alter database datafile '+DATA/wglcta/datafile/undotbs2.264.1047648343' resize 10g;
select file_id,TABLESPACE_NAME,bytes/1024/1024/1024,AUTOEXTENSIBLE,MAXbytes/1024/1024/1024 from dba_data_files where tablespace_name in('UNDOTBS1','UNDOTBS2');
FILE_ID TABLESPACE_NAME BYTES/1024/1024/1024 AUT MAXBYTES/1024/1024/1024
---------- ------------------------------ -------------------- --- -----------------------
3 UNDOTBS1 10 NO 0
5 UNDOTBS2 10 NO 0
6 UNDOTBS1 30 NO 0
7 UNDOTBS2 30 NO 0
18 UNDOTBS1 30 NO 0
19 UNDOTBS2 10 NO 0

GROUP_NUMBER NAME TOTAL_GB FREE_GB FREE_PERCENT STATE TYPE CARE
------------ -------------------- ---------- ---------- ------------ --------------- ------ -----
1 ARCH 500.00 499.87 99.97 CONNECTED EXTERN
2 DATA 500.00 26.89 5.38 CONNECTED EXTERN *

 

 

1.4事後追蹤

1） 確認UNDOTBS1的使用情況，最近幾個小時包括問題時段
SQL> select ts#,name from v$tablespace where name='UNDOTBS1';
       TS# NAME
---------- --------------------
         2 UNDOTBS1
         
select * from 
DBA_HIST_TBSPC_SPACE_USAGE where TABLESPACE_ID=2 order by RTIME;
   SNAP_ID       DBID TABLESPACE_ID TABLESPACE_SIZE TABLESPACE_MAXSIZE TABLESPACE_USEDSIZE RTIME
---------- ---------- ------------- --------------- ------------------ ------------------- -------------------------
      4728  476729316             2         3942400            8126462             1344368 11/12/2020 01:30:01
      4729  476729316             2         3942400            8126462             1147240 11/12/2020 02:00:04
      4730  476729316             2         3942400            8126462             1001072 11/12/2020 02:30:10
      4731  476729316             2         3942400            8126462              923368 11/12/2020 03:00:12
      4732  476729316             2         3942400            8126462              959200 11/12/2020 03:30:01
      4733  476729316             2         3942400            8126462              973392 11/12/2020 04:00:02
      4734  476729316             2         3942400            8126462              990800 11/12/2020 04:30:03
      4735  476729316             2         3942400            8126462             1031128 11/12/2020 05:00:04
      4736  476729316             2         3942400            8126462             1087312 11/12/2020 05:30:06
      4737  476729316             2         3942400            8126462             1168968 11/12/2020 06:00:07
      4738  476729316             2         3942400            8126462             1315032 11/12/2020 06:30:08
      4739  476729316             2         3942400            8126462             1544672 11/12/2020 07:00:10
      4740  476729316             2         3942400            8126462             1795568 11/12/2020 07:30:11
      4741  476729316             2         3942400            8126462             2033392 11/12/2020 08:00:12
      4742  476729316             2         3942400            8126462             2305024 11/12/2020 08:30:14
      4743  476729316             2         3942400            8126462             2605192 11/12/2020 09:00:15
      4744  476729316             2         3942400            8126462             2872568 11/12/2020 09:30:16
      4745  476729316             2         3942400            8126462             3098480 11/12/2020 10:00:18
      4746  476729316             2         3942400            8126462             3246192 11/12/2020 10:30:06
      4747  476729316             2         3942400            8126462             3414576 11/12/2020 11:00:11
      4748  476729316             2         3942400            8126462             3577952 11/12/2020 11:30:14
      4749  476729316             2         3942400            8126462             3580104 11/12/2020 12:00:17
      4750  476729316             2         3942400            8126462             3458504 11/12/2020 12:30:19
      4751  476729316             2         3942400            8126462             3300168 11/12/2020 13:00:22
      4752  476729316             2         3942400            8126462             3024576 11/12/2020 13:30:28
      4753  476729316             2         3942400            8126462             2831064 11/12/2020 14:00:29
      4754  476729316             2         3942400            8126462             2698656 11/12/2020 14:30:31
      4755  476729316             2         3942400            8126462             2644232 11/12/2020 15:00:32
      4756  476729316             2         3942400            8126462             2669832 11/12/2020 15:30:37
      4757  476729316             2         3942400            8126462             2780168 11/12/2020 16:00:38
      4758  476729316             2         3942400            8126462             2911240 11/12/2020 16:30:40
      4759  476729316             2         3942400            8126462             2985720 11/12/2020 17:00:41
      4760  476729316             2         3942400            8126462             3577632 11/12/2020 17:30:42
      4761  476729316             2         3942400            8126462             3697616 11/12/2020 18:00:44
      4762  476729316             2         3942400            8126462             3812664 11/12/2020 18:30:44
      4763  476729316             2         4071680            8126462             4055680 11/12/2020 19:01:35
      4764  476729316             2         8800640           12058622             4935560 11/12/2020 19:30:12
695 rows selected.
           
參考
https://yq.aliyun.com/articles/283841

我們查詢ASH檢視看看當時的情況：

 SELECT D.SQL_ID,CHR(BITAND(P1, -16777216) / 16777215) ||
        CHR(BITAND(P1, 16711680) / 65535) "Lock",
        BITAND(P1, 65535) "Mode", COUNT(1),COUNT(DISTINCT d.session_id )
  FROM DBA_HIST_ACTIVE_SESS_HISTORY D
 WHERE D.SAMPLE_TIME BETWEEN TO_DATE('2020-11-12 16:00:00', 'YYYY-MM-DD HH24:MI:SS') AND
       TO_DATE('2020-11-12 19:00:00', 'YYYY-MM-DD HH24:MI:SS')
   AND D.EVENT = 'enq: US - contention'
 GROUP BY D.SQL_ID,(CHR(BITAND(P1, -16777216) / 16777215) ||
        CHR(BITAND(P1, 16711680) / 65535)),(BITAND(P1, 65535));

SQL_ID        Lock           Mode   COUNT(1) COUNT(DISTINCTD.SESSION_ID)
------------- -------- ---------- ---------- ---------------------------
q              US                6       5472                        1161
c              US                6      33943                        1340select distinct sql_id,sql_text from v$sql where sql_id in('xx')
 order by 1;


2）AWR對比報告，看看能否觀察一些其它資訊

AWR對比報告
@?/rdbms/admin/awrddrpt.sql

Snapshot Set Begin Snap Id Begin Snap Time End Snap Id End Snap Time Avg Active Users Elapsed Time (min) DB time (min)
------------ -------------- ------------------------- ------------ ------------------------- -------------------------- 
1st 4761 12-Nov-20 18:00:43 (Thu) 4762 12-Nov-20 18:30:00 (Thu) 542.2 29.3 15,883.8
2nd 4760 12-Nov-20 17:30:41 (Thu) 4761 12-Nov-20 18:00:43 (Thu) 113.0 30.0 3,310.2
~~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~~~~   %Diff: -79.7% 2.5% -79.2%

 

 

 

 

 

 

 

 

 

How to correct performance issues with enq: US - contention related to undo segments (Doc ID 1332738.1)
IF: Undo Wait Event - Enq: US - contention (Doc ID 1951680.1)

Update to latest version or apply the Patch 14226599 (included in 11.2.0.4 patchset and above) and Patch 17720709 (included in 12.2 and above)
Setting _ROLLBACK_SEGMENT_COUNT to a high number to keep undo segments online:
ALTER SYSTEM SET "_rollback_segment_count"=<n>;

Note: In databases with high query activity, particularly parallel query and a high setting for _ROLLBACK_SEGMENT_COUNT, you can expect to see wait contention on the row cache for DC_ROLLBACK_SEGS. It is highly recommended in these environments where setting _ROLLBACK_SEGMENT_COUNT to a high value (10s of thousands and higher) apply the patch for Bug:14226599 (as mentioned in solution 1). This will increase the hash buckets on the DC_ROLLBACK_SEGS row cache to help alleviate latch contention.
A fix to Bug:7291739 is to set a new hidden parameter, _HIGHTHRESHOLD_UNDORETENTION to set a high threshold for undo retention completely distinct from maxquerylen:
ALTER SYSTEM SET "_highthreshold_undoretention"=<n>;

相關文章