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!!

Advertisements

Flashback : Guaranteed Restore Point

Oracle Flashback database and restore points enables us to rewind the database back in time to correct any problems caused by logical data corruption or user errors and it doesn’t require any restoration of backup. There are 2 types of restoration points —

1. Normal Restore Point –> assigns a restore point name to an SCN or specific point in time.The control file stores the name of the restore point and the SCN.

2. Guaranteed Restore Point –> Like Normal restore point, it also serves as an alias for an SCN in recovery operation. The only difference is that the guaranteed restore points never age out of the control file and must be explicitly dropped.

Logging for Guaranteed Restore Points with Flashback Logging Disabled

Assume that you create a guaranteed restore point when logging for Flashback Database is disabled. In this case, the first time a data file block is modified after the time of the guaranteed restore point, the database stores an image of the block before the modification in the flashback logs. Thus, the flashback logs preserve the contents of every changed data block at the time that the guaranteed restore point was created. Later modifications to the same block do not cause the contents to be logged again unless another guaranteed restore point was created after the block was last modified.


11:31:49 SYS@ORCL:1> select name,database_role,open_mode,flashback_on,log_mode from v$database;

NAME      DATABASE_ROLE    OPEN_MODE            FLASHBACK_ON       LOG_MODE
--------- ---------------- -------------------- ------------------ ------------
ORCL      PRIMARY          READ WRITE           NO                 ARCHIVELOG

11:31:54 SYS@ORCL:1> show parameter recovery

NAME                           TYPE        VALUE
------------------------------ ----------- ----------------------------------------------------------------------------------------------------
db_recovery_file_dest          string      D:\oracle\flashback\orcl
db_recovery_file_dest_size     big integer 2G
recovery_parallelism           integer     0
11:31:56 SYS@ORCL:1>  SELECT NAME, SCN, TIME, DATABASE_INCARNATION#, GUARANTEE_FLASHBACK_DATABASE, STORAGE_SIZE FROM V$RESTORE_POINT WHERE GUARANTEE_FLASHBACK_DATABASE='YES';

no rows selected

Create Guaranteed restore point —

11:31:58 SYS@ORCL:1> CREATE RESTORE POINT test_anand GUARANTEE FLASHBACK DATABASE;

Restore point created.

11:32:41 SYS@ORCL:1>
11:33:27 SYS@ORCL:1>  SELECT NAME, SCN, TIME, DATABASE_INCARNATION#, GUARANTEE_FLASHBACK_DATABASE, STORAGE_SIZE FROM V$RESTORE_POINT WHERE GUARANTEE_FLASHBACK_DATABASE='YES';

NAME                SCN TIME                                DATABASE_INCARNATION# GUA STORAGE_SIZE
------------ ---------- ----------------------------------- --------------------- --- ------------
TEST_ANAND      1297697 14-JAN-13 11.32.39.000000000 AM                         2 YES     52428800

Alert log shows —


Mon Jan 14 11:32:39 2013
Starting background process RVWR
Mon Jan 14 11:32:39 2013
RVWR started with pid=25, OS id=7032 
Allocated 3981204 bytes in shared pool for flashback generation buffer
Created guaranteed restore point TEST_ANAND

Lets create an user, table and do some dmls

11:35:36 SYS@ORCL:1> create user anand identified by anand123 default tablespace users;

User created.

11:36:16 SYS@ORCL:1>
11:36:17 SYS@ORCL:1> grant connect,resource to anand;

Grant succeeded.

11:36:25 SYS@ORCL:1>
11:36:42 SYS@ORCL:1> grant dba to anand;

Grant succeeded.

11:36:48 SYS@ORCL:1> conn anand/anand123
Connected.
11:36:52 ANAND@ORCL:1>
11:36:53 ANAND@ORCL:1> create table test as select * from all_objects;

Table created.
11:37:52 ANAND@ORCL:1> insert into test select * from test;

72583 rows created.

...................
....................
....................

11:39:01 ANAND@ORCL:1> insert into test select * from test;

1161328 rows created.

11:41:11 ANAND@ORCL:1> select * from V$FLASHBACK_DATABASE_LOG;

OLDEST_FLASHBACK_SCN OLDEST_FLASHBACK_TI RETENTION_TARGET FLASHBACK_SIZE ESTIMATED_FLASHBACK_SIZE
-------------------- ------------------- ---------------- -------------- ------------------------
             1297697 2013.01.14 11:32:41             1440      104857600                        0

11:41:30 ANAND@ORCL:1>
11:41:31 ANAND@ORCL:1>
11:41:31 ANAND@ORCL:1> select * from V$FLASHBACK_DATABASE_STAT;

BEGIN_TIME          END_TIME            FLASHBACK_DATA    DB_DATA  REDO_DATA ESTIMATED_FLASHBACK_SIZE
------------------- ------------------- -------------- ---------- ---------- ------------------------
2013.01.14 11:32:41 2013.01.14 11:41:50       12484608  199311360  278596608                        0

11:41:50 ANAND@ORCL:1>
11:42:35 ANAND@ORCL:1> select * from V$FLASHBACK_DATABASE_LOGFILE;

NAME                                                               LOG#    THREAD#  SEQUENCE#      BYTES FIRST_CHANGE# FIRST_TIME          TYPE
------------------------------------------------------------ ---------- ---------- ---------- ---------- ------------- ------------------- ---------
D:\ORACLE\FLASHBACK\ORCL\ORCL\FLASHBACK\O1_MF_8H77W05C_.FLB           1          1          1   52428800       1297697 2013.01.14 11:32:41 NORMAL
D:\ORACLE\FLASHBACK\ORCL\ORCL\FLASHBACK\O1_MF_8H77W2JM_.FLB           2          1          1   52428800             0                     RESERVED


V$FLASHBACK_DATABASE_LOG –> displays information about the flashback data. Use this view to help estimate the amount of flashback space required for the current workload.

V$FLASHBACK_DATABASE_STAT displays statistics for monitoring the I/O overhead of logging flashback data.

11:43:32 ANAND@ORCL:1> insert into test select * from test;

2322656 rows created.

11:43:47 ANAND@ORCL:1> commit;

Commit complete.

11:44:47 ANAND@ORCL:1> select * from V$FLASHBACK_DATABASE_STAT;

BEGIN_TIME          END_TIME            FLASHBACK_DATA    DB_DATA  REDO_DATA ESTIMATED_FLASHBACK_SIZE
------------------- ------------------- -------------- ---------- ---------- ------------------------
2013.01.14 11:32:41 2013.01.14 11:44:57       26501120  482787328  558669824                        0

11:44:57 ANAND@ORCL:1>

Now, lets try to flashback the database to restore point

11:52:24 SYS@ORCL:1> flashback database to restore point test_anand;
flashback database to restore point test_anand
*
ERROR at line 1:
ORA-38757: Database must be mounted and not open to FLASHBACK.

To flashback the database must be in mount mode. Shutdown the db and mount it. Before mounting the database, moved all the archive logs generated from creating the restore point till the shutdown and tried flashback.

11:54:44 SYS@ORCL:1> flashback database to restore point test_anand;
flashback database to restore point test_anand
*
ERROR at line 1:
ORA-38754: FLASHBACK DATABASE not started; required redo log is not available
ORA-38762: redo logs needed for SCN 1297662 to SCN 1297697
ORA-38761: redo log sequence 13 in thread 1, incarnation 2 could not be accessed

13:28:36 SYS@ORCL:1> select CHECKPOINT_CHANGE#,CHECKPOINT_TIME,UNRECOVERABLE_CHANGE#,UNRECOVERABLE_TIME from v$datafile;

CHECKPOINT_CHANGE# CHECKPOINT_TIME     UNRECOVERABLE_CHANGE# UNRECOVERABLE_TIME
------------------ ------------------- --------------------- -------------------
           1309113 2013.01.14 11:52:35                     0
           1309113 2013.01.14 11:52:35                     0
           1309113 2013.01.14 11:52:35                     0
           1309113 2013.01.14 11:52:35                     0
           1309113 2013.01.14 11:52:35                     0

13:29:21 SYS@ORCL:1>

Moved the archive log seq 13 (which was the seq# when guaranteed restore point was created)to the archive log destination and tried flashback

13:57:35 SYS@ORCL:1>  flashback database to restore point test_anand;

Flashback complete.

13:58:02 SYS@ORCL:1>

Alert log shows —

Mon Jan 14 13:57:54 2013
 flashback database to restore point test_anand
Flashback Restore Start
Flashback Restore Complete
Flashback Media Recovery Start
 started logmerger process
Parallel Media Recovery started with 4 slaves
Flashback Media Recovery Log D:\ORACLE\ARCHIVE\ORCL\ORCL_0001_0000000013_0804355822
Mon Jan 14 13:58:02 2013
Incomplete Recovery applied until change 1297698 time 01/14/2013 11:32:41
Flashback Media Recovery Complete
Completed: flashback database to restore point test_anand
13:58:46 SYS@ORCL:1> select * from V$FLASHBACK_DATABASE_LOG;

OLDEST_FLASHBACK_SCN OLDEST_FLASHBACK_ RETENTION_TARGET FLASHBACK_SIZE ESTIMATED_FLASHBACK_SIZE
-------------------- ----------------- ---------------- -------------- ------------------------
             1297697 14-01-13 11:32:41             1440      104857600                   172032

13:59:07 SYS@ORCL:1> select * from V$FLASHBACK_DATABASE_STAT;

BEGIN_TIME        END_TIME          FLASHBACK_DATA    DB_DATA  REDO_DATA ESTIMATED_FLASHBACK_SIZE
----------------- ----------------- -------------- ---------- ---------- ------------------------
14-01-13 11:53:38 14-01-13 13:59:10          16384   25108480          0                        0

14:00:19 SYS@ORCL:1> select CHECKPOINT_CHANGE#,CHECKPOINT_TIME,UNRECOVERABLE_CHANGE#,UNRECOVERABLE_TIME from v$datafile;

CHECKPOINT_CHANGE# CHECKPOINT_TIME     UNRECOVERABLE_CHANGE# UNRECOVERABLE_TIME
------------------ ------------------- --------------------- -------------------
           1297698 2013.01.14 11:32:41                     0
           1297698 2013.01.14 11:32:41                     0
           1297698 2013.01.14 11:32:41                     0
           1297698 2013.01.14 11:32:41                     0
           1297698 2013.01.14 11:32:41                     0

15:11:28 SYS@ORCL:1> alter database open resetlogs;

Database altered.

15:11:58 SYS@ORCL:1>
15:12:06 SYS@ORCL:1> select username,account_status,default_tablespace,profile from dba_users where username='ANAND';

no rows selected