gc buffer busy acquire .. and release

VarugheseSeptember 17, 2016September 17, 2016

RAC Wait event gc buffer busy acquire indicates that the session experiencing this event is waiting on another session on the same instance to release the block. Basically the waiting session is not able to pin a block, and will wait on this event until it can pin the block. (gc buffer busy release means the session experiencing the event is waiting on a session from remote RAC instance.)

We had intermittent gc buffer busy acquire waits in the system. I used the below query to look into the details. (I think the same strategy can be used for gc buffer busy release.)

SELECT instance_number, sql_opname,event, p1, p2, p3,  current_obj#,  COUNT (*) cnt
FROM dba_hist_active_sess_history
WHERE sample_time BETWEEN TIMESTAMP '2016-09-14  14:02:00'
      AND TIMESTAMP '2016-09-14  14:14:00'
  AND wait_class = 'Cluster'
GROUP BY instance_number, event, sql_opname,p1, p2, p3, current_obj#
ORDER BY cnt DESC
 /

INST SQL_OPNAME EVENT                        P1         P2 P3 CURRENT_OBJ#  CNT
---- ---------- ------------------------- ----- ---------- -- ------------ ----
   2 SELECT     gc buffer busy acquire     3368    2979072  1    133868669   19
   2 SELECT     gc buffer busy acquire     3070    2085712  1    121281015   18
   2 SELECT     gc buffer busy acquire     1644    1298853  1    121281059   18
   2 SELECT     gc buffer busy acquire     3714    3564678  1    121281111   17
   2 SELECT     gc buffer busy acquire     3815    1114002  1    121281038   16
   2 SELECT     gc buffer busy acquire     3702    2919988  1    121281111   14
   2 SELECT     gc buffer busy acquire     4185    2813351  1    133868677   14
   2 SELECT     gc buffer busy acquire     3068    1428520  1    103874215   14
   2 SELECT     gc buffer busy acquire     3852     637200  1    121281015   13

gc buffer busy acquire and gc buffer busy release are basically buffer busy waits.
Buffer busy waits are usually caused by:

For tables with index on sequence generated column, Inserts will cause the right most leaf block of the index to grow causing contention. Index growth causes index block to split too. Such index leaf block will be hot.
Multiple session doing Inserts will content for segment header block in non-ASSM tablespace if freelist/freelist group is low.
Sequence with low Cache value could lead to contention for seq$ blocks if the usage(Inserts) is high
CPU issue. Low CPU can cause delays during the block pinning process (kind of stuck in between)
Interconnect delays also can cause delays during the block pinning process

But here, these statements are Select statements. Please see sql_opname below.

For Select statements, buffer busy waits can happen from plan inefficiency, and high concurrent execution can increase the severity.

For gc buffer busy acquire/release, parameter p1 is the file# and p2 is the block# and p3 is the block class.These object ids (also p1,p2) map to different partitions of the same table. Block class of 1 means these are data blocks.

Using a different query I realized that most these issues point to one particular step in the plan:

SELECT sql_id, SQL_PLAN_HASH_VALUE, SQL_PLAN_LINE_ID, COUNT (*) cnt
FROM dba_hist_active_sess_history h
WHERE  sample_time BETWEEN TIMESTAMP '2016-09-14  14:02:00'
       AND TIMESTAMP '2016-09-14  14:14:00'
  AND wait_class = 'Cluster' and event='gc buffer busy acquire'
GROUP BY sql_id, SQL_PLAN_HASH_VALUE, SQL_PLAN_LINE_ID
ORDER BY cnt DESC;

SQL_ID        SQL_PLAN_HASH_VALUE SQL_PLAN_LINE_ID        CNT
------------- ------------------- ---------------- ----------
0bp0244jtyykx           800453358                8         82
dcr0x1ka230k9           800453358                8         77
faz4zbwy58ar3           800453358                8         75
dchgsfds58akn           800453358                8         70
56tx1khv7vmrb           800453358                8         67
cj30tcbaqzjdc           800453358                8         63
d1swp67w795m9           800453358                8         61
91awx3zf97xgz           800453358                8         56
6rzmd2y2fwx44           980965006                8         47
3urxktq0h1u6h           800453358                8         36
8axjuyxs4zss7           800453358                8         33
8xzvgfd6drux2           800453358                8         25
4zu7k9gztappm           800453358                8         17
5cp8s99wrdwtx           800453358                8         16
90vcv0wqmx5ku           800453358                8         14
69hb3jbwwgzcy           800453358                8         11
2g2c9ratbnwwu          2426697778               14          8

Line 8 in the plan with hash value 800453358 is experiencing the wait. Though the sql_ids are different, they are basically same sql that differ only for literals.

Plan hash value: 800453358
--------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                         | Name                         | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                                  |                              |       |       |   139K(100)|          |       |       |
|   1 |  SORT UNIQUE                                      |                              |  4919 |   365K|   139K  (1)| 00:00:22 |       |       |
|   2 |   UNION-ALL                                       |                              |       |       |            |          |       |       |
|   3 |    CONCATENATION                                  |                              |       |       |            |          |       |       |
|   4 |     FILTER                                        |                              |       |       |            |          |       |       |
|   5 |      HASH JOIN OUTER                              |                              |   129K|  9596K| 69683   (1)| 00:00:11 |       |       |
|   6 |       NESTED LOOPS OUTER                          |                              | 23945 |  1613K| 39284   (1)| 00:00:07 |       |       |
|   7 |        NESTED LOOPS                               |                              |  4925 |   298K| 24505   (1)| 00:00:04 |       |       |
|   8 |         TABLE ACCESS BY GLOBAL INDEX ROWID BATCHED| FIN_STMT_ALL                 |  9475 |   314K|  5550   (1)| 00:00:01 | ROWID | ROWID |
|   9 |          INDEX RANGE SCAN                         | FIN_STMT_ACT_IX_5             |  9475 |       |   124   (0)| 00:00:01 |       |       |
..

It seems there is some issue with TABLE ACCESS BY GLOBAL INDEX ROWID BATCHED step in the plan. This is new in 12c and not much information is available on it. Oracle documentation says:

The BATCHED access means that the database retrieves a few rowids from the index, and then attempts to access rows in block order to improve the clustering and reduce the number of times that the database must access a block.

I want to optimize the plan avoiding the TABLE ACCESS BY GLOBAL INDEX ROWID BATCHED and see what happens. Need to investigate the suitability of the index FIN_STMT_ACT_IX_5. TABLE ACCESS BY GLOBAL INDEX ROWID BATCHED need not be the culprit. Need to check if SQL Tuning Advisor has some recommendations.

I will keep you posted.