Tuesday, March 11, 2014

GC buffer busy acquire in RAC


This is classic case when same Update runs from multiple Instance in RAC at same time and Execution plan is worst of all. this will create Heavy block contention.

These wait events used to be "buffer busy" in 10g but in 11g It has splited and granual at detail level.

we first analyzed AWR from all 3 Nodes for same Time frame and we found that "GC buffer busy acquire" and " Read by another session"


ON INSTANCE 1

ON INSTANCE 2

ON INSTANCE 3


So I ran few queries which can tell us more about what happen during this time-frame.
You may also find this query at Daily Performance Report.


SELECT sql_id,
text,
elapsed_time,
CPU_TIME,
EXECUTIONS,
round(elapsed_time/Executions,0) avg_elp_time,
PX_SERVERS,
DISK_READ_BYTES,
DISK_WRITE_BYTES,
IO_INTERCONNECT_BYTES,
OFFLOAD_ELIGIBLE_BYTES,
CELL_SMART_SCAN_ONLY_BYTES,
FLASH_CACHE_READS,
ROWS_PROCESSED
FROM (SELECT x.sql_id,
SUBSTR ( dhst.sql_text, 1, 30) text,
ROUND ( x.elapsed_time / 1000000,0)  elapsed_time,
ROUND ( x.cpu_time / 1000000,0)  CPU_TIME,
x.executions_delta       EXECUTIONS,
ROUND (X.DISK_READ_BYTES/1048576,0)        DISK_READ_BYTES,
ROUND (X.DISK_WRITE_BYTES/1048576,0)       DISK_WRITE_BYTES,
ROUND (X.IO_INTERCONNECT_BYTES/1048576,0)  IO_INTERCONNECT_BYTES,
ROUND (X.OFFLOAD_ELIGIBLE_BYTES/1048576,0) OFFLOAD_ELIGIBLE_BYTES,
X.FLASH_CACHE_READS                        FLASH_CACHE_READS,
ROUND (X.cell_smart_scan_only_BYTES/1048576,0)  CELL_SMART_SCAN_ONLY_BYTES,
(x.ROWS_PROCESSED) ROWS_PROCESSED,
(X.PX_SERVERS) PX_SERVERS,
row_number () OVER (PARTITION BY x.sql_id ORDER BY 0) rn
FROM dba_hist_sqltext dhst,
(SELECT dhss.sql_id                       sql_id,
SUM (dhss.cpu_time_delta)                 cpu_time,
SUM (dhss.elapsed_time_delta)             elapsed_time,
SUM (dhss.executions_delta)               executions_delta,
SUM (dhss.PHYSICAL_READ_BYTES_DELTA)      DISK_READ_BYTES,
SUM (dhss.PHYSICAL_WRITE_BYTES_DELTA)     DISK_WRITE_BYTES,
SUM (dhss.IO_INTERCONNECT_BYTES_DELTA)    IO_INTERCONNECT_BYTES,
SUM (dhss.IO_OFFLOAD_ELIG_BYTES_DELTA)    OFFLOAD_ELIGIBLE_BYTES,
SUM (dhss.OPTIMIZED_PHYSICAL_READS_DELTA) FLASH_CACHE_READS,
SUM (dhss.IO_OFFLOAD_RETURN_BYTES_DELTA)  cell_smart_scan_only_BYTES,
SUM (dhss.ROWS_PROCESSED_DELTA)      ROWS_PROCESSED,
SUM (dhss.PX_SERVERS_EXECS_DELTA) PX_SERVERS
FROM dba_hist_sqlstat dhss
WHERE dhss.snap_id IN
(SELECT snap_id
FROM dba_hist_snapshot
-----change snap_id here. 
WHERE SNAP_ID > 31822 AND SNAP_ID<= 31826)
GROUP BY dhss.sql_id) x
WHERE x.sql_id = dhst.sql_id
AND ROUND ( x.elapsed_time / 1000000, 3) > 3600)
WHERE rn = 1 and EXECUTIONS> 0
ORDER BY ELAPSED_TIME DESC;

---output

SQL_ID        TEXT                            ELAPSED_TIME  CPU_TIME  EXECUTIONS AVG_ELP_TIME   PX_SERVERS  DISK_READ_BYTES DISK_WRITE_BYTES IO_INTERCONNECT_BYTES OFFLOAD_ELIGIBLE_BYTES CELL_SMART_SCAN_ONLY_BYTES  FLASH_CACHE_READS ROWS_PROCESSED
------------- ------------------------------ ------------- --------- ----------- ------------ ------------ ---------------- ---------------- --------------------- ---------------------- -------------------------- -------------------- --------------
6vbxrnpxwc1mz BEGIN Sp_XYZ_DUMMY_Reversa             53686       830          98          548            0           344717                0                344824                    0                        107                    0             98
g25x6rr6x4yv7 UPDATE ABC_DUMMY_XYZACTION             44306       571          88          503            0            30440                0                 30426                    0                        -14                    0             88
74d8zqzh802xq SELECT MAX (BUSINESS_DATE || B         42335       186       14930            3            0             8293                0                  8293                    0                          0                    0          14921
g75678tr0ddmw BEGIN SP_PASSIVEPERIOD_CALC(:1         30266       150       10679            3            0             5567                0                  5567                    0                          0                    0          10678
cpz2fp6466vus SELECT CPT_TOTALHOLD_AMT FROM           9040       255         211           43            0           314231                0                314231                    0                          0                    0            209
7d4xjr17waxy7 BEGIN SP_CARD_ISSUENCE_SRT_TO_          4701       533         107           44            0           164865                0                164865                    0                          0                    0            103
c8hgnxkkr7jvz SELECT abc_ROW_ID, abc_SSNFAIL          4685       532         103           45            0           164861                0                164861                    0                          0                    0            103

For Top Hot object by Physical Read.   (Hot Object)

SELECT * FROM (
SELECT do.OWNER||'.'||do.OBJECT_NAME||'..['||do.OBJECT_TYPE||']' AS OBJECTS,
DHSS.INSTANCE_NUMBER AS INST,
SUM(DHSS.LOGICAL_READS_DELTA) LOGICAL_READ,
SUM(DHSS.PHYSICAL_READS_DELTA) PHY_READ,
SUM(DHSS.PHYSICAL_WRITES_DELTA) PHY_WRIT,
SUM(DHSS.ITL_WAITS_DELTA) ITL_WT,
SUM(DHSS.ROW_LOCK_WAITS_DELTA) ROW_LCK_WT
from dba_hist_seg_stat DHSS, DBA_OBJECTS DO
WHERE SNAP_ID > 31822 AND SNAP_ID<= 31826
--WHERE DHSS.SNAP_ID > 20135 AND DHSS.SNAP_ID<= 20183
AND DHSS.OBJ#=DO.OBJECT_ID
group by do.OWNER||'.'||do.OBJECT_NAME||'..['||do.OBJECT_TYPE||']',DHSS.INSTANCE_NUMBER
order BY PHY_READ DESC
) WHERE ROWNUM <=40;


OBJECTS                                             INST         LOGICAL_READ             PHY_READ    PHY_WRIT   ITL_WT ROW_LCK_WT
-------------------------------------------------- ----- -------------------- -------------------- ----------- -------- ----------
corpABC.ABC_DUMMY_XYZACTION..[TABLE]                2             22388144             16357126        1797        0          0
corpABC.ABC_DUMMY_XYZACTION..[TABLE]                1             19444032             14708504        2055        0          0
corpABC.ABC_DUMMY_XYZACTION..[TABLE]                3             16945392             12908672        1367        0          0
corpABC.ABC_CAF_INFO_ENTRY..[TABLE]                 1              7789840              7788316          98        0          0
corpABC.ABC_CAF_INFO_ENTRY..[TABLE]                 2              6969952              6968505          97        0          0
corpABC.ABC_CAF_INFO_ENTRY..[TABLE]                 3              6354976              6353643         104        0          0
corpABC.ABC_APPL_PAN..[TABLE]                       3              1149808              1069323         227        0          0
corpABC.ABC_APPL_PAN..[TABLE]                       2               903440               803870         256        0          0
corpABC.XYZACTIONLOG..[TABLE]                       3              1867424               629380         689        0          0
corpABC.XYZACTIONLOG..[TABLE]                       1           1197310176               436078         723        0          0
corpABC.XYZACTIONLOG..[TABLE]                       2              1909632               372565        1255        0          0
SQL_ID affected by "gc buffer busy acquire"
SQL> SELECT INSTANCE_NUMBER,SQL_ID,COUNT(EVENT) FROM DBA_HIST_ACTIVE_SESS_HISTORY WHERE SNAP_ID > 31822 AND SNAP_ID<= 31826 AND EVENT LIKE '%busy acquire%' group by sql_id,INSTANCE_NUMBER order by 2 desc;

INSTANCE_NUMBER SQL_ID                COUNT(EVENT)
-------------   ------------- --------------------
            3   g25x6rr6x4yv7                 619
            2   g25x6rr6x4yv7                 548
            1   g25x6rr6x4yv7                 192
SQL_ID affected by "read by other session"
SQL> SELECT SQL_ID,COUNT(EVENT) FROM DBA_HIST_ACTIVE_SESS_HISTORY WHERE SNAP_ID > 31822 AND SNAP_ID<= 31826 AND EVENT LIKE '%read by%' group by sql_id order by 2 desc;

INSTANCE_NUMBER SQL_ID                COUNT(EVENT)
-------------   ------------- --------------------
            3   g25x6rr6x4yv7                 764
            2   g25x6rr6x4yv7                 658
            1   g25x6rr6x4yv7                 169
Now lets see what is plan of Most affected SQL_ID '
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_AWR('g25x6rr6x4yv7'));


--------------------
UPDATE ABC_DUMMY_XYZACTION SET ABC_TOTALHOLD_AMT = TRIM(TO_CHAR(:B4, '77777777777')), ABC_DUMMY_VALIDFLAG = 'N',
ABC_XYZACTION_FLAG = 'R' WHERE ABC_RRN = :B3 AND ABC_TXN_DATE = :B2 AND ABC_INST_CODE = :B1

Plan hash value: 4161612620
----------------------------------------------------------------------------------------------
| Id  | Operation          | Name                    | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT   |                         |       |       | 12704 (100)|          |
|   1 |  UPDATE            |     ABC_DUMMY_XYZACTION |       |       |            |          |
|   2 |   TABLE ACCESS FULL|     ABC_DUMMY_XYZACTION |     1 |   106 | 12704   (1)| 00:02:33 |
----------------------------------------------------------------------------------------------


And Of-course it will generate GC wait event.  As you see "corp.ABC.ABC_DUMMY_XYZACTION"  is top Objects for Physical Reads. We created index on few columns which solved issue.

No comments:

Post a Comment