Enabling Flashback – Be Cautious

Enabling flashback on 11.2.0.4 database can take minutes and cause multiple database wait events degrading database performance.

On a quite busy system, during the low peak hours, I tried to enable flashback on 11.2.0.4.6 version database and multiple sessions waited on

1. buffer exterminate
2. enq: SQ – contention
3. latch: cbc contention
4. SGA: allocation forcing component growth

PRAKANAN_DBA@:1> show parameter sga_target
 
NAME                           TYPE        VALUE
------------------------------ ----------- ---------------
sga_target                     big integer 0

23:35:40 PRAKANAN_DBA@:1> show parameter db_cache_size
NAME                           TYPE        VALUE
------------------------------ ----------- ------------
db_cache_size                  big integer 39G

23:35:53 PRAKANAN_DBA@:1> show parameter shared_pool
 
NAME                           TYPE        VALUE
------------------------------ ----------- -------------
shared_pool_reserved_size      big integer 128M
shared_pool_size               big integer 4G

23:36:21 PRAKANAN_DBA@:1> @free_memory_in_shared_pool.sql
 
POOL         NAME                            BYTES
------------ -------------------------- ----------
shared pool  free memory                 283039728

23:38:48 PRAKANAN_DBA@:1> @shared_pool_detail.sql
 
POOL         NAME                               MB
------------ -------------------------- ----------
shared pool  KGLH0                      785.823174
shared pool  SQLA                        592.82975
shared pool  free memory                269.572815
shared pool  db_block_hash_buckets      268.503906
shared pool  SQLP                       192.214272
shared pool  KKSSP                       191.37767
shared pool  FileOpenBlock              156.083519
shared pool  event statistics per sess  142.083984
shared pool  ksunfy : SSO free list     135.169922
shared pool  KGLHD                      132.602089
shared pool  Checkpoint queue              128.125
shared pool  dirty object counts array         128
shared pool  dbktb: trace buffer          117.1875
shared pool  ASH buffers                       100
shared pool  parameter table block      83.7121429
shared pool  KGLDA                      36.5461655
shared pool  object queue hash buckets          36
shared pool  procs: ksunfy              30.6129456
shared pool  transaction                30.5776443
shared pool  enqueue                    27.7831573

SQL> alter database flashback on;
 
Database altered.

23:41:28 PRAKANAN_DBA@:1> /
 
USERNAME                      SID    SERIAL# SPID       EVENT                          LAST_CALL_ET  WAIT_TIME SECONDS_IN_WAIT STATE               SQL_ID        SQL_CHILD_NUMBER PLAN_HASH_VALUE MODULE
------------------------- ------- ---------- ---------- ------------------------------ ------------ ---------- --------------- ------------------- ------------- ---------------- --------------- -------------------------
APPS_USER_2                  3458       9875 15518      SQL*Net message from client               0          0               0 WAITING             b4pav99kxux32                0      3764792327 SessionV2
PRAKANAN_DBA                 9290      35933 21649      SQL*Net message to client                 0         -1               0 WAITED SHORT TIME   8q6awbsup6jm5                0      1761607409 SQL*Plus
APPS_USER_2                  1963      13699 28348      buffer exterminate                        1          0               0 WAITING             2zrudchusrcwa                3               0 JDBC Thin Client
SQL_240                      7301      36487 28346      buffer exterminate                        1          0               0 WAITING             2zrudchusrcwa                3               0
APPS_USER_2                  7467      12721 28352      buffer exterminate                        1          0               0 WAITING             2zrudchusrcwa                3               0 JDBC Thin Client
APPS_USER_2                  9038      42107 28351      buffer exterminate                        1          0               0 WAITING             2zrudchusrcwa                3               0 JDBC Thin Client
APPS_USER_2                 11153      29227 28354      buffer exterminate                        1          0               0 WAITING             2zrudchusrcwa                3               0 JDBC Thin Client
APPS_USER_2                   438      52879 28356      buffer exterminate                        1          0               0 WAITING             2zrudchusrcwa                3               0 JDBC Thin Client
APPS_USER_2                  1449      29585 3901       read by other session                     0          0               0 WAITING             4n4u2qqbfcmhu                1      1270994832 ResourceMonitor
APPS_USER_2                  5405      26175 6055       latch: cache buffers chains               0         -1               0 WAITED SHORT TIME   4n4u2qqbfcmhu                1      1270994832 ResourceMonitor
APPS_USER_2                  7807       9423 6057       db file sequential read                   0          0               0 WAITING             2ksm378ta54rw                2       231135236 ResourceMonitor
APPS_USER_2                  2319      34579 12665      db file sequential read                   0          0               0 WAITING             4n4u2qqbfcmhu                1      1270994832 ResourceMonitor
APPS_USER_2                   570      11479 5193       read by other session                     0          0               0 WAITING             4n4u2qqbfcmhu                1      1270994832 ResourceMonitor
SYS                          7106      60689 14609      SGA: allocation forcing compon           11          0               0 WAITING             1pbrwgrgmfu40                0               0 sqlplus@
                                                        ent growth                                                                                                                                
APPS_USER_2                   196      22161 5270       read by other session                     0          0               0 WAITING             4n4u2qqbfcmhu                1      1270994832 ResourceMonitor
 
15 rows selected.
 
Elapsed: 00:00:00.45
23:41:29 PRAKANAN_DBA@:1> /
 
USERNAME                      SID    SERIAL# SPID       EVENT                          LAST_CALL_ET  WAIT_TIME SECONDS_IN_WAIT STATE               SQL_ID        SQL_CHILD_NUMBER PLAN_HASH_VALUE MODULE
------------------------- ------- ---------- ---------- ------------------------------ ------------ ---------- --------------- ------------------- ------------- ---------------- --------------- -------------------------
APPS_USER_2                   899      26003 12761      enq: TX - index contention                0          0               0 WAITING             7mvrrf2cr8w26                1      3334570644 ResourceMonitor
PRAKANAN_DBA                 9290      35933 21649      SQL*Net message to client                 0         -1               0 WAITED SHORT TIME   8q6awbsup6jm5                0      1761607409 SQL*Plus
SYS                          7106      60689 14609      SGA: allocation forcing compon           12          0               1 WAITING             1pbrwgrgmfu40                0               0 sqlplus@
                                                        ent growth 
 
Elapsed: 00:00:00.44
23:41:30 PRAKANAN_DBA@:1> /
 
USERNAME                      SID    SERIAL# SPID       EVENT                          LAST_CALL_ET  WAIT_TIME SECONDS_IN_WAIT STATE               SQL_ID        SQL_CHILD_NUMBER PLAN_HASH_VALUE MODULE
------------------------- ------- ---------- ---------- ------------------------------ ------------ ---------- --------------- ------------------- ------------- ---------------- --------------- -------------------------
APPS_USER_2                    45       5745 18731      db file sequential read                   0         -1               0 WAITED SHORT TIME   7mvrrf2cr8w26                0      3334570644 ResourceMonitor
PRAKANAN_DBA                 9290      35933 21649      SQL*Net message to client                 0         -1               0 WAITED SHORT TIME   8q6awbsup6jm5                0      1761607409 SQL*Plus
APPS_USER_2                 10446      23443 14617      SQL*Net message from client               0          5               0 WAITED KNOWN TIME   8tk54xvssnx13                0      3718310410 SessionV2
SYS                          7106      60689 14609      SGA: allocation forcing compon           13          0               2 WAITING             1pbrwgrgmfu40                0               0 sqlplus@
                                                        ent growth

23:42:17 PRAKANAN_DBA@:1> show parameter shared_pool
 
NAME                           TYPE        VALUE
------------------------------ ----------- ----------------------
shared_pool_reserved_size      big integer 128M
shared_pool_size               big integer 4224M

23:42:48 PRAKANAN_DBA@:1> @free_memory_in_shared_pool.sql
 
POOL         NAME                            BYTES
------------ -------------------------- ----------
shared pool  free memory                2147133056

PRAKANAN_DBA@:1> @hidden_param
Enter value for parameter: _memory_imm_mode_without_autosga
Enter value for 1: _memory_imm_mode_without_autosga
old  11: AND    a.ksppinm like DECODE(LOWER('%&parameter%'), 'all', a.ksppinm, LOWER('%&1%'))
new  11: AND    a.ksppinm like DECODE(LOWER('%_memory_imm_mode_without_autosga%'), 'all', a.ksppinm, LOWER('%_memory_imm_mode_without_autosga%'))
 
PARAMETER                             DESCRIPTION                    SESSION_VA INSTANCE_V
------------------------------------- ------------------------------ ---------- ----------
_memory_imm_mode_without_autosga      Allow immediate mode without   TRUE       TRUE
                                      sga/memory target

23:43:18 PRAKANAN_DBA@:1> select start_time,COMPONENT, PARAMETER, INITIAL_SIZE/1024/1024 "INITIAL_SIZE",FINAL_SIZE/1024/1024 "FINAL_SIZE", STATUS from v$SGA_RESIZE_OPS where start_time > sysdate -1 order by 1;
 
START_TIME          COMPONENT                                                        PARAMETER                                                                        INITIAL_SIZE FINAL_SIZE STATUS
------------------- ---------------------------------------------------------------- -------------------------------------------------------------------------------- ------------ ---------- ---------
2016.11.01 23:41:21 shared pool                                                      shared_pool_size                                                                         4096       4096 ERROR
2016.11.01 23:41:21 DEFAULT buffer cache                                             db_cache_size                                                                           39936      39936 ERROR
2016.11.01 23:41:31 DEFAULT buffer cache                                             db_cache_size                                                                           39936      39808 COMPLETE
2016.11.01 23:41:31 shared pool                                                      shared_pool_size                                                                         4096       4224 COMPLETE
 
23:43:33 PRAKANAN_DBA@:1> @shared_pool_resize_ops.sql
 
END                     OPER_TYPE     INITIAL_SIZE TARGET_SIZE FINAL_SIZE
----------------------- ------------- ------------ ----------- ----------
01-Nov-2016 23:41       GROW            4294967296  4429185024 4294967296
01-Nov-2016 23:41       GROW            4294967296  4429185024 4429185024
29-Nov-2015 09:01       STATIC                   0  4294967296 4294967296

23:43:56 PRAKANAN_DBA@:1> @shared_pool_detail.sql
 
POOL         NAME                               MB
------------ -------------------------- ----------
shared pool  free memory                2044.86245
shared pool  db_block_hash_buckets      268.503906
shared pool  KKSSP                      191.963104
shared pool  FileOpenBlock              156.083519
shared pool  event statistics per sess  142.083984
shared pool  ksunfy : SSO free list     135.169922
shared pool  Checkpoint queue              128.125
shared pool  dirty object counts array         128
shared pool  flashback generation buff  124.156067
shared pool  dbktb: trace buffer          117.1875
shared pool  ASH buffers                       100
shared pool  parameter table block      83.8214722
shared pool  object queue hash buckets          36
shared pool  procs: ksunfy              30.6129456
shared pool  transaction                30.5776443
shared pool  enqueue                    27.7831573
shared pool  buffer handles             25.1770096
shared pool  state objects              22.5323486
shared pool  write state object         19.9843826
shared pool  KGLH0                      18.8174286

Alert log :-

alter database flashback on
Starting background process RVWR
Tue Nov 01 23:40:08 2016
RVWR started with pid=6159, OS id=1030
Tue Nov 01 23:40:29 2016
Errors in file /dumps-01/diag/rdbms/db1/db1/trace/db1_ora_29214.trc:
ORA-00379: no free buffers available in buffer pool DEFAULT for block size 8K
ORA-00379: no free buffers available in buffer pool DEFAULT for block size 8K

Trace file shows --

Scanned into hot portion of LRU
Deadlock because all buffers pinned.
In set=527, bsz=8192, wsi=0, poolid=3, pool_name=DEFAULT
Buffers originally scanned and found pinned = [189 0], evict=189, aged=0
Buffers rescanned on auxiliary list = 0
Buffers rescanned on main list = 140
Buffers in working set 189 (0), hbufs=50, hbmax=50
Buffers on repl list main=189, aux=0
Scanned into hot portion of LRU
Deadlock because all buffers pinned.
In set=528, bsz=8192, wsi=0, poolid=3, pool_name=DEFAULT
Buffers originally scanned and found pinned = [185 1], evict=184, aged=0
Buffers rescanned on auxiliary list = 0
Buffers rescanned on main list = 136
Buffers in working set 185 (0), hbufs=50, hbmax=50
Buffers on repl list main=185, aux=0

*** 2016-11-01 23:40:29.473
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=3, mask=0x0)
----- Error Stack Dump -----
ORA-00379: no free buffers available in buffer pool DEFAULT for block size 8K
ORA-00379: no free buffers available in buffer pool DEFAULT for block size 8K
----- SQL Statement (None) -----
Current SQL information unavailable - no cursor.

From Metalink Doc id 2195173.1

The normal behavior is that the flashback buffer is only allocated at mount time if flashback is already enabled, otherwise the flashback buffer is allocated later when the Database Administrator decides to enable flashback (either explicitly, or by creating the first restore point) but in the latter case, there is the possibility that the database performance may be impacted as the instance searches for the required amount of contiguous memory in shared pool to allocate to the flashback buffer.

The issue is related to

Bug 24838599 Turning on Flashback Database May Take Minutes to Complete and may cause errors ORA-4031 ORA-379″ Doc ID 24838599.8

Patch 24838599: TURNING ON FLASHBACK DATABASE TAKES 15 MINUTES TO COMPLETE

Post Install Instructions for Bug 24838599 – Turning on Flashback Database May Take Minutes to Complete (Doc ID 2195173.1)

Hope this helps!!

Leave a Reply

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 / Change )

Twitter picture

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

Facebook photo

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

Google+ photo

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

Connecting to %s