Extending Flashback Data Archive in 12c

Flashback Data Archive (previously called Total Recall) has been around for a long time now. For those unfamiliar with it, (and by the way, if you are on Enterprise Edition, you should be familiar with it, because its a free feature), here is a very quick primer.

Create a tablespace to hold your history, and create a flashback archive using that space allocation.



SQL> create tablespace SPACE_FOR_ARCHIVE
  2  datafile 'C:\ORACLE\DB11\ARCH_SPACE.DBF' 
  3  size 100M;

Tablespace created.



SQL> CREATE FLASHBACK ARCHIVE longterm
  2  TABLESPACE space_for_archive
  3  RETENTION 1 YEAR;

Flashback archive created.

Then add your tables to the archive. Some tables will be created automatically to support being able to record all of the changes to that table for as long as the archive duration specifies


SQL> ALTER TABLE EMP FLASHBACK ARCHIVE LONGTERM;

Table altered.

SQL> select table_name
  2  from   user_tables
  3  /

TABLE_NAME
---------------------------
SYS_FBA_HIST_71036
SYS_FBA_TCRV_71036
SYS_FBA_DDL_COLMAP_71036
EMP

And then voila! We can track changes to our table over time, well beyond the typical undo_retention setting for the database.


SQL> select empno, ename, job, sal, comm,
  2      nvl(VERSIONS_STARTTIME,LAST_MOD) TS
  3     ,nvl(VERSIONS_OPERATION,'I') op
  4  from EMP
  5  versions between timestamp
  6    timestamp '2014-02-11 20:12:00' and
  7    systimestamp
  8  order by empno;


     EMPNO ENAME      JOB              SAL       COMM TS           O
---------- ---------- --------- ---------- ---------- ------------ -
      7369 SMITH      CLERK            806            08.10.51 PM  I
      7369 SMITH      SALES           8060       1000 08.12.10 PM  U
      7499 ALLEN      SALESMAN        1606  300000000 08.10.51 PM  I
      7521 WARD       SALESMAN        1256  500000000 08.10.51 PM  I
      7566 JONES      MANAGER         2981            08.10.51 PM  I
      ...
      7900 JAMES      CLERK            956            08.10.51 PM  I
      7902 FORD       ANALYST         3006            08.10.51 PM  I
      7934 MILLER     CLERK           1306            08.10.51 PM  I
      7934 MILLER     CLERK           1306            08.12.10 PM  D

But sometimes we want to know more about the history. We want to know who did the change, what machine were they on, etc etc. Auditors tend to be a little snippy about those kind of things Smile

  • You: “I can confirm that the SALARY field was updated at 9:01am on January 25th”
  • Auditor: “And who did that change?”
  • You: “Er….um…..someone”

But it might not be practical to augment all of your tables with WHO, WHEN, WHERE etc columns to capture that information. That might involve a lot of application changes and testing.

If you’re on 12c, you might be in luck. Flashback Data Archive can capture additional information, assuming your application is taking advantage of the myriad of instrumentation facilities offered by the database.

We simply turn on context tracking, which can capture information on a per transaction basis


SQL> begin
  2    dbms_flashback_archive.set_context_level(
  3        level=> 'ALL');
  4  end;

PL/SQL procedure successfully completed.

Now when we perform changes to the table, we can look at the transaction ID (XID) for that change.


SQL> update EMP
  2  set    sal = sal*10
  3  where  empno = 7499;

1 row updated.

SQL> commit;


SQL> select XID from SYS_FBA_HIST_510592;

XID
----------------
09000B00C7080000

And using that XID, we can pick up the context information about that transaction


SQL> set serverout on
SQL> begin
  2    dbms_output.put_line(
  3      dbms_flashback_archive.get_sys_context (
  4         '09000B00C7080000', 'USERENV', 'SESSION_USER'));
  5
  6    dbms_output.put_line(
  7      dbms_flashback_archive.get_sys_context (
  8         '09000B00C7080000', 'USERENV', 'HOST'));
  9
 10    dbms_output.put_line(
 11      dbms_flashback_archive.get_sys_context (
 12         '09000B00C7080000', 'USERENV', 'MODULE'));
 13  end;
 14  /
SCOTT
WORKGROUP\XPS
SQL*Plus

How much more ? Well, quite a lot actually !


SQL> desc SYS.SYS_FBA_CONTEXT_AUD

 Name                      Null?    Type
 ------------------------- -------- ------------------
 XID                                RAW(8)
 ACTION                             VARCHAR2(256)
 AUTHENTICATED_IDENTITY             VARCHAR2(256)
 CLIENT_IDENTIFIER                  VARCHAR2(256)
 CLIENT_INFO                        VARCHAR2(256)
 CURRENT_EDITION_NAME               VARCHAR2(256)
 CURRENT_SCHEMA                     VARCHAR2(256)
 CURRENT_USER                       VARCHAR2(256)
 DATABASE_ROLE                      VARCHAR2(256)
 DB_NAME                            VARCHAR2(256)
 GLOBAL_UID                         VARCHAR2(256)
 HOST                               VARCHAR2(256)
 IDENTIFICATION_TYPE                VARCHAR2(256)
 INSTANCE_NAME                      VARCHAR2(256)
 IP_ADDRESS                         VARCHAR2(256)
 MODULE                             VARCHAR2(256)
 OS_USER                            VARCHAR2(256)
 SERVER_HOST                        VARCHAR2(256)
 SERVICE_NAME                       VARCHAR2(256)
 SESSION_EDITION_NAME               VARCHAR2(256)
 SESSION_USER                       VARCHAR2(256)
 SESSION_USERID                     VARCHAR2(256)
 SESSIONID                          VARCHAR2(256)
 TERMINAL                           VARCHAR2(256)
 SPARE                              VARCHAR2(256)

And since we can use our flashback query syntax to pick up all of the transaction ID’s


SQL> select empno, ename, job, sal, comm,
  2      VERSIONS_XID
  3  from EMP
  4  versions between timestamp
  5    timestamp '2014-02-11 20:12:00' and
  6    systimestamp
  7  order by empno;

     EMPNO ENAME      JOB              SAL       COMM VERSIONS_XID
---------- ---------- --------- ---------- ---------- ----------------
      7369 SMITH      CLERK            806
      7369 SMITH      SALES           8060       1000 09001C00E04A0000
      7499 ALLEN      CLERK          16060  300000000 0A000A0024080000
      7499 ALLEN      SALESMAN       16060  300000000 09000B00C7080000
      7499 ALLEN      SALESMAN        1606  300000000
      7521 WARD       SALESMAN        1256  500000000

we can also take advantage of that new dictionary view SYS.SYS_FBA_CONTEXT_AUD to get all the context information for each transaction.


SQL> select ...
  2  from
  3  (  select
  4         empno, ename, job,
  5         sal, comm, VERSIONS_XID
  6     from EMP
  7     versions between timestamp
  8        timestamp '2014-02-11 20:12:00' and
  9        systimestamp
 10  ) e, SYS.SYS_FBA_CONTEXT_AUD  a
 11  where e.VERSIONS_XID = a.XID;

Flashback Data Archive is pretty nifty in 12c.

https://docs.oracle.com/database/121/ADFNS/adfns_flashback.htm#ADFNS01011

ORA-65131 grrrr

So…the future is container databases ?

Cool ! I’ll create all my databases as container databases….I’m so happy….until

SQL> CREATE FLASHBACK ARCHIVE longterm TABLESPACE demo RETENTION 1 MONTH;
CREATE FLASHBACK ARCHIVE longterm TABLESPACE demo RETENTION 1 MONTH
*
ERROR at line 1:
ORA-65131: The feature Flashback Data Archive  is not supported in a pluggable database.

It is documented but seriously….that’s not so flash 🙂

Lob CACHE vs NOCACHE – impact on flashback logging

I was doing some work for a client, and LOB processing seemed incredibly slow. After some poking around, it appears that LOB processing is quite sensitive when it comes to flashback mode in the database. Test bench is a simple table with three clobs. 4kb will be insert into each clob in 5000 individual inserts. The “wait” option is applied to the commit to ensure that the standard PLSQL commit optimizations do not come into play.

Database is 11.2.0.1 running in flashback mode.

SQL> create table t_nocache ( x1 clob, x2 clob, x3 clob )
  2    lob ( x1 ) store as ( nocache )
  3    lob ( x2 ) store as ( nocache )
  4    lob ( x3 ) store as ( nocache )
  5    ;

Table created.

SQL> set timing on
SQL> begin
  2  for i in 1 .. 5000 loop
  3    insert into t_nocache values (rpad('x',4000,'x'),rpad('x',4000,'x'),rpad('x',4000,'x'));
  4    commit WRITE WAIT IMMEDIATE;
  5  end loop;
  6  end;
  7  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:13.21

So for NOCACHE, the elapsed time is 13 seconds, and then we can inspect where the time was lost:

SQL> @sessev
Sid required: 17

EVENT                                        TOTAL_WAITS TOTAL_TIMEOUTS       SECS PCT        MAX_WAIT
-------------------------------------------- ----------- -------------- ---------- -------- ----------
Data file init write                                   2              0          0 00.00%            0
events in waitclass Other                              2              0          0 00.00%            0
db file single write                                   2              0          0 00.00%            0
control file parallel write                           14              0          0 00.00%            0
CPU                                                                              0 00.00%            0
log file switch (checkpoint incomplete)                2              0        .01 00.11%            1
log file switch completion                             3              0        .01 00.11%            0
control file sequential read                          70              0        .01 00.11%            0
Disk file operations I/O                              11              0        .04 00.44%            1
db file sequential read                              563              0        .13 01.44%            2
buffer busy waits                                      1              0        .25 02.77%           25
direct path write                                  14996              0       1.19 13.16%            2
log file sync                                       4999              0       1.82 20.13%            7
direct path read                                   14865              0       2.24 24.78%            4
flashback log file sync                            14999              0       3.34 36.95%            9

15 rows selected.

SQL> select * from V$FLASHBACK_DATABASE_STAT;

BEGIN_TIME           END_TIME             FLASHBACK_DATA    DB_DATA  REDO_DATA ESTIMATED_FLASHBACK_SIZE
-------------------- -------------------- -------------- ---------- ---------- ------------------------
05-feb-2013 15:37:02 05-feb-2013 15:42:06      125911040  126820352  136450048                        0

Test 1 – CACHE lob

SQL> create table t_cache ( x1 clob, x2 clob, x3 clob )
  2    lob ( x1 ) store as ( cache )
  3    lob ( x2 ) store as ( cache )
  4    lob ( x3 ) store as ( cache )
  5    ;

SQL> set timing on
SQL> begin
  2  for i in 1 .. 5000 loop
  3    insert into t_cache values (rpad('x',4000,'x'),rpad('x',4000,'x'),rpad('x',4000,'x'));
  4    commit WRITE WAIT IMMEDIATE;
  5  end loop;
  6  end;
  7  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:07.89

So for CACHE, the elapsed time is 8 seconds, and then we can inspect where the time was lost:

SQL> @sessev
Sid required: 17

EVENT                                        TOTAL_WAITS TOTAL_TIMEOUTS       SECS PCT        MAX_WAIT
-------------------------------------------- ----------- -------------- ---------- -------- ----------
Data file init write                                   1              0          0 00.00%            0
control file sequential read                          35              0          0 00.00%            0
control file parallel write                            7              0          0 00.00%            0
events in waitclass Other                              1              0          0 00.00%            0
flashback log file sync                                1              0          0 00.00%            0
CPU                                                                              0 00.00%            0
db file single write                                   1              0          0 00.00%            0
Disk file operations I/O                               8              0        .02 00.38%            1
log file switch completion                             1              0         .1 01.88%           10
buffer busy waits                                      1              0        .25 04.71%           25
log file switch (checkpoint incomplete)                2              0        .45 08.47%           45
log file sync                                       4998              0       1.24 23.35%            6
db file sequential read                             7136              0       1.24 23.35%            4
db file scattered read                              8415              0       2.01 37.85%            2

14 rows selected.

There is an increase in scattered read (ie, bringing blocks into the cache) but the flashback log sync wait has vanished.

SQL> select * from V$FLASHBACK_DATABASE_STAT;

BEGIN_TIME           END_TIME             FLASHBACK_DATA    DB_DATA  REDO_DATA ESTIMATED_FLASHBACK_SIZE
-------------------- -------------------- -------------- ---------- ---------- ------------------------
05-feb-2013 15:37:02 05-feb-2013 15:44:18      128581632  129851392  208777728                        0

Flashback log size growth is minimal (ie it was already 125MB from the previous test, and had grown to 128M). Presumably as the flashback process kicks in from time to time in background, this would be expected to grow, but it is no longer synchronous to the foreground process.