Friday, September 25, 2015

SQL DML Exceptions, Rollbacks and PL/SQL Exception Handlers

When SQL DML statements hit runtime errors, Oracle rollbacks only the last DML statement, which caused the error. PL/SQL exception handling can make use of this behavior to save the not rollbacked work and keep the application continue running. Oracle is optimized to rollback the entire transaction if there is only one single DML statement inside the transaction.

Oracle "Database PL/SQL Language Reference" Section: "Retrying Transactions After Handling Exceptions" said:

   To retry a transaction after handling an exception that it raised, use this technique:
    ......
   If the transaction fails, control transfers to the exception-handling part of the sub-block, and after the exception handler runs, the loop repeats.

which interprets the exception-handling as Transaction-Level. Over there the example contains two DML statements (delete and insert), and rollback is controlled by a savepoint.

At first pick the test code from Book Oracle PL/SQL Programming (5th edition, Steven Feuerstein) Chapter 14: Section: DML and Exception Handling (Page 446), and add some extra lines:
   
drop table books;

create table books (book_id integer);

create or replace function tabcount return pls_integer is
   l_return pls_integer;
begin
   select count (*) into l_return from books;
   return l_return;
end tabcount;
/

create or replace procedure empty_library (pre_empty_count out pls_integer) is
begin
   pre_empty_count := tabcount ();
   dbms_output.put_line ('empty_library pre_empty_count='||pre_empty_count);
   dbms_output.put_line ('empty_library tabcount S1='||tabcount());
   delete from books where book_id=1;
   dbms_output.put_line ('empty_library tabcount S2='||tabcount());
   raise no_data_found;
end;
/

Run first test with Exception Handler:

set serveroutput on;

truncate table books;

declare
  table_count number := -1;
begin
  insert into books (book_id) values (1);
  insert into books (book_id) values (2);
  dbms_output.put_line ('tabcount S1='||tabcount());
  empty_library (table_count);
  exception when others then
    dbms_output.put_line ('tabcount S2='||tabcount());
    dbms_output.put_line ('table_count S3='||table_count);
end;
/

select * from books;

The output looks like:

tabcount S1=2
empty_library pre_empty_count=2
empty_library tabcount S1=2
empty_library tabcount S2=1
tabcount S2=1
table_count S3=-1

SQL> select * from books;
   BOOK_ID
----------
         2   

Run another test without Exception Handler:

set serveroutput on;

truncate table books;

declare
  table_count number := -1;
begin
  insert into books (book_id) values (1);
  insert into books (book_id) values (2);
  dbms_output.put_line ('tabcount S1='||tabcount());
  empty_library (table_count);
end;
/

select * from books;

The output is:

tabcount S1=2
empty_library pre_empty_count=2
empty_library tabcount S1=2
empty_library tabcount S2=1
ORA-01403: no data found
ORA-06512: at "K.EMPTY_LIBRARY", line 8

SQL> select * from books;
no rows selected  

Reading text in Page 446:

  When an exception occurs in a PL/SQL block, the Oracle database does not roll back
  any of the changes made by DML statements in that block.


and Page 447:

  If an exception propagates past the outermost block (i.e., it goes “unhandled”),
  then in most host execution environments for PL/SQL like SQL*Plus, a rollback is
  automatically executed, reversing any outstanding changes.


Crosschecking above two tests, we can see SQL*Plus does not roll back if there is an error handler,
and does a rollback to the beginning of block if there is no error handler (Unhandled Exceptions).

Relevant information can also be found in Page 145 about Unhandled Exceptions:

  If an exception is raised in your program, and it is not handled by an exception section
  in either the current or enclosing PL/SQL blocks, that exception is unhandled. PL/SQL
  returns the error that raised the unhandled exception all the way back to the application
  environment from which PL/SQL was run. That environment (a tool like SQL*Plus,
  Oracle Forms, or a Java program) then takes an action appropriate to the situation; in
  the case of SQL*Plus, a ROLLBACK of any DML changes from within that top-level
  block’s logic is automatically performed.


and Page 137,

  When this procedure(RAISE_APPLICATION_ERROR) is run, execution of the current PL/SQL block halts immediately,
  and any changes made to OUT or IN OUT arguments (if present and without the NOCOPY hint) will be reversed.

Book Expert Oracle Database Architecture (3rd Edition, Thomas Kyte, Darl Kuhn) - Chapter 8, Section: Atomicity (Page 277-283) explains the principle of Statement-Level Atomicity, and mimicks the work Oracle normally does with the SAVEPOINT:

 Savepoint sp;
 statement;
 If error then rollback to sp;


It further shows that Oracle considers Procedure-Level Atomicity (PL/SQL anonymous blocks) to be statements as well.

This Blog will try to show how to apply above principle to PL/SQL blocks with Exception Handlers in order to keep application not interrupted.

We will run 5 test cases to demonstrate such rollbacks in Statement-Level. When error occurs, it is not "transaction fails", but only "statement fails".

All Testcode is appended at the end of Blog.

1. undo_tbs_test_1


Run following code:

  set serveroutput on lines=200
  select n.name, s.value from v$mystat s, v$statname n
  where s.statistic#=n.statistic#
    and name in ('user commits', 'transaction rollbacks', 'rollback changes - undo records applied');
  select id, ts, step from test_t1 where id <= 2;

  exec undo_tbs_test_1;

  select n.name, s.value from v$mystat s, v$statname n
  where s.statistic#=n.statistic#
    and name in ('user commits', 'transaction rollbacks', 'rollback changes - undo records applied');
  select id, ts, step from test_t1 where id <= 2;


The output look as follows:

  NAME                                             VALUE
  ------------------------------------------- ----------
  user commits                                       685
  rollback changes - undo records applied         147854
  transaction rollbacks                              126

  ID TS                                     STEP
  -- -------------------------------- ----------
   1 22-SEP-2015 07:15:01                      0
   2 22-SEP-2015 07:15:01                      0

  ORA-30036: unable to extend segment by 8 in undo tablespace 'TEMPUNDO', at Step=1
  ORA-30036: unable to extend segment by 8 in undo tablespace 'TEMPUNDO', at Step=2
  ORA-30036: unable to extend segment by 8 in undo tablespace 'TEMPUNDO', at Step=3
  End committed, at Step=4

  NAME                                            VALUE
  ------------------------------------------ ----------
  user commits                                      685
  rollback changes - undo records applied        151098
  transaction rollbacks                             129

  ID TS                                   STEP
  -- ------------------------------ ----------
   1 22-SEP-2015 07:15:01                    0
   2 22-SEP-2015 07:15:01                    0


we can see 3 (129-126) "transaction rollbacks", and no user commits (685-685), and hence no rows updated.

2. undo_tbs_test_2


Run following code:

  update test_t1 set acc = null;
  commit;
  select n.name, s.value from v$mystat s, v$statname n
  where s.statistic#=n.statistic#
    and name in ('user commits', 'transaction rollbacks', 'rollback changes - undo records applied');
  select count(*) from test_t1 where acc is null;

  exec undo_tbs_test_2;

  select n.name, s.value from v$mystat s, v$statname n
  where s.statistic#=n.statistic#
    and name in ('user commits', 'transaction rollbacks', 'rollback changes - undo records applied');
  select count(*) from test_t1 where acc is null;


The output look as follows:

  NAME                                                    VALUE
  -------------------------------------------------- ----------
  user commits                                              707
  rollback changes - undo records applied                153199
  transaction rollbacks                                     129

  sql%rowcount=50 Updated_1, at Step=1
  ORA-30036: unable to extend segment by 8 in undo tablespace 'TEMPUNDO', at Step=1
  sql%rowcount=50 Updated_1, at Step=2
  ORA-30036: unable to extend segment by 8 in undo tablespace 'TEMPUNDO', at Step=2
  ......
  ORA-30036: unable to extend segment by 8 in undo tablespace 'TEMPUNDO', at Step=18
  sql%rowcount=50 Updated_1, at Step=19
  ORA-30036: unable to extend segment by 8 in undo tablespace 'TEMPUNDO', at Step=19
  sql%rowcount=50 Updated_1, at Step=20
  sql%rowcount=0 Updated_1, at Step=20
  End committed, at Step=20

  NAME                                                    VALUE
  -------------------------------------------------- ----------
  user commits                                              727
  rollback changes - undo records applied                154923
  transaction rollbacks                                     129

  sql> select count(*) from test_t1 where acc is null;
     COUNT(*)
   ----------
            0


we can see 20 user commits (727-707), no "transaction rollbacks" (129-129), and all rows are updated. From application point of view, all the updates are successfully performed, even with a small UNDO Tablespace, which is not met one-run requirement.

This could be used as a workaround in case of UNDO Tablespace is limited.

3. unique_constraint_test_1


Run following code:

  update test_t1 set id = rownum;
  commit;
  select n.name, s.value from v$mystat s, v$statname n
  where s.statistic#=n.statistic#
    and name in ('user commits', 'transaction rollbacks', 'rollback changes - undo records applied');

  exec unique_constraint_test_1;

  select n.name, s.value from v$mystat s, v$statname n
  where s.statistic#=n.statistic#
    and name in ('user commits', 'transaction rollbacks', 'rollback changes - undo records applied');


The output look as follows:

  NAME                                                    VALUE
  -------------------------------------------------- ----------
  user commits                                              728
  rollback changes - undo records applied                154923
  transaction rollbacks                                     129

  ORA-00001: unique constraint (K.TEST_T1_PK) violated, at Step=1
  ORA-00001: unique constraint (K.TEST_T1_PK) violated, at Step=2
  ORA-00001: unique constraint (K.TEST_T1_PK) violated, at Step=3
  End committed, at Step=4

  NAME                                                    VALUE
  -------------------------------------------------- ----------
  user commits                                              728
  rollback changes - undo records applied                157962
  transaction rollbacks                                     132


Again we see 3 (132-129) "transaction rollbacks", and no user commits (728-728), and hence no rows updated.

4. unique_constraint_test_2


Run following code:

 update test_t1 set id = rownum, step = 0, acc = 0;
 commit;
 select id, ts, step, acc from test_t1
  where id in (1, 900, 901, 1000, -1, -900, -901, 1000) order by step, acc, id;
 select n.name, s.value from v$mystat s, v$statname n
 where s.statistic#=n.statistic#
   and name in ('user commits', 'transaction rollbacks', 'rollback changes - undo records applied');

 exec unique_constraint_test_2;

 select n.name, s.value from v$mystat s, v$statname n
 where s.statistic#=n.statistic#
   and name in ('user commits', 'transaction rollbacks', 'rollback changes - undo records applied'); 
 select id, ts, step, acc from test_t1
  where id in (1, 900, 901, 1000, -1, -900, -901, 1000) order by step, acc, id;


The output look as follows:

   ID TS                               STEP     ACC
 ---- -------------------------- ---------- -------
    1 22-SEP-2015 07:35:13                0       0
  900 22-SEP-2015 07:35:13                0       0
  901 22-SEP-2015 07:35:13                0       0
 1000 22-SEP-2015 07:35:13                0       0

 NAME                                           VALUE
 ----------------------------------------- ----------
 user commits                                     742
 rollback changes - undo records applied       163307
 transaction rollbacks                            145

 sql%rowcount=100 Updated_1, at Step=1
 sql%rowcount=100 Updated_1, at Step=1
 sql%rowcount=100 Updated_1, at Step=1
 sql%rowcount=100 Updated_1, at Step=1
 sql%rowcount=100 Updated_1, at Step=1
 sql%rowcount=100 Updated_1, at Step=1
 sql%rowcount=100 Updated_1, at Step=1
 sql%rowcount=100 Updated_1, at Step=1
 sql%rowcount=100 Updated_1, at Step=1
 ORA-00001: unique constraint (K.TEST_T1_PK) violated, at Step=1
 ORA-00001: unique constraint (K.TEST_T1_PK) violated, at Step=2
 ORA-00001: unique constraint (K.TEST_T1_PK) violated, at Step=3
 End committed, at Step=4

 NAME                                          VALUE
 ---------------------------------------- ----------
 user commits                                    743
 rollback changes - undo records applied      164201
 transaction rollbacks                           147

   ID TS                              STEP     ACC
 ---- ------------------------- ---------- -------
  901 22-SEP-2015 07:35:13               0       0
 1000 22-SEP-2015 07:35:13               0       0
   -1 22-SEP-2015 07:35:13               1       1
 -900 22-SEP-2015 07:35:13               1       9


we can see 1 user commits (743-742), 2 "transaction rollbacks" (147-145), 900 rows are updated, 100 rows not updated.

5. deadlock_test


Restore test table:

 column name format a50
 update test_t1 set id = rownum, name = null, acc = 0;

 commit;


Open 3 Sessions, run following 3 scripts in 3 different sessions sequetially at time T1, T2, and T3:

 exec deadlock_s1;  --Session_1_T1

 exec deadlock_s2;  --Session_2_T2

 exec deadlock_s3;  --Session_3_T3


Check the updates by:

 select id, ts, name, acc from test_t1 where id <= 3 order by id; 
 ID TS                         NAME                                ACC
 -- -------------------------- -------------------------------- ----------
  1 22-SEP-2015 07:35:13       Session_1_T1/Session_2_T2/                2
  2 22-SEP-2015 07:35:13       Session_2_T2/                         1
  3 22-SEP-2015 07:35:13       Session_1_T1/Session_3_T3/                2


All Sessions are terminated in about 120 seconds, and Session_1 throws Exeception:
 ORA-00060: deadlock detected while waiting for resource, in Session_1_T1/

Row 1 updated twice (Session_1 and Session_2), Row 3 updated twice (Session_1 and Session_3),
Row 2 updated once (Session_2).

In fact, Row 2 was also updated once by Session_1, but it hit deadlock error, and the update is rollbacked. However, the other two row updates (Row 1 and 3) by Session_1 are still kept, thus committed.

Session_3 is blocked by Session_1, no transaction can be started (see v$transaction).
It will wait till Session_1's transaction terminated.

TestCode


--ensure no transaction alive on TEMPUNDO and all TEMPUNDO'terminated DML's undo_retention expired.
drop tablespace tempundo;


create undo tablespace tempundo
datafile '/testdb/undo/tempundo.dbf'
size 8m reuse autoextend off retention noguarantee
/


alter system set undo_tablespace = tempundo scope=both;
select name, value from v$parameter where name like '%undo%';
drop table test_t1;
create table test_t1
  (id number, ts timestamp default systimestamp, step number, name varchar2(4000), acc number);
alter table test_t1 add constraint test_t1_pk primary key (id);
insert into test_t1 select level, systimestamp, 0, lpad('x', 4000, 'y'), null
  from dual connect by level <= 1000;
commit;
select bytes from dba_segments where segment_name ='TEST_T1';  
--8'388'608

create or replace procedure undo_tbs_test_1 as
  l_step number := 0;
begin
  loop
    begin
      l_step := l_step + 1;
      exit when l_step > 3;  -- limit the number of retries. without it, endless loop.
      update test_t1 set step=l_step, name = lower(name) where id >= 2;
      dbms_output.put_line('sql%rowcount='||sql%rowcount||' Updated_2, at Step='||l_step);
      exit;
    exception when others then
      dbms_output.put_line(sqlerrm||', at Step='||l_step);
      commit;
    end;
  end loop;
  commit;
  dbms_output.put_line('End committed'||', at Step='||l_step);
end;
/


create or replace procedure undo_tbs_test_2 as
  l_step number := 0;
begin
  loop
    begin
      l_step := l_step + 1;
      exit when l_step > 20;
     
      for i in 1..3 loop
        update test_t1 set step=l_step, name = lower(name), acc=rownum

         where acc is null and rownum <=50;
        dbms_output.put_line('sql%rowcount='||sql%rowcount||' Updated_1, at Step='||l_step);
        exit when sql%rowcount=0;
      end loop;
     
      exit;
    exception when others then
      dbms_output.put_line(sqlerrm||', at Step='||l_step);
      commit;
    end;
  end loop;
  commit;
  dbms_output.put_line('End committed'||', at Step='||l_step);
end;
/


create or replace procedure unique_constraint_test_1 as
  l_step number := 0;
begin
  loop
    begin
      l_step := l_step + 1;
      exit when l_step > 3;   -- limit the number of retries. without it, endless loop.
      update test_t1 set id = - mod(id, 998);
      dbms_output.put_line('sql%rowcount='||sql%rowcount||' Updated_1, at Step='||l_step);
      exit;
    exception when others then
      dbms_output.put_line(sqlerrm||', at Step='||l_step);
      commit;
    end;
  end loop;
  commit;
  dbms_output.put_line('End committed'||', at Step='||l_step);
end;
/


create or replace procedure unique_constraint_test_2 as
  l_step number := 0;
begin
  loop
    begin
      l_step := l_step + 1;
      exit when l_step > 3;
     
      for i in 1..10 loop
        update test_t1 set id = - mod(id, 998), step = l_step, acc = i where id > 0 and rownum <=100;
        dbms_output.put_line('sql%rowcount='||sql%rowcount||' Updated_1, at Step='||l_step);
        exit when sql%rowcount=0;
      end loop;
     
      exit;
    exception when others then
      dbms_output.put_line(sqlerrm||', at Step='||l_step);
      commit;
    end;
  end loop;
  commit;
  dbms_output.put_line('End committed'||', at Step='||l_step);
end;
/


create or replace procedure deadlock_s1 as
begin
  update test_t1 set name = name||'Session_1_T1/', acc = acc + 1 where id = 3; 

  -- updated, keep locked till committed
  update test_t1 set name = name||'Session_1_T1/', acc = acc + 1 where id = 1; 

  -- updated, keep locked till committed
  dbms_lock.sleep(60);
  update test_t1 set name = name||'Session_1_T1/', acc = acc + 1 where id = 2; 

  -- rollback due to deadlock
  commit;
exception when others then
  dbms_output.put_line(sqlerrm||', in Session_1_T1/');
  dbms_lock.sleep(60);
  commit; 
end;
/

create or replace procedure deadlock_s2 as
begin
  update test_t1 set name = name||'Session_2_T2/', acc = acc + 1 where id = 2; 

  -- updated, keep locked till committed
  dbms_lock.sleep(60);
  update test_t1 set name = name||'Session_2_T2/', acc = acc + 1 where id = 1; 

  -- updated, keep locked till committed
  commit;
exception when others then
  dbms_output.put_line(sqlerrm||', in Session_2_T2/');
  dbms_lock.sleep(60);
  commit;   
end;
/

create or replace procedure deadlock_s3 as
begin
  update test_t1 set name = name||'Session_3_T3/', acc = acc + 1 where id = 3;  
  -- blocked 120 seconds by Session_1, no transaction started, see v$transaction
  commit;
end;
/

Monday, September 14, 2015

Limit PGA Memory Usage

Following MOS Notes lists 2 measures to control and limit PGA memory usage, but neither are recommended by Oracle. However, the best option is to fix the application.

This Blog is a follow-up of previous Blog: ORA-04030 incident file and alert.log.

1.   Event 10261


Oracle MOS:
    ORA-00600 [723], [67108952], [pga heap] When Event 10261 Set To Limit The PGA Leak (Doc ID 1162423.1)

This event is useful for PGA memory leaks (and UGA if the UGA is in the PGA). The event causes Oracle to raise an ORA-600 if the PGA tries to grow above the specified size.

In pfile/spfile, for example, the below event:
  event = 10261 trace name context forever,level 3145728
enforces a 3.2Gb Gb limit on the PGA size, and replaces the ORA-4030 with an ORA-600 [723] error.

Let's make two tests (see appended Test Code, tested with Oracle 11.2.0.3.0 on AIX):

alter system set event = "10261 trace name context forever,level 3145728" scope=spfile;
    -- DB must be restarted

SQL > exec pga_mem_test.allo(2*1024);
    -- 2GB allocation is OK
SQL > exec pga_mem_test.allo(4*1024);
    -- 4GB allocation throws error
   
ORA-00600: internal error code, arguments: [723], [65520], [top uga heap], [], [], [], [], [], [], [], [], []

Incident Dump shows:

 ORA-00600: internal error code, arguments: [723], [65520], [top uga heap], [], [], [], [], [], [], [], [], []
 
 ========= Dump for incident 16985 (ORA 600 [723]) ========
 ----- Beginning of Customized Incident Dump(s) -----
 ****** ERROR: PGA size limit exceeded in rfg: 3221284184 > 3221225472 *****
 ******************************************************

where the bottom limit is computed as:
   3221225472 = 3145728*1024
Update: In Oracle 19.13, the output looks like:

SQL > exec pga_mem_test.allo(4*1024);
BEGIN pga_mem_test.allo(4*1024); END;

*
ERROR at line 1:
ORA-04068: existing state of packages has been discarded
ORA-10260: PGA limit (3072 MB) exceeded - process terminated
ORA-06512: at "K.PGA_MEM_TEST", line 44
ORA-06512: at line 1

2.   Limit Parameters


Oracle MOS:
   PLSQL Procedure Causing ORA-04030: (pga heap,control file i/o buffer) And ORA-04030:
   (koh-kghu sessi,pmuccst: adt/record) or ORA-04030: (koh-kghucall ,pmucalm coll) Errors (Doc ID 1325100.1)

Either Change the page count (memory map entries per process) limit at the OS level, or adjust realfree heap pagesize at the database level:
Change the page count at the OS level:
     more /proc/sys/vm/max_map_count
  sysctl -w vm.max_map_count=262144 (for example)


Adjust the realfree heap pagesize within the database by setting the following parameters in the init/spfile and restart the database.

For versions 11.2.0.4 and lower:
  _use_realfree_heap=TRUE
  _realfree_heap_pagesize_hint = 262144

For 12.1 and higher:
  _use_realfree_heap=TRUE
  _realfree_heap_pagesize = 262144

As a test with Oracle 11.2.0.4.0 on Linux with following configuration:

Linux$ cat /proc/sys/vm/max_map_count
65530
 
Linux$ > free -mt
             total       used       free     shared    buffers     cached
Mem:         24160       5571      18588       1761        131       4257
-/+ buffers/cache:       1183      22977
Swap:            0          0          0
Total:       24160       5571      18588

The system has 24GB physical memory, and database SGA is 4GB.

At first, limit PGA per Session to 65530*4K = 256M

SQL > alter system set "_realfree_heap_pagesize_hint"=4K scope=spfile;
   -- restart DB
SQL > exec pga_mem_test.allo(1024); 

the incident dump shows:      

Dump of Real-Free Memory Allocator Heap [0x7fd64003a000]
mag=0xfefe0001 flg=0x5000003 fds=0x6 blksz=4096
blkdstbl=0x7fd64003a010, iniblk=331776 maxblk=524288 numsegs=71
In-use num=65353 siz=1335451648, Freeable num=32 siz=155648, Free num=113 siz=2225766
...
******************* Dumping process map ****************
...
7f455e47e000-7f455e483000 rw-p 00000000 00:05 4219                       /dev/zero
...
 
where blksz=4096.

However, siz/num=1335451648/65353=20434, it means that average pagesize is about 20 instead of specified 4k.
The entries in process map also confirmed it:
 7f455e47e000-7f455e483000
is decimal:
 139935911239680-139935911260160
i.e 20k.

Then, increase PGA per Session limit to 65530*256K = 16G

SQL > alter system set "_realfree_heap_pagesize_hint"=256K scope=spfile;
   -- restart DB

Open 3 Sqlplus sessions, at first session, run:

SQL(162,55) > exec pga_mem_test.allo(1024*13, 120);

Wait 5 seconds, at second session, run query:

SQL(84,59) > set numformat 99,999,999,999
SQL(84,59) > select s.sid, s.program, p.pga_used_mem, p.pga_alloc_mem 
               from v$session s, v$process p
              where s.paddr=p.addr and p.pga_used_mem >1e9;

 SID PROGRAM        PGA_USED_MEM   PGA_ALLOC_MEM
---- ----------- --------------- ---------------
 162 sqlplus.exe  15,957,853,158  15,959,926,406

At third session, run:

SQL(242,559) > exec pga_mem_test.allo(1024*13, 120);

Wait 5 seconds, at second session, run again the query:

SQL(84,59) > select s.sid, s.program, p.pga_used_mem, p.pga_alloc_mem 
               from v$session s, v$process p
              where s.paddr=p.addr and p.pga_used_mem >1e9;
 
 SID PROGRAM        PGA_USED_MEM   PGA_ALLOC_MEM
---- ----------- --------------- ---------------
 242 sqlplus.exe  15,957,853,158  15,959,926,406 

Look again first session:

SQL(162,55) > exec pga_mem_test.allo(1024*13, 120);
ERROR:
ORA-03114: not connected to ORACLE
BEGIN pga_mem_test.allo(1024*13, 120); END;
ERROR at line 1:
ORA-03113: end-of-file on communication channel
Process ID: 19710
Session ID: 162 Serial number: 55

Checking Oracle alert.log, trace, and incident files, there are nothing about the disconnected 1st session (Process ID: 19710, Session ID: 162 Serial number: 55).

Resorting to Linux dmesg, we can see:

[12:15:20] oracle invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0, oom_score_adj=0
[12:15:20] oracle cpuset=/ mems_allowed=0
[12:15:20] Pid: 19555, comm: oracle Not tainted 2.6.32-642.el6.x86_64 #1  <--- Pid: 19555 PMON
[12:15:20] Call Trace:
[12:15:20] [<ffffffff81131640>] ? dump_header+0x90/0x1b0
[12:15:20] [<ffffffff8123c20c>] ? security_real_capable_noaudit+0x3c/0x70
[12:15:20] [<ffffffff81131ac2>] ? oom_kill_process+0x82/0x2a0
[12:15:20] [<ffffffff81131a01>] ? select_bad_process+0xe1/0x120
[12:15:20] [<ffffffff81131f00>] ? out_of_memory+0x220/0x3c0
[12:15:20] [<ffffffff8113e8dc>] ? __alloc_pages_nodemask+0x93c/0x950
[12:15:20] [<ffffffff81177b2a>] ? alloc_pages_current+0xaa/0x110
[12:15:20] [<ffffffff8112ea37>] ? __page_cache_alloc+0x87/0x90
[12:15:20] [<ffffffff8112e41e>] ? find_get_page+0x1e/0xa0
[12:15:20] [<ffffffff8112f9d7>] ? filemap_fault+0x1a7/0x500
[12:15:20] [<ffffffff81159394>] ? __do_fault+0x54/0x530
[12:15:20] [<ffffffff81159967>] ? handle_pte_fault+0xf7/0xb20
[12:15:20] [<ffffffff8122959c>] ? sem_lock+0x6c/0x130
[12:15:20] [<ffffffff8122b298>] ? sys_semtimedop+0x338/0xae0
[12:15:20] [<ffffffff8115a629>] ? handle_mm_fault+0x299/0x3d0
[12:15:20] [<ffffffff8100bc0e>] ? apic_timer_interrupt+0xe/0x20
[12:15:20] [<ffffffff81052156>] ? __do_page_fault+0x146/0x500
[12:15:20] [<ffffffff810688ed>] ? thread_group_times+0x3d/0x120
[12:15:20] [<ffffffff81079b8e>] ? mmput+0x1e/0x120
[12:15:20] [<ffffffff8109c348>] ? getrusage+0x158/0x340
[12:15:20] [<ffffffff8154dbce>] ? do_page_fault+0x3e/0xa0
[12:15:20] [<ffffffff8154aed5>] ? page_fault+0x25/0x30
...
[12:15:20] [ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
[12:15:20] [19555]   100 19555  1168551      871   0       0             0 oracle  <--- PMON
...
[12:15:20] [19710]   100 19710  5072861  3995279   0       0             0 oracle  <--- 1st session
[12:15:20] [19713]   100 19713  2974770  1866502   5       0             0 oracle  <--- 3rd session
[12:15:20] [19715]   100 19715  1171449    60050   4       0             0 oracle  <--- 2nd session
...
[12:15:20] Out of memory: Kill process 19710 (oracle) score 647 or sacrifice child
[12:15:20] Killed process 19710, UID 100, (oracle) total-vm:20291444kB, anon-rss:15600524kB, file-rss:380592kB
The above log shows that Oracle PMON(19555) calls oom_kill_process() to kill one memory offending process(19710) to satisfy the request of the new process(19713).

process 19710 is killed due to badness score 647:
  Out of memory: Kill process 19710 (oracle) score 647 or sacrifice child

The baseline for the badness score is the proportion of RAM that each task's rss, pagetable and swap space use.

In Linux oom_kill.c, out_of_memory() calls select_bad_process() to find processes to be killed.
  If found, kill by oom_kill_process().
  If not found, panic the system (halt the system, never return) by:
     panic("Out of memory and no killable processes...\n");

and it is emphasized by the comment:

  out_of_memory - kill the "best" process when we run out of memory
  Found nothing?!?! Either we hang forever, or we panic.

The hidden parameter _pga_max_size does not limit a process size, only the work area.

3.   12c PGA_AGGREGATE_LIMIT


Oracle MOS:
   Doc ID 1520324.1: Limiting process size with database parameter PGA_AGGREGATE_LIMIT

While PGA_AGGREGATE_TARGET only controls allocations of tunable memory, PGA_AGGREGATE_LIMIT aborts or terminates the sessions or processes that are consuming the most untunable PGA memory, such as:
     pl/sql memory areas
  session context, cursor caches (MOS Doc ID 284951.1).

This new initialization parameter dynamically sets an instance-wide hard limit for PGA memory.

If the value of PGA_AGGREGATE_LIMIT is reached, a 12c new error message will be reported:
  ORA-04036: PGA memory used by the instance exceeds PGA_AGGREGATE_LIMIT

4.  PGA Memory Components


Blog TUNING PGA : PART – I (Anju Garg) classified PGA in functions, and by tunability:

PGA components:
    Stack space
        bind variables
        arrays (PL/SQL)
   UGA
        Session information such as logon information, and other information required by a database Session.
        SQL Work areas : used for sorting, hash operations etc.
        Private SQL Area : contains Open/Closed cursors and cursor state information for open cursors for example, 
                                        the number of rows retrieved so far in a full table scan.

PGA areas:
    Untunable PGA
         Context information of each session
         Each open cursor
         PL/SQL, OLAP or Java memory
   Tunable PGA
         SQL work areas

5.  PGA Overallocation vs. tunable and non-tunable areas


Oracle MOS: LOW PGA HIT RATIO THOUGH OVER ALLOCATION COUNT IS NONE (Doc ID 284951.1) said:

 Over-allocating PGA memory can happen if the value of PGA_AGGREGATE_TARGET is too small to accommodate the PGA component un tunable (session context, cursor caches, etc) memory plus the minimum memory required to execute the work area workload. When this happens, Oracle cannot honor the initialization parameter PGA_AGGREGATE_TARGET, and extra PGA memory needs to be allocated.
 
The number of times Oracle had to allocate more PGA memory then the PGA_AGGREGATE_TARGET suggested. This indicates the PGA target was set too small to accommodate the un tunable (session context, cursor caches, etc) memory plus the tunable component. This count should be zero ideally.

Oracle MOS: How To Avoid ORA-04030/ORA-12500 In 32-bit Windows Environment [Video] (Doc ID 373602.1) wrote:

 Within the PGA we have "tunable" and "non-tunable" areas. The tunable part is memory allocated for intensive SQL operations such as sorts, hash-joins, bitmap merge, and bitmap index create. This memory can be shrunk and expanded in response to system load. However, the non-tunable part cannot be managed in the same way. Importantly the non-tunable part includes cursors. We can control the number of cursors by the init.ora OPEN_CURSORS parameter, but if this is exceeded we get an ORA-1000 error, which is clearly undesirable. See unpublished Note:1012266.6 - "Overview of ORA-1000 Maximum Number of Cursors Exceeded" for more info. More importantly, however, we have no control over the size of a cursor, and users may open very large cursors dependent on their SQL or PLSQL.
 
 Also note that if we set PGA_AGGREGATE_TARGET too small to accommodate the non-tunable part of the PGA plus the minimum memory required to execute the tunable part, then Oracle cannot honour the PGA_AGGREGATE_TARGET value, and will attempt to allocate extra memory. This is known as overallocation, and an estimation of this can be seen in the view V$PGA_TARGET_ADVICE under the column ESTD_OVERALLOC_COUNT.

PGA memory is divided as tunable and non-tunable areas, while tunable is constrained under PGA_AGGREGATE_TARGET, non-tunable can be over allocated in any size (till ORA-04030), and Oracle records these activities in column ESTD_OVERALLOC_COUNT of V$PGA_TARGET_ADVICE. Therefore ESTD_OVERALLOC_COUNT is caused by over request of non-tunable areas.

Before each overallocation, probably Oracle tries to deallocate certain less used memory (for example, LRU Algorithm) at first. If not satisfied, new memory is allocated.

OPEN_CURSORS specifies the maximum number of open cursors (handles to private SQL areas) a session can have at once. Under overallocation, session cursor caches could be subject to memory deallocation.

In Oracle, each child cursor is associated with one KGLH0 and one SQLA (both in SGA), where KGLH0 stores environment information, SQLA stores parsing tree and xplan. When memory is reclaimed, KGLH0 stays, whereas SQLA is deallocated.

Once child cursor is cleaned out from session cursor caches, and no more found in SQLA. The later re-use of the same child cursor will result in a hard-parsing, and normally Oracle SQL Trace shows it as:

     Misses in library cache during parse:   0
    Misses in library cache during execute: 1


Probably the parsing "during execute" is a quick parsing with less optimization compared to “during parse”, for example, limiting "_optimizer_max_permutations" to a small number, so that it could be faster and not disturb too much execution phase. But in the negative side, it could be that it would not find the optimal xplan.

We have observed such sub-optimal xplan generated in "during execute" phase, but in general we don't know how to determine if an xplan is created "during parse" or "during execute".

In order to fix such sub-optimal xplan generated in "during execute" phase, PGA_AGGREGATE_TARGET is increased to avoid PGA overallocation, and at the same time, the SQL statement is manipulated to be different so that it is forced to be hard parsed from scratch.

The problem sql involves partitions of a partitioned table, in which all partitions are unbalanced (some of them almost empty). Hence the pure sql with partition key is hardly optimal for each partition select. So we try to put some dummy hint with partition key to prevent cursor sharing (this sounds counterproductive). Since the sql is heavy, and at one time period, only a few partitions are selected, this paid off seems justified.

Since the problem occurs when upgrade to 11.2.0.4 and much more "Parse Calls" than "Executions" are found in AWR report, probably we hit:
     Oracle MOS: ORA-04030 occurred while executing PLSQL procedure (Doc ID 1953999.1)
which is supposed to be fixed by interim Patch 18384537:
     OPIPLS TAKES TOO MANY RETRIES TO LOAD CURSOR.

In summary, the above discussion reveals one aspect of cooperative work between SGA and PGA. Here we are trying to bring two commonly regarded independent components together.

Test Code



create or replace package pga_mem_test as
  procedure allo (p_mb int, p_sleep number := 0);
end;
/

create or replace package body pga_mem_test as
  type t_tab_kb   is table of char(1024);   -- 1KB
  p_tab_1mb          t_tab_kb := t_tab_kb();
  type t_tab_mb   is table of t_tab_kb;     
  p_tab_mb           t_tab_mb := t_tab_mb();
  p_sid              number;  --   := sys.dbms_support.mysid;
  
  -------------------------------------------
  procedure rpt(l_name varchar) is
     l_v$process_mem            varchar2(4000);
     l_v$process_memory_mem     varchar2(4000);
  begin
   select 'Used/Alloc/Freeable/Max >>> '||
           round(pga_used_mem/1024/1024)    ||'/'||round(pga_alloc_mem/1024/1024)||'/'||
             round(pga_freeable_mem/1024/1024)||'/'||round(pga_max_mem/1024/1024)
       into l_v$process_mem
       from v$process 
       where addr = (select paddr from v$session where sid = p_sid);
      
    select 'Category(Alloc/Used/Max) >>> '||
             listagg(Category||'('||round(allocated/1024/1024)||'/'||
                     round(used/1024/1024)||'/'||round(max_allocated/1024/1024)||') > ')
     within group (order by Category desc) name_usage_list
       into l_v$process_memory_mem
       from v$process_memory
       where pid = (select pid from v$process
                     where addr = (select paddr from v$session where sid = p_sid));
  
    dbms_output.put_line(rpad(l_name, 20)||' > '||rpad(l_v$process_mem, 50));
    dbms_output.put_line('             ------ '||l_v$process_memory_mem);
  end rpt;
   
  -------------------------------------------   
  procedure allo (p_mb int, p_sleep number) is
  begin
   select sid into p_sid from v$mystat s where rownum <=1;
   
   rpt('Start allocate: '||p_mb||' MB');
   
   select 'M' bulk collect into p_tab_1mb from dual connect by level <= 1024;  -- 1MB
   
   for i in 1..p_mb loop   -- p_mb MB
    p_tab_mb.extend;
    p_tab_mb(i) := p_tab_1mb;
   end loop;
  
   rpt('End allocate: '||p_mb||' MB');
   dbms_lock.sleep(p_sleep);
  end allo;
  
end;
/

/*
   exec dbms_session.reset_package;
   set  serveroutput on
   exec pga_mem_test.allo(1024*1, 30);       -- allocate 1GB
*/

------------------------------------------- 
create or replace procedure pga_mem_test_jobs(p_job_cnt number, p_mb number, p_sleep number := 0)
as
   l_job_id pls_integer;
begin
    for i in 1.. p_job_cnt loop
      dbms_job.submit(l_job_id, 'begin pga_mem_test.allo('||p_mb||', '||p_sleep||'); end;');
    end loop;
    commit;
end;    
/

--exec pga_mem_test_jobs(4, 1024*2, 60);   -- 4 Jobs, each allocates 2 GB, sleeping 60 seconds

Thursday, August 27, 2015

Latch _SPIN_COUNT: adaptive

The pseudo-code in Page 241 of Expert Oracle Database Architecture(3rd Edition) - Section: Latch "Spinning" shows that each latch sleep occurs after 2000 Get Requests. According to that program logic, query:

select snap_id, latch_name, gets, misses, sleeps, spin_gets, wait_time
      ,round(gets/sleeps)               gets_per_sleep
      ,((sleeps + spin_gets) - misses)  delta
      ,round(wait_time/sleeps)          wait_time_per_sleep
from
  (select snap_id, latch_name
         ,gets - lag(gets) over (partition by latch_name order by snap_id) gets
         ,misses - lag(misses) over (partition by latch_name order by snap_id) misses
         ,sleeps - lag(sleeps) over (partition by latch_name order by snap_id) sleeps
         ,spin_gets - lag(spin_gets) over (partition by latch_name order by snap_id) spin_gets
         ,wait_time - lag(wait_time) over (partition by latch_name order by snap_id) wait_time
   from   dba_hist_latch
   where latch_name = 'shared pool'
  )
where sleeps > 0
order by snap_id, latch_name;


should return gets_per_sleep >= 2000.

(Column delta is discussed in Blog: Is latch misses statistic gathered or deduced ?)

However running the test code "instest.java.NOBIND" provided by the Book, we observe rows whose value is around 200, much less than 2000 for "latch: shared pool", and also rows with value bigger than 20,000.

 Latch Name     Requests  Misses  Sleeps  Gets (Spin Gets)
 -------------- --------  ------- ------- ----------------
 shared pool    2,296,041 75,240  15,267  60,165


confirms the above observation:

 gets_per_sleep = 2,296,041 / 15,267         = 150
 delta          = (15,267 + 60,165) - 75,240 = 192


The pattern seems that gets_per_sleep decreases when hard parsing increases.

It looks like that Oracle tends to make performance more and more adaptive, in my humble opinion, called system self-tuning or self-learning. Probably it uses some Adaptive Control method, which adapts "_SPIN_COUNT" based on feedback of latches' workload.

MOS Note (Doc ID 1970450.1) on "_SPIN_COUNT" (amount to spin waiting for a latch) said:

The default value of the parameter is automatically adjusted when the machine's CPU count changes provided that the default was used. If the parameter was explicitly set, then there is no change. It is not usually recommended to change the default value for this parameter.

If after this entire loop, the latch is still not available, the process must yield the CPU and go to sleep. Initially, it sleeps for one centisecond. This time is doubled in every subsequent sleep.

gets_per_sleep < 2000 could also indicate that internally Oracle halves (or reduce) "_SPIN_COUNT" when it doubles sleep time.

2000 is the default value of "_SPIN_COUNT".

Changing it by:
 alter system set "_SPIN_COUNT"=4000;
seems no influence on the above latch statistics.

Wednesday, July 8, 2015

Redo Practice

Although "Undo is more complicated than redo" (Oracle Core: Essential Internals for DBAs and Developers), Redo performance is more visible to applications. End user is affected by "log file sync", while DBA is googling Panacea of "log file parallel write". It travels through all layers of computer system, from applications, Oracle, OS (Scheduler, VM, FS), adapter, down to disk (LUNS, RAID) and network.

Following previous Blog: "UNDO Practice", it is time to do the second exercise in sticking to:
"The Beginners' Guide to Becoming an Oracle Expert" (Page 5).

All tests are done in Oracle 11.2.0.4.0 (see appended Test Code).

1. Asynchronous Commit


The default PL/SQL commit behavior for nondistributed transactions is BATCH NOWAIT if the COMMIT_LOGGING and COMMIT_WAIT database initialization parameters have not been set (Database PL/SQL Language Reference).

Run:

 exec create_awr;
 exec update_test_tab(1000, 1);
 exec create_awr;


AWR shows:

Statistic Total / Waits per Second per Trans
redo size 11,369,340 943,435.40 11,245.64
user commits 1,011 83.89 1.00
redo synch writes 2 0.17 0.00
redo writes 971 80.57 0.96
log file sync 2
log file parallel write 972

Table-1

For 1000 updates and 1000 user commits, it requires 971 "redo write" which triggered almost same number of "log file parallel write" (972), very close to the number of user commits. However, only 2 "redo synch write", hence 2 "log file sync". That is the effect of Asynchronous Commit.

Note that "select for update" shows the similar Redo behaviour as "update" even though there is no real update (see Test Code 2).

This Redo optimization is also effective for Oracle Server-Side Internal Driver JVM.

2. Synchronous Commit


Run "script_1 1000", AWR shows:


Statistic Total / Waits per Second per Trans
redo size 11,202,868 3,002,644.87 11,080.98
user commits 1,011 270.97 1.00
redo synch writes 1,001 268.29 0.99
redo writes 1,036 277.67 1.02
log file sync 1,001
log file parallel write 1,034

Table-2

In case of 1000 Synchronous Commits, all 5 statistics (not including "redo size") are almost same. Each user commit leads to one respective event.

"redo synch write" represents the number of times the redo is forced to disk immediately, usually for a transaction commit.

Client-Side JDBC connection has the similar behaviour. But it is possible to switch off default auto-commit by:
   connection.setAutoCommit(false).

3. Piggybacked Commit


Piggybacked Commit reduces the number of redo writes caused by commits by grouping redo records from several sessions together (Oracle Mos WAITEVENT: "log file sync" Reference Note (Doc ID 34592.1)).

Run:

 exec create_awr;
 exec update_test_tab_loop(1000, 10);
 exec dbms_lock.sleep(120); 
 -- wait for job finished
 exec create_awr;


AWR shows:


Statistic Total / Waits per Second per Trans
redo size 18,138,376 136,033.06 1,808.05
user commits 10,032 75.24 1.00
redo synch writes 12 0.09 0.00
redo writes 440 3.30 0.04
log file sync 12
log file parallel write 439

Table-3

Comparing to Table-1, although we make 10,000 updates and user commits, "redo size" is not 10 times that of Table-1 (18,138,376 vs. 11,369,340), and "redo write" (also "log file parallel write") is even less than that of Table-1 (440 vs. 971). That is the role Piggybacked Commit plays.

LGWR truss outputs:

  listio64(0x0000000010000004, 0x000000000FFFFFFF, 0x00000000FFFDB4D0, 0x0000000000000002, ...) = 0x0000000000000000
  aio_nwait64(0x0000000000001000, 0x0000000000000002, 0x0FFFFFFFFFFEB4D0, 0x800000000000D032, ...) = 0x0000000000000002
  thread_post_many(7, 0x0FFFFFFFFFFF3488, 0x0FFFFFFFFFFF3480) = 0
  listio64(0x0000000010000004, 0x000000000FFFFFFF, 0x00000000FFFDB4D0, 0x0000000000000002, ...) = 0x0000000000000000
  aio_nwait64(0x0000000000001000, 0x0000000000000002, 0x0FFFFFFFFFFEB4D0, 0x800000000000D032, ...) = 0x0000000000000002
  thread_post_many(4, 0x0FFFFFFFFFFF3488, 0x0FFFFFFFFFFF3480) = 0
  listio64(0x0000000010000004, 0x000000000FFFFFFF, 0x00000000FFFDB4D0, 0x0000000000000002, ...) = 0x0000000000000000
  aio_nwait64(0x0000000000001000, 0x0000000000000002, 0x0FFFFFFFFFFEB4D0, 0x800000000000D032, ...) = 0x0000000000000002
  thread_post_many(6, 0x0FFFFFFFFFFF3488, 0x0FFFFFFFFFFF3480) = 0

We can see LGWR "thread_post_many" several sessions (nthreads is the first parameter of "thread_post_many") after each "aio_nwait64". It means that redo of multiple threads (oracle sessions) are written by one single "listio64" and are posted at the same time.

4. Distributed Transactions


We will look at Oracle-Controlled Distributed Transactions (using Database Link).

Run "script_2 1000", AWR in dblocal (Commit Point Site) shows:


Statistic Total / Waits per Second per Trans
redo size 12,135,636 394,513.70 12,003.60
user commits 1,011 32.87 1.00
redo synch writes 3,003 97.62 2.97
redo writes 3,038 98.76 3.00
log file sync 3,002
log file parallel write 3,116
transaction branch allocation 4,012

Table-4


AWR in dbremote shows:

Statistic Total / Waits per Second per Trans
redo size 11,315,104 371,681.63 11,191.99
user commits 1,011 33.21 1.00
redo synch writes 2,003 65.80 1.98
redo writes 2,035 66.85 2.01
log file sync 2,002
log file parallel write 2,036
transaction branch allocation 9,013

Table-5

Comparing to Table-2 of 1000 Synchronous Commits in nondistributed transactions, 1000 updates and 1000 user commits in Distributed Transactions demand for 3 times of redo events in Commit Point Site, and 2 times in other node. "transaction branch allocation" is 4 times, respectively, 9 times.

Each "redo synch write" is translated as one UNIX System Call "pwrite", which can be watched by truss or dtrace command in Solaris. Therefore there are 3,003 pwrites in dblocal, and 2,003 pwrites in dbremote.

By dumping Redo Log only for the "commit" command in dblocal and dbremote with:
     ALTER SYSTEM DUMP LOGFILE '<full_path_logfile_name>';

CHANGE vectors in dblocal are:

CLS:117 AFN:3 DBA:0x00c00290 OBJ:4294967295 SCN:0x0853.9628ab8a SEQ:1 OP:5.2 
CLS:118 AFN:3 DBA:0x00c00550 OBJ:4294967295 SCN:0x0853.9628ab8a SEQ:1 OP:5.1 
CLS:118 AFN:3 DBA:0x00c00550 OBJ:4294967295 SCN:0x0853.9628ab8d SEQ:1 OP:5.1 
CLS:117 AFN:3 DBA:0x00c00290 OBJ:4294967295 SCN:0x0853.9628ab8d SEQ:1 OP:5.12 
CLS:117 AFN:3 DBA:0x00c00290 OBJ:4294967295 SCN:0x0853.9628ab8d SEQ:2 OP:5.12 
CLS:117 AFN:3 DBA:0x00c00290 OBJ:4294967295 SCN:0x0853.9628ab8f SEQ:1 OP:5.4 

CHANGE vectors in dbremote are:

CLS:123 AFN:3 DBA:0x00c002b0 OBJ:4294967295 SCN:0x0853.9628ac1d SEQ:1 OP:5.2
CLS:124 AFN:3 DBA:0x00c009ba OBJ:4294967295 SCN:0x0853.9628ac5c SEQ:1 OP:5.1
CLS:124 AFN:3 DBA:0x00c009ba OBJ:4294967295 SCN:0x0853.9628ac6a SEQ:1 OP:5.1
CLS:123 AFN:3 DBA:0x00c002b0 OBJ:4294967295 SCN:0x0853.9628ac6a SEQ:1 OP:5.4

we can see that "commit" in dblocal includes two additional "OP:5.12" CHANGE vectors on UNDO header (CLS:117), apart from OP:5.2 (change for update transaction table in undo segment header), OP:5.1 (Change for update of the undo block), OP:5.4 (change for Commit). Probably "OP:5.12" is particular for 2pc commit.

As documented in Oracle Two-Phase Commit Mechanism, Commit Point Site experiences 3 Phases: Prepare/Commit/Forget Phases, whereas other resource nodes perform only first 2 Phases.

A redo record, also called a redo entry, is made up of a group of change vectors. In AWR report, we can also check "redo entries".

Each committed transaction has an associated system change number (SCN) to uniquely identify the changes made  by the SQL statements within that transaction.

During the prepare phase, the database determines the highest SCN at all nodes involved in the transaction. The transaction then commits with the high SCN at the commit point site. The commit SCN is then sent to all prepared nodes with the commit decision (Distributed Transactions Concepts).

alert log of dblocal contains the following text when first time to make the Distributed Transaction.

 Fri Jul 03 13:48:00 2015
 Advanced SCN by 29394 minutes worth to 0x0824.738bd480, by distributed transaction logon, remote DB: DBREMOTE.COM.
  Client info: DB logon user TESTU, machine dbremote, program oracle@dbremote (TNS V1-V3), and OS user oracle
 Fri Jul 03 13:50:04 2015 

Following two queries can help monitor Distributed Transactions.

 select 'local' db, v.* from v$global_transaction v  union all
 select 'remote' db, v.* from v$global_transaction@dblinkremote v;
 
 select 'local' db, v.* from v$lock v where type in ('TM', 'TX', 'DX')  union all
 select 'remote' db, v.* from v$lock@dblinkremote v where type in ('TM', 'TX', 'DX');

For XA Based Distributed Transactions (X/Open DTP), the similar behaviour can be observed.
Additionally in AWR - Enqueue Activity shows "DX-Distributed Transaction".

5. Distributed Transaction Commit


We can commit the whole distributed transaction in local db:
   update test_redo set name = 'update_local_1' where id = 1;
   update
test_redo@dblinkremote set name = 'update_remote_1' where id = 1;
   commit;

or commit in remote db:
   update test_redo set name = 'update_local_1' where id = 1;
   update
test_redo@dblinkremote set name = 'update_remote_1' where id = 1;
   exec dblinkremote_commit;


6. Distributed Transaction with autonomous_transaction


We can make one more sophisticated test by incorporating one autonomous_transaction in remote DB.
Run "script_3 1000", AWR in dblocal (Commit Point Site) shows:

Statistic Total / Waits per Second per Trans
redo size 12,010,796 483,565.34 11,880.11
user commits 1,011 40.7 1.00
redo synch writes 3,004 120.94 2.97
redo writes 3,041 122.43 3.01
log file sync 3,004
log file parallel write 3,042
transaction branch allocation 6,010

Table-6

AWR in dbremote shows:

Statistic Total / Waits per Second per Trans
redo size 12,156,052 499,673.30 6,047.79
user commits 2,010 82.62 1.00
redo synch writes 3,002 123.4 1.49
redo writes 3,035 124.75 1.51
log file sync 3,004
log file parallel write 3,034
transaction branch allocation 10,019

Table-7

In dblocal, Table-4 and Table-6 are almost identical.

In dbremote, the numbers in Table-7 is higher than Table-5 due to autonomous_transaction. It looks like no Piggybacked Commit in effect.

The above test case reflects the complexity of three-tier architecture, where middle tier and data tier synchronize atomic data operations with Distributed Transaction. In case of Oracle as data tier, it can involve autonomous_transactions.

7. Distributed Transaction: distributed_lock_timeout


In remote db, set distributed_lock_timeout by:
       alter system set distributed_lock_timeout=27 scope=spfile;
then restart remote db:
       startup force;
in remote db, run;
       update test_redo set name = 'update_remote_0' where id = 1;
and then in local db, execute:
   update test_redo set name = 'update_local_1' where id = 1;
   update
test_redo@dblinkremote set name = 'update_remote_1' where id = 1;
after 27 seconds (waiting Event "enq: TX - contention"), it returns:
   ORA-02049: timeout: distributed transaction waiting for lock
   ORA-02063: preceding line from DBLINKREMOTE


ORA-02049 occurs when the DML modified segment is blocked more than distributed_lock_timeout, for example, if the segment is stored in Oracle bigfile tablespace, and pre-allocation takes more than distributed_lock_timeout. (see Blog: Oracle bigfile tablespace pre-allocation and session blocking).

Test Setup


Setup two DBs, one named dblocal, another dbremote.

Run Test Code 1 on both DBs, additionally run Test Code 2 on dblocal.
Note: adapt database name, user_id, password at first.

---------------- Test Code 1 ----------------

drop table test_redo; create table test_redo ( id int primary key using index (create index ind_p on test_redo (id)), name varchar2(300)); insert into test_redo select level, rpad('abc', 100, 'x') y from dual connect by level <= 10000; exec dbms_stats.gather_table_stats(null, 'TEST_REDO', cascade => true); create or replace procedure create_awr as begin sys.dbms_workload_repository.create_snapshot('ALL'); end; / create or replace procedure db_commit as begin commit; end; / create or replace procedure db_commit_autotrx(i number) as pragma autonomous_transaction; begin update test_redo set name = i||'_autonomous_transaction_at_'||localtimestamp where id = (10000 - (i - 1)); commit; end; /

---------------- Test Code 2 ----------------

drop database link dblinkremote; create database link dblinkremote connect to k identified by k using 'dbremote'; create or replace procedure update_test_tab(p_cnt number, p_job number) as begin for i in 1.. p_cnt loop update test_redo set name = rpad('abc', 100, i) where id = (p_job -1) * 1000 + mod(i, 1001); ---- get similar AWR Redo figures for select for update --for c in (select name from test_redo where id = (p_job -1) * 1000 + mod(i, 1001) for update) --loop null; end loop; commit; end loop; end; / create or replace procedure update_test_tab_loop(p_cnt number, p_job_cnt number) as l_job_id pls_integer; begin for i in 1.. p_job_cnt loop dbms_job.submit(l_job_id, 'update_test_tab('||p_cnt||', '|| i||');'); end loop; commit; end; / create or replace procedure dblinkremote_commit as begin db_commit@dblinkremote; end; / create or replace procedure dblinkremote_commit_autotrx(i number) as begin db_commit_autotrx@dblinkremote(i); end; /

---------------- script_1 ----------------

#!/bin/ksh sqlplus -s testu/testp |& print -p "exec create_awr;" print -p "set feedback off" i=0 while (( i < $1 )) do (( i+=1 )) echo $i print -p "update test_redo set name = rpad('abc', 100, $i) where id = mod($i, 1001);" print -p "commit;" done print -p "exec create_awr;" print -p "exit 0"

---------------- script_2 ----------------

#!/bin/ksh sqlplus -s testu/testp |& print -p "exec create_awr;" print -p "exec create_awr@dblinkremote;" print -p "set feedback off" i=0 while (( i < $1 )) do (( i+=1 )) echo $i print -p "update test_redo set name = rpad('abc', 100, $i) where id = mod($i, 1001);" print -p "update test_redo@dblinkremote set name = rpad('abc', 100, $i) where id = mod($i, 1001);" print -p "commit;" done print -p "exec create_awr;" print -p "exec create_awr@dblinkremote;" print -p "exit 0"

---------------- script_3 ----------------

#!/bin/ksh sqlplus -s testu/testp |& print -p "exec create_awr;" print -p "exec create_awr@dblinkremote;" print -p "set feedback off" i=0 while (( i < $1 )) do (( i+=1 )) echo $i print -p "update test_redo set name = rpad('abc', 100, $i) where id = mod($i, 1001);" print -p "update test_redo@dblinkremote set name = rpad('abc', 100, $i) where id = mod($i, 1001);" print -p "exec dblinkremote_commit_autotrx(mod($i, 1001));" print -p "commit;" done print -p "exec create_awr;" print -p "exec create_awr@dblinkremote;" print -p "exit 0"

Thursday, July 2, 2015

UNDO Practice

An expert is a person who has found out by his own painful experience all the mistakes that one can make in a very narrow field.
Niels Bohr

Book Oracle Core: Essential Internals for DBAs and Developers declared that change vector (the heart of redo and undo) is most important feature of Oracle (Page 5). While redo data(after image) is written to be forgotten, undo data(before image) is active over the life time of instance. Therefore it is worth of doing a couple of exercises on UNDO by following:
"The Beginners' Guide to Becoming an Oracle Expert" (Page 5).

All tests are done in Oracle 11.2.0.4.0 with undo_management=AUTO and db_block_size=8192.

UNDO dump


The first test code is to practice what one learned from the book (see the book for more details).

Run Test Code 1, output looks like:

------------ testhost_ora_25106_block_1.trc ------------
Start dump data blocks tsn: 1172 file#:863 minblk 2082662 maxblk 2082662
scn: 0x0824.e789f0b4 seq: 0x02 flg: 0x04 tail: 0xf0b40602
0x02   0x0078.01c.000006ba  0x00c0054a.03c8.01  ----    1  fsc 0x0000.00000000
bdba: 0x001fc766


------------ testhost_ora_25106_block_2.trc ------------
Start dump data blocks tsn: 1172 file#:863 minblk 2082663 maxblk 2082663
scn: 0x0824.e789f0b8 seq: 0x02 flg: 0x04 tail: 0xf0b80602
0x02   0x0078.01c.000006ba  0x00c0054b.03c8.01  ----    1  fsc 0x0000.00000000
bdba: 0x001fc767


------------ testhost_ora_25106_block_3.trc ------------
Start dump data blocks tsn: 1172 file#:863 minblk 2082659 maxblk 2082659
scn: 0x0824.e789f0bc seq: 0x02 flg: 0x04 tail: 0xf0bc0602
0x02   0x0078.01c.000006ba  0x00c0054c.03c8.01  ----    1  fsc 0x0000.00000000
bdba: 0x001fc763


------------ testhost_ora_25106_undo_1.trc ------------
Start dump data blocks tsn: 2 file#:3 minblk 1354 maxblk 1354
BH (0xc0f6fe38) file#: 3 rdba: 0x00c0054a (3/1354) class: 256 ba: 0xc013a000
scn: 0x0824.e789f0b4 seq: 0x01 flg: 0x04 tail: 0xf0b40201
xid: 0x0078.01c.000006ba  seq: 0x3c8 cnt: 0x1   irb: 0x1   icl: 0x0   flg: 0x0000
rdba: 0x00c00549
op: C  uba: 0x00c00549.03c8.38


------------ testhost_ora_25106_undo_2.trc ------------
Start dump data blocks tsn: 2 file#:3 minblk 1355 maxblk 1355
BH (0xcef64d80) file#: 3 rdba: 0x00c0054b (3/1355) class: 256 ba: 0xce018000
scn: 0x0824.e789f0b8 seq: 0x02 flg: 0x04 tail: 0xf0b80202
xid: 0x0078.01c.000006ba  seq: 0x3c8 cnt: 0x1   irb: 0x1   icl: 0x0   flg: 0x0000
rdba: 0x00c0054a
op: C  uba: 0x00c0054a.03c8.02


------------ testhost_ora_25106_undo_3.trc ------------
Start dump data blocks tsn: 2 file#:3 minblk 1356 maxblk 1356
BH (0xd2fe5930) file#: 3 rdba: 0x00c0054c (3/1356) class: 256 ba: 0xd2d4c000
scn: 0x0824.e789f0bc seq: 0x02 flg: 0x04 tail: 0xf0bc0202
xid: 0x0078.01c.000006ba  seq: 0x3c8 cnt: 0x1   irb: 0x1   icl: 0x0   flg: 0x0000
rdba: 0x00c0054b
op: C  uba: 0x00c0054b.03c8.02


1. Above output showed that all UNDO blocks are linked with "rdba" field, from last to first
    (0x00c0054c -> 0x00c0054b -> 0x00c0054a).

2. The modified ITL in each Data block is also saved in its UNDO block's field marked with:
    "op: C  uba:". So all modified information in Data block are recorded in Before Image.

UNDO Size


We can make an UNDO test by updating one block many times, and querying an un-modified block in a different session. The purpose is trying to extend UNDO length (Space) to infinitive.

Open one session, update first row 1000 times, without commit:

 begin
   for i in 1..1000 loop
     update test_tab set name = rpad('a', 3000, i) where id = '1';
   end loop;
 end;
 /

Open a second session, read second row:

 select value from v$sysstat where name = 'data blocks consistent reads - undo records applied';
 select count(*) from test_tab t where id = '2';
 select value from v$sysstat where name = 'data blocks consistent reads - undo records applied';

The output:

 7401710432
 1
 7401711432

shows that there are 1000 (7401711432 - 7401710432) "data blocks consistent reads - undo records applied".

Even though the second row is not modified and in a different block, it still needs to apply whole UNDO records to make the CR read:

(More statistics can be listed by RUNSTATS in Expert Oracle Database Architecture)


UNDO Duration


Another UNDO test is by continuously inserting rows without commit, and querying in a few other sessions. The purpose is trying to extend UNDO duration (Time) to infinitive.

The similar pattern of code could probably be found in some real applications.
(see Test Code 2)

Start the test by:

 exec insert_no_commit_loop(1);
 exec test_select_loop(24);

From time to time, run following query, we could see elapsed_per_exec of select statement is gradually increasing. At beginning, it is some milliseconds, after a few hours, it could reach a couple of minutes.

select executions, disk_reads
      ,rows_processed, round(rows_processed/executions, 2) rows_per_exec
      ,buffer_gets, round(buffer_gets/executions, 2) buffer_per_exec
      ,round(elapsed_time/1e3) elapsed_time, round(elapsed_time/1e3/executions, 2) elapsed_per_exec
      ,v.*
from v$sql v where lower(sql_text) like '%test_tab2%' and v.executions > 0
order by v.executions desc;


Deeper into Buffer Cloning


In the Section: Deeper into Buffer Cloning (Page 244) of  Oracle Performance Firefighting (4th Printing June 2010) there is some text:

The SCN is 12320, which is before our query stated at time 12330. Therefore, we do not apply the undo. If we did apply the undo, our CR buffer would represent a version of block 7,678 at time
12320, which is too early!

Probably even though 12320 is before 12330, we should also apply this undo since it belongs to an opened transaction. In fact, we should reverse all blocks in this un-committed transaction.

Otherwise, the elapsed_per_exec of above select statement would arrive at a fixpoint (might be Nash equilibrium ?).

In Page 242, text:

If you recall, when a server process locates a desired buffer and discovers a required row has changed since its query began, it must create a back-in-time image of the buffer.

Same as above argument, even a required row is changed before its query began, it should also be reversed if not yet committed.


Temporary Table (GTT): UNDO / Redo


As we know, Oracle fulfils a DML by following 5 steps:
  1. create UNDO Change Vector
  2. create REDO Change Vector
  3. combine both Change Vectors into Redo Buffer, and then write to redo log
  4. write UNDO record into UNDO file
  5. write modified Data into DATA file
(See: Oracle Core: Essential Internals for DBAs and Developers (Page 10); Update Restart and new Active Undo Extent )

In case of GTT, applying the principle:
  Oracle redo log never records temporary data.
to prune the above 5 steps, a DML on GTT is processed by 4 steps:
  1. create UNDO Change Vector
  3. combine UNDO Change Vectors into Redo Buffer, and then write to redo log
  4. write UNDO record into UNDO file
  5. write modified Data into DATA (TEMP) file     
when setting 12c temp_undo_enabled=TRUE, it is further shortened as:
  1. create UNDO Change Vector
  4. write UNDO record into TEMP file (Remember TEMP has NEVER redo, V$TEMPUNDOSTAT)
  5. write modified Data into DATA (TEMP) file    

Test Code 1


drop table test_tab;
create table test_tab (id varchar2(3), scn number, name varchar2(3000), team varchar2(3000));
insert into test_tab values ('1', 1, rpad('a', 3000, 'a'), rpad('x', 3000, 'x'));
insert into test_tab values ('2', 2, rpad('b', 3000, 'b'), rpad('y', 3000, 'y'));
insert into test_tab values ('3', 3, rpad('c', 3000, 'c'), rpad('z', 3000, 'z'));
commit;

set lines 200
column name new_value  hostname
column mysid new_value mysid
column spid new_value  myspid
column dir new_value   mydir

select lower(name) name, sys.dbms_support.mysid mysid from v$database;
select spid from v$session s, v$process p where s.paddr=p.addr and s.sid = sys.dbms_support.mysid;
select '/orabin/app/oracle/admin/'||'&hostname'||'/diag/rdbms/'||'&hostname'||'/'||'&hostname'||'/trace' dir
from dual;

prompt hostname: &hostname, mysid: &mysid, myspid: &myspid, mydir: &mydir

create or replace directory TEST_DUMP_DIR as '&mydir';  
-- see: select * from v$diag_info where name = 'Diag Trace';

drop table dump_text_tab;

create table dump_text_tab (text varchar2(1000)) organization external
(type oracle_loader default directory TEST_DUMP_DIR
 access parameters
  (records delimited by newline CHARACTERSET AL32UTF8
   badfile aaa_db_io:'dump_text_tab.bad'
   logfile aaa_db_io:'dump_text_tab.log'
   discardfile aaa_db_io:'dump_text_tab.dsc'
   fields terminated by ','  OPTIONALLY ENCLOSED BY '"'
   missing field values are null
   reject rows with all null fields
   (text position(1:1000)))
 location ('host_ora_spid_x.trc')) reject limit unlimited;

create or replace procedure dump_read(loc varchar2, type varchar2) as
begin
  dbms_output.put_line('------------ '||loc||' ------------');
  execute immediate q'[alter table dump_text_tab location (']'||loc||q'[')]';
  if type = 'block' then
    for c in (
      select text from dump_text_tab
      where text like 'Start dump data blocks tsn:%'
         or text like 'scn:%'
         or text like '%-    1  fsc%'
         or text like 'bdba:%') loop
      dbms_output.put_line(c.text);
    end loop;
  else
  for c in (
    select text from dump_text_tab
    where text like 'Start dump data blocks tsn:%'
       or text like 'BH (%'
       or text like 'scn:%'
       or text like 'xid:%'
       or text like 'rdba:%'
       or text like 'op: C  uba:%') loop
    dbms_output.put_line(c.text);
  end loop;   
  end if;
end;
/

------------ Block 1 ------------
def id = 1

update test_tab set scn = dbms_flashback.get_system_change_number, name = upper(name), team = upper(team) where id = '&id';
-- dbms_flashback.get_system_change_number call makes test stable.

column file_id new_value  fid
column block_nr new_value blk
column location new_value loc_block_1

select dbms_rowid.rowid_to_absolute_fno(t.rowid, 'K', 'TEST_TAB') file_id
      ,dbms_rowid.rowid_block_number(t.rowid)           block_nr
      ,'&hostname'||'_ora_'||trim('&myspid')||'_block_&id'||'.trc' location
from test_tab t where id = '&id';

prompt fid: &fid, blk: &blk, loc: &loc_block_1

alter session set tracefile_identifier = 'block_&id';
alter system flush buffer_cache;
alter system dump datafile &fid block &blk; 

------------ UNDO 1 ------------
column location new_value loc_undo_1
select ubafil    file_id
      ,ubablk    block_nr
   ,'&hostname'||'_ora_'||trim('&myspid')||'_undo_&id'||'.trc' location
from v$session s, v$transaction x
where s.saddr = x.ses_addr and s.sid = sys.dbms_support.mysid;

alter session set tracefile_identifier = 'undo_&id';
alter system flush buffer_cache;
alter system dump datafile &fid block &blk; 

------------ Block 2 ------------
def id = 2

update test_tab set scn = dbms_flashback.get_system_change_number, name = upper(name), team = upper(team) where id = '&id';

column location new_value loc_block_2
select dbms_rowid.rowid_to_absolute_fno(t.rowid, 'K', 'TEST_TAB') file_id
      ,dbms_rowid.rowid_block_number(t.rowid)           block_nr
      ,'&hostname'||'_ora_'||trim('&myspid')||'_block_&id'||'.trc' location
from test_tab t where id = '&id';

alter session set tracefile_identifier = 'block_&id';
alter system flush buffer_cache;
alter system dump datafile &fid block &blk; 

------------ UNDO 2 ------------
column location new_value loc_undo_2
select ubafil    file_id
      ,ubablk    block_nr
   ,'&hostname'||'_ora_'||trim('&myspid')||'_undo_&id'||'.trc' location
from v$session s, v$transaction x
where s.saddr = x.ses_addr and s.sid = sys.dbms_support.mysid;

alter session set tracefile_identifier = 'undo_&id';
alter system flush buffer_cache;
alter system dump datafile &fid block &blk; 

------------ Block 3 ------------
def id = 3

update test_tab set scn = dbms_flashback.get_system_change_number, name = upper(name), team = upper(team) where id = '&id';

column location new_value loc_block_3
select dbms_rowid.rowid_to_absolute_fno(t.rowid, 'K', 'TEST_TAB') file_id
      ,dbms_rowid.rowid_block_number(t.rowid)           block_nr
      ,'&hostname'||'_ora_'||trim('&myspid')||'_block_&id'||'.trc' location
from test_tab t where id = '&id';

alter session set tracefile_identifier = 'block_&id';
alter system flush buffer_cache;
alter system dump datafile &fid block &blk; 

------------ UNDO 3 ------------
column location new_value loc_undo_3
select ubafil    file_id
      ,ubablk    block_nr
   ,'&hostname'||'_ora_'||trim('&myspid')||'_undo_&id'||'.trc' location
from v$session s, v$transaction x
where s.saddr = x.ses_addr and s.sid = sys.dbms_support.mysid;

alter session set tracefile_identifier = 'undo_&id';
alter system flush buffer_cache;
alter system dump datafile &fid block &blk; 

------------ Block dump read ------------
set serveroutput on
exec dump_read('&loc_block_1', 'block');
exec dump_read('&loc_block_2', 'block');
exec dump_read('&loc_block_3', 'block');

------------ UNDO dump read ------------
exec dump_read('&loc_undo_1', 'undo');
exec dump_read('&loc_undo_2', 'undo');
exec dump_read('&loc_undo_3', 'undo');

Test Code 2


create sequence test_seq;
create table test_tab2 (id number, seq_nr number, cnt number);
create index test_tab2_ind on test_tab2 (id, seq_nr, cnt) compress 1;
create type type_c100 as table of varchar2(100);
/

create or replace procedure insert_no_commit(p_cnt number) as
begin
  insert into test_tab2 select 99, test_seq.nextval, level from dual connect by level <= p_cnt;
  dbms_lock.sleep(0.1);
end;
/

create or replace procedure test_select as
  l_tab   type_c100;
begin
    select rowidtochar(rowid) bulk collect into l_tab
    from   test_tab2 where  id = 99;
    dbms_lock.sleep(0.1);
end;
/

create or replace procedure insert_no_commit_loop(p_job_cnt number)
as
   l_job_id pls_integer;
begin
    for i in 1.. p_job_cnt loop
      dbms_job.submit(l_job_id, 'begin while true loop insert_no_commit(4); end loop; end;');
    end loop;
    commit;
end;   
/

create or replace procedure test_select_loop(p_job_cnt number)
as
   l_job_id pls_integer;
begin
    for i in 1.. p_job_cnt loop
      dbms_job.submit(l_job_id, 'begin while true loop test_select; end loop; end;');
    end loop;
    commit;
end;   
/