Tuesday, February 18, 2025

Blog List

Posted by at

One Oracle CLOB Space Usage Test

In this Blog, we will make LOB space usage test to show the used_blocks, expired_blocks, unexpired_blocks.
And in case of LOB "buffer busy waits" and "latch: cache buffers chains", we list the type of LOB data blocks in buffer cache.

Note: Tested in Oraclw 19.25 with following UNDO parameters: 
  temp_undo_enabled   boolean     TRUE
  undo_management     string      AUTO
  undo_retention      integer     3600


1. Test Run


Run following test to insert 1000 rows (TEST_SEQ is cycle with maxvalue 1000), each row has one CLOB of 1MB, so total is about 1000MB. 

-- see appended Test Code
truncate table test_tab_lob;
set serveroutput on size unlimited 
alter sequence test_seq_1000 restart start with 1;
exec check_space_securefile_2('K', 'TEST_TAB_LOB', 'MYLOB');
-- 10000 inserts for total 1000 rows, each row is repeatedly overwritten.
exec test_lob_proc(1, 1000, 1e4); 
exec check_space_securefile_2('K', 'TEST_TAB_LOB', 'MYLOB');
select round(sum(dbms_lob.getlength(mylob))/1024/1024, 2) LOB_MB, round(sum(length(mylob))/1024/1024, 2) MB
      ,count(id), min(id), max(id), min(ts), max(ts) from test_tab_lob;
The output looks like: 

SQL > exec test_lob_proc(1, 1000, 1e4);
  Each mylob Length = 1056000, SUM Size (MB) =10000
  SUM Size (MB) =10000, Real Contained Size (MB, due to TEST_SEQ_1000.Max Limit) = 1000    
  
  Elapsed: 00:08:02.09

SQL > exec check_space_securefile_2('K', 'TEST_TAB_LOB', 'MYLOB');
  ===========================================================================
  segment_size_blocks = 1301880
  used_blocks         = 145718 (11.19 %)
  expired_blocks      = 1156162 (88.81 %)
  unexpired_blocks    = 0 (0 %)
  ===========================================================================
  Segment Blocks/Bytes   = 1301880 / 10665000960 (10170.94 MB)
  Unused Blocks/Bytes    = 0 / 0 (0 %)
  Used Blocks/Bytes      = 145718 / 1193721856 (11.19 %)
  Expired Blocks/Bytes   = 1156162 / 9471279104 (88.81 %)
  Unexpired Blocks/Bytes = 0 / 0 (0 %)
  ===========================================================================
  NON Data Blocks  = 1156162 (88.81 %)
  NON_data_blocks_2 (= segment_size_blocks - used_blocks) = 1156162
  ===========================================================================
  LOBSEGMENT DBA_EXTENTS storage size Blocks  = 1301880, CNT = 280, MIN_Blocks = 120, MAX_Blocks = 8192
  LOBSEGMENT DBA_EXTENTS storage size Byets   = 10665000960 (10170.94 MB)
  LOBSEGMENT DBA_SEGMENTS storage size Blocks = 1301880
  LOBSEGMENT DBA_SEGMENTS storage size Byets  = 10665000960 (10170.94 MB)

SQL > select round(sum(dbms_lob.getlength(mylob))/1024/1024, 2) LOB_MB, round(sum(length(mylob))/1024/1024, 2) MB
             ,count(id), min(id), max(id), min(ts), max(ts) from test_tab_lob;

   LOB_MB         MB  COUNT(ID)  MIN(ID)  MAX(ID) MIN(TS)               MAX(TS)
  ------- ---------- ---------- -------- -------- --------------------  --------------------
  1007.08    1007.08       1000        1     1000 17-FEB-2025 11:14:27  17-FEB-2025 11:15:15
Above output shows that for 1007.08 MB CLOB data, the segment consumes about 10170.94 MB, of which 88.81% is used for NON Data Blocks, and they are expired_blocks.

By the way, previous Blog: "LOB ORA-22924: snapshot too old and Fix" (http://ksun-oracle.blogspot.com/2019/04/lob-ora-22924-snapshot-too-old-and-fix.html) showed the special behaviour of LOB snapshot too old.

We can also run a parallel job sessions to show 'buffer busy waits' / 'latch: cache buffers chains' and the contention data block CLASS#.

Run job test by: 

--exec clearup_test;
truncate table test_tab_lob;
alter sequence test_seq_1000 restart start with 1;
exec check_space_securefile_2('K', 'TEST_TAB_LOB', 'MYLOB');
exec test_lob_proc_job(16, 1000, 1e3);

-- Wait till all Jobs finished
select count(*) from dba_scheduler_jobs where job_name like '%TEST_JOB%';

-- Show space usage
exec check_space_securefile_2('K', 'TEST_TAB_LOB', 'MYLOB');
And run monitoring query during test to watch the wait event: 

select program, event, module, action, event, p1, p2, p3, p1text, p2text, p3text, t.* 
from v$active_session_history t
where sample_time > sysdate -10/1440 and action like 'TEST_JOB%' 
  and event in ('buffer busy waits', 'latch: cache buffers chains')
order by t.sample_time desc;
It shows that most of 'buffer busy waits' / 'latch: cache buffers chains' are on LOB metadata CLASS# 8 (1st level bmb) and 6 (free list).

With following query, we can display the type of data blocks in buffer cache: 

with sq as  (select /*+ materialize */ segment_name, index_name from dba_lobs where owner='K' and table_name='TEST_TAB_LOB'),
     obj as (select /*+ materialize */ object_name||', '||object_type LOB_INFO, object_id, data_object_id 
             from dba_objects t, sq where object_name = 'TEST_TAB_LOB' or object_name = sq.segment_name or object_name = sq.index_name)
select LOB_INFO, objd,  class#, status, dirty, file#, count(block#), count(distinct block#)  from v$bh, obj
where objd =  obj.data_object_id
group by LOB_INFO, objd,  class#, status, dirty, file# order by 1, 6 desc, 2, 3, 4, 5 desc; 
  
  LOB_INFO                                OBJD     CLASS# STATUS     D      FILE# COUNT(BLOCK#) COUNT(DISTINCTBLOCK#)
  --------------------------------- ---------- ---------- ---------- - ---------- ------------- ---------------------
  SYS_IL0005743559C00005$$, INDEX      5743561          1 xcur       N       1625             1                     1
  SYS_IL0005743559C00005$$, INDEX      5743561          4 xcur       N       1625             1                     1
  SYS_IL0005743559C00005$$, INDEX      5743561          8 xcur       N       1625             1                     1
  SYS_LOB0005743559C00005$$, LOB       5743564          4 cr         N       1625             5                     1
  SYS_LOB0005743559C00005$$, LOB       5743564          4 xcur       Y       1625             1                     1
  SYS_LOB0005743559C00005$$, LOB       5743564          6 cr         N       1625           205                    46
  SYS_LOB0005743559C00005$$, LOB       5743564          6 xcur       Y       1625            56                    56
  SYS_LOB0005743559C00005$$, LOB       5743564          8 cr         N       1625            34                     9
  SYS_LOB0005743559C00005$$, LOB       5743564          8 xcur       Y       1625             9                     9
  SYS_LOB0005743559C00005$$, LOB       5743564          9 cr         N       1625           424                   106
  SYS_LOB0005743559C00005$$, LOB       5743564          9 xcur       Y       1625           126                   126
  SYS_LOB0005743559C00005$$, LOB       5743564          9 xcur       N       1625            59                    59
  SYS_LOB0005743559C00005$$, LOB       5743564         10 cr         N       1625           115                    26
  SYS_LOB0005743559C00005$$, LOB       5743564         10 xcur       Y       1625            50                    50
  SYS_LOB0005743559C00005$$, LOB       5743564         12 xcur       N       1625          1271                  1271
  TEST_TAB_LOB, TABLE                  5743565          1 cr         N       1625           114                    28
  TEST_TAB_LOB, TABLE                  5743565          1 xcur       Y       1625            28                    28
  TEST_TAB_LOB, TABLE                  5743565          4 cr         N       1625             1                     1
  TEST_TAB_LOB, TABLE                  5743565          4 xcur       Y       1625             1                     1
  TEST_TAB_LOB, TABLE                  5743565          8 xcur       Y       1625             2                     2
  TEST_TAB_LOB, TABLE                  5743565          9 xcur       Y       1625             1                     1
  
  21 rows selected.
The above output shows that majority blocks are from CLASS# 12 (bitmap index block) and CLASS# 9 (2nd level bmb), and hardly see blocks of CLASS# 1 (data block), because Oracle uses "direct path" for LOB data (not IN ROW short LOB).

We can also dump the segment header and bitmap blocks to reveal space distribution. 

with sq as (select /*+ materialize */ segment_name, index_name from dba_lobs where owner='K' and table_name='TEST_TAB_LOB')
select t.segment_name, tablespace_name, header_file, relative_fno, header_block, bytes, blocks, extents from dba_segments t, sq 
where t.segment_name = sq.segment_name or t.segment_name = sq.index_name;

  SEGMENT_NAME               TABLESPACE_NAME  HEADER_FILE RELATIVE_FNO HEADER_BLOCK      BYTES     BLOCKS    EXTENTS
  -------------------------- ---------------- ----------- ------------ ------------ ---------- ---------- ----------
  SYS_LOB0005743559C00005$$  TEST_TBS                1625         1024       262153 1.0661E+10    1301376        276
  SYS_IL0005743559C00005$$   TEST_TBS                1625         1024       262274      65536          8          1


alter session set max_dump_file_size = UNLIMITED;
alter session set tracefile_identifier = 'TEST_TAB_LOB_SEGMENT_DUMP_3';
EXECUTE DBMS_SPACE_ADMIN.SEGMENT_DUMP('TEST_TBS', 1024, 262153); 

-- Dump DDL
select dbms_metadata.get_ddl('TABLE', 'TEST_TAB_LOB', 'KS') from dual;
or dump single bmb block: 

select * from  v$bh where objd=5743591 and class#=8 and status='xcur';
  -- 1625	262159	8	xcur
alter session set max_dump_file_size = UNLIMITED;
alter session set tracefile_identifier = 'bmb_1_262159_dump';
alter system dump datafile 1625 block 262159;
In above test, the CLOB retention_type is DEFAULT: 

select t.column_name, t.retention_type, retention_value, s.segment_name, s.tablespace_name, s.header_file, s.relative_fno, s.header_block--, t.*
from dba_lobs t, dba_segments s where t.owner='K' and t.table_name='TEST_TAB_LOB' and t.segment_name = s.segment_name;

  COLUMN_NAME  RETENTION_TYPE  RETENTION_VALUE SEGMENT_NAME               TABLESPACE_NAME   HEADER_FILE RELATIVE_FNO HEADER_BLOCK
  ------------ --------------- --------------- -------------------------- ----------------- ----------- ------------ ------------
  MYLOB        DEFAULT                         SYS_LOB0005743559C00005$$  TEST_TBS                 1625         1024       262153
We can modify its retention_type as NONE by: 

alter table TEST_TAB_LOB modify lob(mylob) (retention none);

SQL > select t.column_name, t.retention_type, retention_value, s.segment_name, s.tablespace_name, s.header_file, s.relative_fno, s.header_block--, t.*
        from dba_lobs t, dba_segments s where t.owner='K' and t.table_name='TEST_TAB_LOB' and t.segment_name = s.segment_name;

  COLUMN_NAME  RETENTION_TYPE  RETENTION_VALUE SEGMENT_NAME               TABLESPACE_NAME   HEADER_FILE RELATIVE_FNO HEADER_BLOCK
  ------------ --------------- --------------- -------------------------- ----------------- ----------- ------------ ------------
  MYLOB        NONE                            SYS_LOB0005743559C00005$$  TEST_TBS                 1625         1024       262153
and then repeat above test: 

SQL > exec test_lob_proc(1, 1000, 1e4);

  Each mylob Length = 1056000, SUM Size (MB) =10000
  SUM Size (MB) =10000, Real Contained Size (MB, due to TEST_SEQ_1000.Max Limit) = 1000
  
  Elapsed: 00:08:02.12

SQL > exec check_space_securefile_2('K', 'TEST_TAB_LOB', 'MYLOB');

  ===========================================================================
  segment_size_blocks = 163960
  used_blocks         = 144372 (88.05 %)
  expired_blocks      = 19588 (11.95 %)
  unexpired_blocks    = 0 (0 %)
  ===========================================================================
  Segment Blocks/Bytes   = 163960 / 1343160320 (1280.94 MB)
  Unused Blocks/Bytes    = 0 / 0 (0 %)
  Used Blocks/Bytes      = 144372 / 1182695424 (88.05 %)
  Expired Blocks/Bytes   = 19588 / 160464896 (11.95 %)
  Unexpired Blocks/Bytes = 0 / 0 (0 %)
  ===========================================================================
  NON Data Blocks  = 19588 (11.95 %)
  NON_data_blocks_2 (= segment_size_blocks - used_blocks) = 19588
  ===========================================================================
  LOBSEGMENT DBA_EXTENTS storage size Blocks  = 163960, CNT = 140, MIN_Blocks = 120, MAX_Blocks = 8192
  LOBSEGMENT DBA_EXTENTS storage size Byets   = 1343160320 (1280.94 MB)
  LOBSEGMENT DBA_SEGMENTS storage size Blocks = 163960
  LOBSEGMENT DBA_SEGMENTS storage size Byets  = 1343160320 (1280.94 MB)

SQL > select round(sum(dbms_lob.getlength(mylob))/1024/1024, 2) LOB_MB, round(sum(length(mylob))/1024/1024, 2) MB
            ,count(id), min(id), max(id), min(ts), max(ts) from test_tab_lob;

   LOB_MB         MB  COUNT(ID)    MIN(ID)    MAX(ID) MIN(TS)               MAX(TS)
  ------- ---------- ---------- ---------- ---------- --------------------- --------------------
  1007.08    1007.08       1000          1       1000 17-FEB-2025 11:41:04  17-FEB-2025 11:41:52
The above output shows that when RETENTION_TYPE=NONE, only 1280.94 MB is used and expired_blocks is 11.95%, compared to previous RETENTION_TYPE=DEFAULT, 10170.94 MB is used and expired_blocks is 88.81%.

Strangely, once RETENTION_TYPE is set to NONE, setting back to DEFAULT gets error: 

SQL > alter table TEST_TAB_LOB modify lob(mylob) (retention default);
  alter table TEST_TAB_LOB modify lob(mylob) (retention default)
                                                      *
  ERROR at line 1:
  ORA-22853: invalid LOB storage option specification
Here is one hacking workaround to set it back to DEFAULT: 

select header_file, relative_fno, header_block, t.* from dba_segments t where segment_name = 'SYS_LOB0005742851C00004$$';
  --1625	137
                   
select lists
      ,decode(s.lists, 0, 'NONE', 1, 'AUTO',
                       2, 'MIN',  3, 'MAX',
                       4, 'DEFAULT', 'INVALID') ora_retention_type
      ,(select retention_type from  dba_lobs t where table_name='TEST_TAB_LOB') dba_retention_type
      ,s.* 
from sys.seg$ s where file# = 1024 and block# = 262153;   -- lists stores RETENTION

  --4	DEFAULT	DEFAULT	1024	262153
  --0	NONE	  NONE	  1024	262153

update sys.seg$ set lists= 4  where file# = 1024 and block# = 262153;   -- set RETENTION_TYPE to DEFAULT as DBA
commit;
In this Blog, we tested CLOB with "SECUREFILE/COMPRESS/NOCACHE", the similar behavior is also observed with "BASICFILE/NO COMPRESS/CACHE READS".


2. Test Setup 



drop tablespace test_tbs including contents and datafiles;

create bigfile tablespace test_tbs datafile '/oratestdb/oradata/testdb/test_tbs.dbf' size 10G online;

drop table test_tab_lob cascade constraints;

create table test_tab_lob(id number, cnt number, ts timestamp with local time zone default localtimestamp, lob_state varchar2(20), mylob clob) 
  segment creation immediate tablespace test_tbs
  lob (mylob) store as securefile (
   tablespace test_tbs enable storage in row chunk 8192 retention 
   nocache logging compress medium keep_duplicates
   storage(initial 65536 next 131072 minextents 1 maxextents 2147483645
   pctincrease 0 freelists 1 freelist groups 1
   buffer_pool default flash_cache default cell_flash_cache default))  enable row movement;

drop sequence test_seq_1000;

create sequence test_seq_1000 start with 1 maxvalue 1000 minvalue 1 cycle cache 10 global;


3. Test Code 



create or replace procedure test_lob_proc(p_job_nr number, p_kb_cnt number, p_loop_cnt number) as 
  l_mylob     clob;
  l_src_mylob clob;
  l_lob_32kb  clob := lpad('abc', 32000, 'x');
  l_seq       number;
  l_ts_text   varchar2(50);
begin
  l_ts_text   := to_char(localtimestamp, 'YYYY*MON*DD-HH24:MI:SS.FF9');
  l_lob_32kb := dbms_random.string('p', 4000);
  
  --CLOB stored in AL16UTF16 (wo bytes) in AL32UTF8 database. Use dbms_random.string due to CLOB compress
  for i in 1..7 loop
    dbms_lob.append(dest_lob => l_lob_32kb, src_lob => dbms_random.string('p', 4000));  
  end loop;
  l_src_mylob := l_lob_32kb;
  if p_kb_cnt >= 32 then
	  for i in 1..round(p_kb_cnt/32)+1 loop
	    dbms_lob.append(l_src_mylob, l_lob_32kb);
	  end loop;
	else
	  l_src_mylob := dbms_lob.substr(l_lob_32kb, p_kb_cnt*1000, 1);
	end if;
  dbms_output.put_line('Each mylob Length = '||dbms_lob.getlength(l_src_mylob) ||', SUM Size (MB) ='|| (p_loop_cnt*p_kb_cnt/1000));
  dbms_output.put_line('SUM Size (MB) ='|| (p_loop_cnt*p_kb_cnt/1000) ||', Real Contained Size (MB, due to TEST_SEQ_1000.Max Limit) = '|| (1000*p_kb_cnt/1000));
  
  for k in 1..p_loop_cnt loop
	  l_seq := test_seq_1000.nextval;

		merge 
		  into  test_tab_lob l
		  using (select l_seq id, 1 cnt, localtimestamp ts, 'pending' lob_state, empty_clob() mylob from dual) v
		  on (l.id = v.id)
		  when matched then
		    update set cnt = v.cnt + 1, mylob = v.mylob
		  when not matched then
		    insert (id, cnt, ts, mylob) values (l_seq, 1, localtimestamp, v.mylob);
		
		--select mylob into l_mylob from test_tab_lob where id = l_seq;
		--dbms_lob.append(dest_lob => l_mylob, src_lob => l_src_mylob);
    
    -- @TODO First commit more important table scalar columns (fast by LGWR and DBWR) to make them visible, and then mise-a-jour LOB column.
    commit;
    update test_tab_lob set lob_state = 'updated', mylob = l_src_mylob where id = l_seq;
    
	  commit;
	  
	  if k <= 10 then 
		  dbms_output.put_line('Create id = '||l_seq||', mylob Length = '||dbms_lob.getlength(l_src_mylob));
		end if;
    if k = 10 then 
		  dbms_output.put_line('Create id: ........ only print first 10 id');
		end if;
	end loop;
end;
/

-- exec test_lob_proc(1, 1000*3, 10);     -- insert 10 rows with mylob length=3MB 

-------------------- create test jobs ----------------------

create or replace procedure test_lob_proc_job(p_job_cnt number, p_kb_cnt number, p_loop_cnt number) as
  l_job_name varchar2(50);
begin
  for i in 1..p_job_cnt loop
    l_job_name := 'TEST_JOB_ENQ_'||i;
    dbms_scheduler.create_job (
      job_name        => l_job_name,
      job_type        => 'PLSQL_BLOCK',
      job_action      => 
        'begin 
           test_lob_proc('||i||', '||p_kb_cnt||', '||p_loop_cnt||');
        end;',    
      start_date      => systimestamp,
      --repeat_interval => 'systimestamp',
      auto_drop       => true,
      enabled         => true);
  end loop;
end;
/


4. LOB Space Usage 



------------------------------------ SECUREFILE LOB space usage ------------------------------------
--   MOS: How to Determine what storage is used in a LOBSEGMENT and should it be shrunk / reorganized? (Doc ID 1453350.1)

CREATE OR REPLACE PROCEDURE check_space_securefile (u_name in varchar2, v_segname varchar2) IS
  l_segment_size_blocks NUMBER;
  l_segment_size_bytes NUMBER;
  l_used_blocks NUMBER;
  l_used_bytes NUMBER;
  l_expired_blocks NUMBER;
  l_expired_bytes NUMBER;
  l_unexpired_blocks NUMBER;
  l_unexpired_bytes NUMBER;
  l_unused_blocks NUMBER;
  l_unused_bytes NUMBER;
  l_non_data_blocks NUMBER;
  l_non_data_bytes NUMBER;
  l_non_data_blocks_2 NUMBER;
  BEGIN
    DBMS_SPACE.SPACE_USAGE( segment_owner =>u_name,                        --segment_owner           IN    VARCHAR2,                 
                            segment_name => v_segname,                     --segment_name            IN    VARCHAR2,              
                            segment_type => 'LOB',                         --segment_type            IN    VARCHAR2,      
                            suoption     => DBMS_SPACE.SPACEUSAGE_EXACT,   -- or DBMS_SPACE.SPACEUSAGE_FAST
                            segment_size_blocks => l_segment_size_blocks,  --segment_size_blocks     OUT   NUMBER,                
                            segment_size_bytes => l_segment_size_bytes,    --segment_size_bytes      OUT   NUMBER,                
                            used_blocks => l_used_blocks,                  --used_blocks             OUT   NUMBER,                
                            used_bytes => l_used_bytes,                    --used_bytes              OUT   NUMBER,                
                            expired_blocks => l_expired_blocks,            --expired_blocks          OUT   NUMBER,                
                            expired_bytes => l_expired_bytes,              --expired_bytes           OUT   NUMBER,                
                            unexpired_blocks => l_unexpired_blocks,        --unexpired_blocks        OUT   NUMBER,                
                            unexpired_bytes => l_unexpired_bytes           --unexpired_bytes         OUT   NUMBER,                
                                                                           --partition_name          IN    VARCHAR2 DEFAULT NULL
                           );
    DBMS_OUTPUT.PUT_LINE('===========================================================================');
    DBMS_OUTPUT.PUT_LINE('segment_size_blocks = '||l_segment_size_blocks);
    DBMS_OUTPUT.PUT_LINE('used_blocks         = '||l_used_blocks     ||' ('||(round(100*l_used_blocks/l_segment_size_blocks, 2))||' %)');
    DBMS_OUTPUT.PUT_LINE('expired_blocks      = '||l_expired_blocks  ||' ('||(round(100*l_expired_blocks/l_segment_size_blocks, 2))||' %)');
    DBMS_OUTPUT.PUT_LINE('unexpired_blocks    = '||l_unexpired_blocks||' ('||(round(100*l_unexpired_blocks/l_segment_size_blocks, 2))||' %)');
    DBMS_OUTPUT.PUT_LINE('===========================================================================');
    
    l_unused_blocks := l_segment_size_blocks - (l_used_blocks + l_expired_blocks + l_unexpired_blocks);
    l_unused_bytes  := l_segment_size_bytes - (l_used_bytes + l_expired_bytes + l_unexpired_bytes);

    l_non_data_blocks   := l_unused_blocks + l_expired_blocks + l_unexpired_blocks;
    l_non_data_blocks_2 := l_segment_size_blocks - l_used_blocks;
    
    DBMS_OUTPUT.ENABLE;
    DBMS_OUTPUT.PUT_LINE('Segment Blocks/Bytes   = '||l_segment_size_blocks||' / '||l_segment_size_bytes||' ('||round(l_segment_size_bytes/1024/1024, 2) ||' MB)');
    DBMS_OUTPUT.PUT_LINE('Unused Blocks/Bytes    = '||l_unused_blocks      ||' / '||l_unused_bytes      ||' ('||(round(100*l_unused_blocks/l_segment_size_blocks, 2))||' %)');
    DBMS_OUTPUT.PUT_LINE('Used Blocks/Bytes      = '||l_used_blocks        ||' / '||l_used_bytes        ||' ('||(round(100*l_used_blocks/l_segment_size_blocks, 2))||' %)');
    DBMS_OUTPUT.PUT_LINE('Expired Blocks/Bytes   = '||l_expired_blocks     ||' / '||l_expired_bytes     ||' ('||(round(100*l_expired_blocks/l_segment_size_blocks, 2))||' %)');
    DBMS_OUTPUT.PUT_LINE('Unexpired Blocks/Bytes = '||l_unexpired_blocks   ||' / '||l_unexpired_bytes   ||' ('||(round(100*l_unexpired_blocks/l_segment_size_blocks, 2))||' %)');
    DBMS_OUTPUT.PUT_LINE('===========================================================================');
    DBMS_OUTPUT.PUT_LINE('NON Data Blocks  = '||l_non_data_blocks||' ('||(round(100*l_non_data_blocks/l_segment_size_blocks, 2))||' %)');
    DBMS_OUTPUT.PUT_LINE('NON_data_blocks_2 (= segment_size_blocks - used_blocks) = '||l_non_data_blocks_2);
    DBMS_OUTPUT.PUT_LINE('===========================================================================');
    
    -- Determine the storage size of the LOBSEGMENT
    for c in (SELECT round(SUM(BYTES)/8192) blocks, SUM(BYTES) bytes, count(*) cnt, min(blocks) MIN_Blocks, max(blocks) MAX_Blocks FROM DBA_EXTENTS WHERE SEGMENT_NAME = v_segname) loop
      DBMS_OUTPUT.PUT_LINE('LOBSEGMENT DBA_EXTENTS storage size Blocks  = '||c.blocks||', CNT = ' ||c.cnt  ||', MIN_Blocks = '||c.MIN_Blocks ||', MAX_Blocks = '||c.MAX_Blocks);
      DBMS_OUTPUT.PUT_LINE('LOBSEGMENT DBA_EXTENTS storage size Byets   = '||c.bytes ||' ('||round(c.bytes/1024/1024, 2) ||' MB)');
    end loop;
    
    for c in (SELECT round(SUM(BYTES)/8192) blocks, SUM(BYTES) bytes FROM DBA_SEGMENTS WHERE SEGMENT_NAME = v_segname) loop
      DBMS_OUTPUT.PUT_LINE('LOBSEGMENT DBA_SEGMENTS storage size Blocks = '||c.blocks);
      DBMS_OUTPUT.PUT_LINE('LOBSEGMENT DBA_SEGMENTS storage size Byets  = '||c.bytes ||' ('||round(c.bytes/1024/1024, 2) ||' MB)');
    end loop;
  END;
/

CREATE OR REPLACE PROCEDURE check_space_securefile_2 (v_owner_name in varchar2, v_table_name varchar2, v_column_name varchar2) IS
  l_lob_segment_name varchar2(100);
begin
  select segment_name into l_lob_segment_name from dba_lobs where owner=v_owner_name and table_name=v_table_name and column_name=v_column_name;
  check_space_securefile(u_name=>v_owner_name, v_segname=>l_lob_segment_name);
end;
/
Posted by at

Tuesday, November 5, 2024

Oracle Self-tune checkpointing lag of log switch

Often DB alert.log shows a lag of 5 minutes from log switch to Completed checkpoint as follows:
(from 11:03:36 to 11:08:39) 

2024-11-04T11:03:36.681460+01:00
Beginning log switch checkpoint up to RBA [0x8b.2.10], SCN: 13022649669494
2024-11-04T11:03:36.681565+01:00
Thread 1 advanced to log sequence 139 (LGWR switch),  current SCN: 13022649669494
  Current log# 3 seq# 139 mem# 0: /oratestdb/oradata/testdb/redo03.dbf
2024-11-04T11:08:39.613734+01:00
Completed checkpoint up to RBA [0x8b.2.10], SCN: 13022649669494
is this a LGWR performance problem ?

In this Blog, we will demonstrate those LGWR and CKPT asynchronous write and 3 hidden parameters with Linux bpftrace by following the advanced guidance Let's trace it! A peek into the inner workings of Oracle with bpftrace von Christoph Lutz. 

  _selftune_checkpointing_lag		Self-tune checkpointing lag the tail of the redo log   300
  _disable_selftune_checkpointing	Disable self-tune checkpointing                        FALSE
  _selftune_checkpoint_write_pct	Percentage of total physical i/os for self-tune ckpt   3
Note: Tested in Oracle 19.24.

In Linux window, start bpftrace script below: 

BPFTRACE_STRLEN=200 bpftrace -e '
 tracepoint:syscalls:sys_enter_openat /(strncmp("ora_lgwr", comm, 7) == 0 || strncmp("ora_ckpt", comm, 7) == 0) && strncmp("/oradir", str(args->filename), 7) == 0/ 
   {time("====== %H:%M:%S ------ ");
    printf("comm=%s, pid=%d, filename ------\n%8s%s\n", comm, pid, "", str(args->filename));}
 tracepoint:syscalls:sys_enter_write /(strncmp("ora_lgwr", comm, 7) == 0 || strncmp("ora_ckpt", comm, 7) == 0) && strncmp("<",str(args->buf), 1) == 1/ 
   {time("====== %H:%M:%S ------ ");
    printf("comm=%s, pid=%d, fd=%d, BUF ------\n%s\n", comm, pid, args->fd, str(args->buf));}'
In Sqlplus window, run following SQL: 

--create table test_tab as select 1 x from dual; 

update tt1 set x = x + 1;
commit;
alter system switch logfile;
Back to Linux Window, we can see following output during around 5 minutes: 

Attaching 2 probes...

====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/alert/log.xml
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/trace/alert_testdb.log
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, fd=8, BUF ------
2024-11-04T11:03:36.681460+01:00
Beginning log switch checkpoint up to RBA [0x8b.2.10], SCN: 13022649669494

====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/alert/log.xml
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/trace/alert_testdb.log
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, fd=8, BUF ------
2024-11-04T11:03:36.681565+01:00
Thread 1 advanced to log sequence 139 (LGWR switch),  current SCN: 13022649669494

====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/alert/log.xml
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/trace/alert_testdb.log
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, fd=8, BUF ------
  Current log# 3 seq# 139 mem# 0: /oratestdb/oradata/testdb/redo03.dbf

====== 11:08:39 ------ comm=ora_ckpt_testdb, pid=1926186, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/alert/log.xml
====== 11:08:39 ------ comm=ora_ckpt_testdb, pid=1926186, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/trace/alert_testdb.log
====== 11:08:39 ------ comm=ora_ckpt_testdb, pid=1926186, fd=10, BUF ------
2024-11-04T11:08:39.613734+01:00
Completed checkpoint up to RBA [0x8b.2.10], SCN: 13022649669494
Both LGWR and CKPT write to DIAG "log.xml" and alert.log (xml content in "log.xml" are filtered out).
LGWR records redo log activities at beginning (11:03:36), and only after about 5 minutes,
CKPT sends "Completed checkpoint" (11:08:39) with same "RBA [0x8b.2.10]".

If we look redo logs immediately after switch logfile, the current one is marked with log switch timestamp (11:03): 

oracle@testdb:testdb > ls -ltr /oratestdb/oradata/testdb/redo*
-rw-r----- 1 oracle dba 1073742336 Nov  4 10:19 /oratestdb/oradata/testdb/redo04.dbf
-rw-r----- 1 oracle dba 1073742336 Nov  4 10:21 /oratestdb/oradata/testdb/redo01.dbf
-rw-r----- 1 oracle dba 1073742336 Nov  4 11:03 /oratestdb/oradata/testdb/redo03.dbf
-rw-r----- 1 oracle dba 1073742336 Nov  4 11:03 /oratestdb/oradata/testdb/redo02.dbf
As tested, the 5 minutes is an upper limit and controlled by the default 300 seconds of "_selftune_checkpointing_lag".

If we change it as (require DB restart): 

alter system set "_selftune_checkpointing_lag"=60 scope=spfile;
The "Completed checkpoint" is written after 1 minutes.

If we disable the Self-tune by (require DB restart): 

alter system set "_disable_selftune_checkpointing"=true scope=spfile;
CKPT will no more write "Completed checkpoint" in alert.log.

Of course, if we want to watch "Completed checkpoint", we can force a checkpoint by: 

alter system checkpoint;
Posted by at

Sunday, October 20, 2024

Find the skipped rows in select for update skip locked

This Blog will make a test to show how to find the skipped rows when running "select for update skip locked".
It first gets the number of skipped rows, and lists all the skipped rows as well.
We also give a workaround for delete skip locked.

Then we explore one unexpected Oracle behaviour of analytic function with skip locked in finding the skipped rows.

Note: Tested in Oracle 19.24.


1. Test Setup


We create one test table and one procedure to detect skipped rows. 

drop table test_upd_tab;

create table test_upd_tab as select level x, -level y from dual connect by level <= 10;

create index test_upd_tab_idx_1 on test_upd_tab(x);

exec dbms_stats.gather_table_stats('K', 'TEST_UPD_TAB', cascade=>true);

--drop type test_upd_tab_set force;
--drop type test_upd_tab_row force;

create or replace type test_upd_tab_row as object (x number, y number, vsum number, rcnt number, rnum number);
/

create or replace type test_upd_tab_set is table of test_upd_tab_row;
/

create or replace procedure test_update_skip_locked(p_start number, p_end number) as
  l_row_set_upd     test_upd_tab_set;
  l_updatable_rows  number;
  l_sql_text        varchar2(4000);
  l_xid             varchar2(50);
  l_start_scn       number;
  l_start_date      date;
  l_row_set_start  test_upd_tab_set;
begin
  select /*+ index(t test_upd_tab_idx_1) GATHER_PLAN_STATISTICS MONITOR test_ks_2 */ test_upd_tab_row(x, y, 0, 0, 0)
    bulk collect into l_row_set_upd
    from test_upd_tab t where x between p_start and p_end for update skip locked;
  
  dbms_output.put_line(rpad('=', 100, '='));
  dbms_output.put_line('Selected to Update  Rows#: '||sql%rowcount);
  dbms_output.put_line('Returned to Update  Rows#: '||l_row_set_upd.count());
  dbms_output.put_line(rpad('=', 100, '='));

  for c in (
    with sq as (select * from v$sql_plan_monitor 
                 where sql_id in (select sql_id from v$sql_monitor 
                                   where lower(sql_text) like 'select%test_ks_2%' and sid = sys_context('userenv', 'sid')))
    select sql_id, sid, sql_exec_start, plan_line_id, plan_operation, output_rows from sq 
     where sql_exec_id = (select max(sql_exec_id) from sq) and plan_line_id in (1, 2) order by plan_line_id)
  loop
    case 
      when c.plan_line_id = 1 then
        l_updatable_rows := c.output_rows;
        select sql_text into l_sql_text from v$sql where sql_id = c.sql_id and rownum = 1;
        dbms_output.put_line('Session: '||c.sid||', at: '||c.sql_exec_start||', run SQL_ID: '||c.sql_id);
        dbms_output.put_line('sql_text: '||l_sql_text);
        dbms_output.put_line(rpad('=', 100, '='));
        
      when c.plan_line_id = 2 then
        dbms_output.put_line('Found     Rows#: '||c.output_rows);
        dbms_output.put_line('Updatable Rows#: '||l_updatable_rows);
        dbms_output.put_line('Skipped   Rows#: '||(c.output_rows - l_updatable_rows));
    end case;
  end loop;

  select xid, start_scn, start_date into l_xid, l_start_scn, l_start_date
    from  v$transaction t
   where (xidusn||'.'||xidslot||'.'||xidsqn) = dbms_transaction.local_transaction_id;
       
  dbms_output.put_line(rpad('=', 100, '='));
  dbms_output.put_line('XID = '||l_xid||', Start_SCN = '||l_start_scn||', Start_Date = '||l_start_date);
  
  select /*+ GATHER_PLAN_STATISTICS MONITOR test_ks_3 */ test_upd_tab_row(x, y, 0, 0, 0)
    bulk collect into l_row_set_start
    from test_upd_tab as of scn l_start_scn where x between p_start and p_end;

  dbms_output.put_line(rpad('=', 100, '='));
  dbms_output.put_line('Selected at Start  Rows#: '||SQL%ROWCOUNT);
  dbms_output.put_line('Returned at Start  Rows#: '||l_row_set_start.count());
  dbms_output.put_line(rpad('=', 42, '=')||' Skip Locked Rows '||rpad('=', 42, '='));
  dbms_output.put_line(rpad('X', 8, ' ')||rpad('Y', 8, ' '));
  dbms_output.put_line(rpad('-', 8, '-')||rpad('-', 8, '-'));
  
  for c in (select * from table(l_row_set_start) minus select * from table(l_row_set_upd) order by 1)
  loop
    dbms_output.put_line(rpad(c.x, 8, ' ')||rpad(c.y, 8, ' '));
  end loop;
end;
/


2. Test Run


We open two Sqlplus sessions, and make following test.


2.1 Session_1


We first lock 3 rows with x between 5 and 7 in Session_1: 

------------ Session_1@T1, lock 3 rows ------------

SQL > select * from test_upd_tab t where x between 5 and 7 for update skip locked;

               X          Y
      ---------- ----------
               5         -5
               6         -6
               7         -7


2.2 Session_2


In Session_2, we are trying to lock 8 rows with x between 2 and 9.
The output shows that there are 8 rows found, but only 5 are updatable since 3 (=8-5) rows are locked by Session_1.
Then we list all 3 skipped rows. 

------------ Session_2@T2, Print the number of skipped lock rows, and skip locked rows ------------

alter session set nls_date_format ='YYYY-MM-DD HH24:MI:SS'; 

SQL > exec test_update_skip_locked(2, 9);

      ====================================================================================================
      Selected to Update  Rows#: 5
      Returned to Update  Rows#: 5
      ====================================================================================================
      Session: 553, at: 2024-10-22 05:44:44, run SQL_ID: 14bm0y4afwr9u
      sql_text: SELECT /*+ index(t test_upd_tab_idx_1) GATHER_PLAN_STATISTICS MONITOR test_ks_2 */ TEST_UPD_TAB_ROW(X, Y, 0, 0, 0) 
                FROM TEST_UPD_TAB T WHERE X BETWEEN :B2 AND :B1 FOR UPDATE SKIP LOCKED
      ====================================================================================================
      Found     Rows#: 8
      Updatable Rows#: 5
      Skipped   Rows#: 3
      ====================================================================================================
      XID = 5800010042A60100, Start_SCN = 13106847731835, Start_Date = 2024-10-22 05:44:44
      ====================================================================================================
      Selected at Start  Rows#: 8
      Returned at Start  Rows#: 8
      ========================================== Skip Locked Rows ==========================================
      X       Y
      ----------------
      5       -5
      6       -6
      7       -7
Here the SQL Monitoring Report: 

select sys.dbms_sqltune.report_sql_monitor('14bm0y4afwr9u', report_level=>'all' , type=>'TEXT') from dual; 

   SQL Text
   ------------------------------
   SELECT /*+ index(t test_upd_tab_idx_1) GATHER_PLAN_STATISTICS MONITOR test_ks_2 */ TEST_UPD_TAB_ROW(X, Y, 0, 0, 0) 
   FROM TEST_UPD_TAB T WHERE X BETWEEN :B2 AND :B1 FOR UPDATE SKIP LOCKED
   
   SQL ID                                 :  14bm0y4afwr9u 
    
   Binds
   ========================================================================================================================
   | Name | Position |  Type  |                                           Value                                           |
   ========================================================================================================================
   | :B2  |        1 | NUMBER | 2                                                                                         |
   | :B1  |        2 | NUMBER | 9                                                                                         |
   ========================================================================================================================
   
   Global Stats
   ======================================
   | Elapsed |   Cpu   | Fetch | Buffer |
   | Time(s) | Time(s) | Calls |  Gets  |
   ======================================
   |    0.00 |    0.00 |     1 |     28 |
   ======================================
   
   SQL Plan Monitoring Details (Plan Hash Value=1755639989)
   ===========================================================================================================================================================
   | Id |                Operation                |        Name        |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Activity | Activity Detail |
   |    |                                         |                    | (Estim) |      | Active(s) | Active |       | (Actual) |   (%)    |   (# samples)   |
   ===========================================================================================================================================================
   |  0 | SELECT STATEMENT                        |                    |         |      |         1 |     +0 |     1 |        5 |          |                 |
   |  1 |   FOR UPDATE                            |                    |         |      |         1 |     +0 |     1 |        5 |          |                 |
   |  2 |    FILTER                               |                    |         |      |         1 |     +0 |     1 |        8 |          |                 |
   |  3 |     TABLE ACCESS BY INDEX ROWID BATCHED | TEST_UPD_TAB       |      10 |    1 |         1 |     +0 |     1 |        8 |          |                 |
   |  4 |      INDEX RANGE SCAN                   | TEST_UPD_TAB_IDX_1 |      10 |    1 |         1 |     +0 |     1 |        8 |          |                 |
   ===========================================================================================================================================================


3. Delete skip locked


Oracle does not support "delete skip locked" (error: ORA-00933: SQL command not properly ended). We can have a workaround if we run following code in Session_2: 

------------ Session_2@T2, delete skip locked rows ------------

declare
  p_start           number := 2;
  p_end             number := 9;
  l_row_set_upd     test_upd_tab_set;
  l_row_set_del     test_upd_tab_set;
begin
  select /*+ index(t test_upd_tab_idx_1) GATHER_PLAN_STATISTICS MONITOR test_ks_2 */ test_upd_tab_row(x, y, 0, 0, 0)
    bulk collect into l_row_set_upd
    from test_upd_tab t where x between p_start and p_end for update skip locked;
    
  delete from test_upd_tab 
   where x between p_start and p_end 
     and x in (select x from table(l_row_set_upd))
   returning test_upd_tab_row(x, y, 0, 0, 0) bulk collect into l_row_set_del;
   
  dbms_output.put_line(rpad('=', 42, '=')||' Delete skip locked rows '||rpad('=', 42, '='));
  dbms_output.put_line(rpad('X', 8, ' ')||rpad('Y', 8, ' '));
  dbms_output.put_line(rpad('-', 8, '-')||rpad('-', 8, '-'));
  
  for c in (select * from table(l_row_set_del) order by 1)
  loop
    dbms_output.put_line(rpad(c.x, 8, ' ')||rpad(c.y, 8, ' '));
  end loop;
  
  dbms_output.put_line('');
  dbms_output.put_line(l_row_set_del.count()||' rows deleted.');
end;
/
Here the output: 

========================================== Delete skip locked rows ==========================================
X       Y
----------------
2       -2
3       -3
4       -4
8       -8
9       -9


4. Using Oracle behaviour of analytic function with skip locked


When facing question: "Is there a way to get the data of the rows that were skipped ?",
Solomon Yakobson (Feb 22 2018) in Oracle Forums: For Update Skip Locked (https://forums.oracle.com/ords/apexds/post/for-update-skip-locked-6618)
revealed one related Oracle behaviour of analytic function with skip locked.


4.1. Test of analytic function with skip locked


Here the test and all output, which shows locked row data will be included in analytic function related calculations of VAL_SUM, ROW_NUM.
(at first rollback all transactions in Session_1 and Session_2) 

------------- Session_1@T1, Test Setup and one row update -------------

drop table test_skip_tab;

create table test_skip_tab as select level id, 100 val from dual connect by level <= 3;

select * from test_skip_tab;

update test_skip_tab set val = val where id = 2;

select sum(val), count(*) from test_skip_tab;

  SUM(VAL)   COUNT(*)
---------- ----------
       300          3

select t.*, sum (val) over () val_sum, count (*) over () row_cnt,  row_number() over (order by id) row_num from test_skip_tab t;

        ID        VAL    VAL_SUM    ROW_CNT    ROW_NUM
---------- ---------- ---------- ---------- ----------
         1        100        300          3          1
         2        100        300          3          2
         3        100        300          3          3

------------- Session_2@T2, look VAL_SUM, ROW_NUM -------------

select t.*, sum (val) over () val_sum, count (*) over () row_cnt,  row_number() over (order by id) row_num from test_skip_tab t for update skip locked;

        ID        VAL    VAL_SUM    ROW_CNT    ROW_NUM
---------- ---------- ---------- ---------- ----------
         1        100        300          3          1
         3        100        300          3          3

------------- Session_1@T3, look VAL_SUM, ROW_NUM -------------

select t.*, sum (val) over () val_sum, count (*) over () row_cnt,  row_number() over (order by id) row_num from test_skip_tab t for update skip locked;

        ID        VAL    VAL_SUM    ROW_CNT    ROW_NUM
---------- ---------- ---------- ---------- ----------
         2        100        300          3          2


4.2. Use unexpected behaviour to in find the skipped rows.


Similar to Section 1 Test Setup, we first code one Plsql procedure: 

create or replace procedure test_update_skip_locked_2(p_start number, p_end number) as
  l_row_set_upd     test_upd_tab_set;
  l_updatable_rows  number;
  l_sql_text        varchar2(4000);
  l_xid             varchar2(50);
  l_start_scn       number;
  l_start_date      date;
  l_row_set_start   test_upd_tab_set;
  l_cnt             number;
begin
  select /*+ index(t test_upd_tab_idx_1) GATHER_PLAN_STATISTICS MONITOR test_ks_2b */ 
    test_upd_tab_row(x, y, sum (1) over (), count (1) over (), row_number() over (order by x))
    bulk collect into l_row_set_upd
    from test_upd_tab t where x between p_start and p_end for update skip locked;
  
  dbms_output.put_line(rpad('=', 100, '='));
  dbms_output.put_line('Selected to Update  Rows#: '||sql%rowcount);
  dbms_output.put_line('Returned to Update  Rows#: '||l_row_set_upd.count());
  dbms_output.put_line(rpad('=', 100, '='));

  dbms_output.put_line('Found     Rows#: '||l_row_set_upd(1).rcnt);
  dbms_output.put_line('Updatable Rows#: '||l_row_set_upd.count);
  dbms_output.put_line('Skipped   Rows#: '||(l_row_set_upd(1).rcnt - l_row_set_upd.count));
  
  dbms_output.put_line(rpad('=', 100, '='));
  for c in (select level  + (p_start-1) rnum from dual connect by level <= l_row_set_upd(1).rcnt
            minus
            select t.rnum + (p_start-1) rnum from table(l_row_set_upd) t
            )
  loop
    dbms_output.put_line('Skipped Row Number: '||c.rnum);
  end loop;

  select xid, start_scn, start_date into l_xid, l_start_scn, l_start_date
    from  v$transaction t
   where (xidusn||'.'||xidslot||'.'||xidsqn) = dbms_transaction.local_transaction_id;
       
  dbms_output.put_line(rpad('=', 100, '='));
  dbms_output.put_line('XID = '||l_xid||', Start_SCN = '||l_start_scn||', Start_Date = '||l_start_date);
  
  select /*+ GATHER_PLAN_STATISTICS MONITOR test_ks_3b */ 
    test_upd_tab_row(x, y, sum (1) over (), count (1) over (), row_number() over (order by x))
    bulk collect into l_row_set_start
    from test_upd_tab as of scn l_start_scn where x between p_start and p_end;

  dbms_output.put_line(rpad('=', 100, '='));
  dbms_output.put_line('Selected at Start  Rows#: '||SQL%ROWCOUNT);
  dbms_output.put_line('Returned at Start  Rows#: '||l_row_set_start.count());
  dbms_output.put_line(rpad('=', 42, '=')||' Skip Locked Rows '||rpad('=', 42, '='));
  dbms_output.put_line(rpad('X', 8, ' ')||rpad('Y', 8, ' '));
  dbms_output.put_line(rpad('-', 8, '-')||rpad('-', 8, '-'));
  
  for c in (select * from table(l_row_set_start) minus select * from table(l_row_set_upd) order by 1)
  loop
    dbms_output.put_line(rpad(c.x, 8, ' ')||rpad(c.y, 8, ' '));
  end loop;  
end;
/


4.3 Session_1 Test


We first lock 3 rows with x between 5 and 7 in Session_1:
(at first rollback all transactions in Session_1 and Session_2) 

------------ Session_1@T1, lock 3 rows ------------

SQL > select * from test_upd_tab t where x between 5 and 7 for update skip locked;

               X          Y
      ---------- ----------
               5         -5
               6         -6
               7         -7


4.4 Session_2 Test


In Session_2, we are trying to lock 8 rows with x between 2 and 9.
The output shows that there are 8 rows found, but only 5 are updatable since 3 (=8-5) rows are locked by Session_1.
Then we list all 3 skipped rows. 

------------ Session_2@T2, Print the number of skipped lock rows, and skip locked rows ------------

alter session set nls_date_format ='YYYY-MM-DD HH24:MI:SS'; 

SQL > exec test_update_skip_locked_2(2, 9);

====================================================================================================
Selected to Update  Rows#: 5
Returned to Update  Rows#: 5
====================================================================================================
Found     Rows#: 8
Updatable Rows#: 5
Skipped   Rows#: 3
====================================================================================================
Skipped Row Number: 5
Skipped Row Number: 6
Skipped Row Number: 7
====================================================================================================
XID = 5F00140055F40100, Start_SCN = 13106847744696, Start_Date = 2024-10-22 10:16:57
====================================================================================================
Selected at Start  Rows#: 8
Returned at Start  Rows#: 8
========================================== Skip Locked Rows ==========================================
X       Y
----------------
5       -5
6       -6
7       -7


5. Related Work


Rob van Wijk (February 7, 2009) in Blog: FOR UPDATE SKIP LOCKED (http://rwijk.blogspot.com/2009/02/for-update-skip-locked.html) showed:
(1). opening a cursor with the "for update skip locked" clause doesn't lock a single row. Fetching a row does lock the row.
(2). a "for update skip locked" doesn't only skip the locked rows, it also skips the rows that were modified between the opening and the fetching, thus avoiding the classic "lost update".
Posted by at

Sunday, September 22, 2024

One OracleJVM TIME_MODEL Test

In this Blog, we will make 5 different scenario tests of Java Stored Procedure running in Oracle RDBMS embedded JVM, and collect their stats from Oracle V$SESS_TIME_MODEL and V$SYS_TIME_MODEL.

Note: Tested in Oracle 19.24 with single user session.


1. Test Run


We run 5 different Scenarios (see Blog appended Test Code), each for 100 seconds. 

  set serveroutput on size 50000
  -- Enable java println output on Sqlplus Window
  exec dbms_java.set_output(50000);   

  exec TestOraJvmRun2_call(plsqlSleepSeconds=> 100);
  exec TestOraJvmRun2_call(plsqlRunSeconds=> 100);    
  exec TestOraJvmRun2_call(javaPlsqlMixRunSeconds=> 100);
  exec TestOraJvmRun2_call(javaSleepSeconds=> 100);
  exec TestOraJvmRun2_call(javaRunSeconds=> 100);


2. Test Output



2.1 plsqlSleepSeconds 



SQL >  exec TestOraJvmRun2_call(plsqlSleepSeconds=> 100);

***** TestOraJvmRun2: plsqlSleepSeconds = 100, plsqlRunSeconds = 0, javaPlsqlMixRunSeconds = 0, javaSleepSeconds = 0, javaRunSeconds = 0

====== 1 Start plsqlSleepSeconds  ========= at 16:09:06.699
====== 1   End plsqlSleepSeconds  ========= at 16:10:47.252

====== 2 Start plsqlRunSeconds  ========= at 16:10:47.252
====== 2   End plsqlRunSeconds  ========= at 16:10:47.253

====== 3 Start javaPlsqlMixRunSeconds  ========= at 16:10:47.253
====== 3   End javaPlsqlMixRunSeconds  ========= at 16:10:47.253

====== 4 Start javaSleepSeconds  ========= at 16:10:47.255
====== 4   End javaSleepSeconds  ========= at 16:10:47.255

====== 5 Start javaRunSeconds  ========= at 16:10:47.255
====== 5   End javaRunSeconds  ========= at 16:10:47.255

============================================================
SESS_TIME_MODEL-stat_name (Sid=374, Run=1)               val
------------------------------------------------------------
DB time                                                 1.04
sql execute elapsed time                                1.03

============================================================
SYS_TIME_MODEL-stat_name                                 val
------------------------------------------------------------
background elapsed time                                 3.00
background cpu time                                     2.12
DB time                                                 1.04
sql execute elapsed time                                1.04

Elapsed: 00:01:41.23


2.2 plsqlRunSeconds 



SQl >  exec TestOraJvmRun2_call(plsqlRunSeconds=> 100);

***** TestOraJvmRun2: plsqlSleepSeconds = 0, plsqlRunSeconds = 100, javaPlsqlMixRunSeconds = 0, javaSleepSeconds = 0, javaRunSeconds = 0

====== 1 Start plsqlSleepSeconds  ========= at 16:10:47.457
====== 1   End plsqlSleepSeconds  ========= at 16:10:47.458

====== 2 Start plsqlRunSeconds  ========= at 16:10:47.458
====== 2   End plsqlRunSeconds  ========= at 16:12:27.515

====== 3 Start javaPlsqlMixRunSeconds  ========= at 16:12:27.516
====== 3   End javaPlsqlMixRunSeconds  ========= at 16:12:27.516

====== 4 Start javaSleepSeconds  ========= at 16:12:27.516
====== 4   End javaSleepSeconds  ========= at 16:12:27.516

====== 5 Start javaRunSeconds  ========= at 16:12:27.516
====== 5   End javaRunSeconds  ========= at 16:12:27.516

============================================================
SESS_TIME_MODEL-stat_name (Sid=374, Run=2)               val
------------------------------------------------------------
DB time                                                99.81
sql execute elapsed time                               99.81
DB CPU                                                 99.38
PL/SQL execution elapsed time                          54.10

============================================================
SYS_TIME_MODEL-stat_name                                 val
------------------------------------------------------------
DB time                                                99.81
sql execute elapsed time                               99.81
DB CPU                                                 99.38
PL/SQL execution elapsed time                          54.10
background elapsed time                                50.32
background cpu time                                    18.25

Elapsed: 00:01:40.11


2.3 javaPlsqlMixRunSecond 



SQL >  exec TestOraJvmRun2_call(javaPlsqlMixRunSeconds=> 100);

***** TestOraJvmRun2: plsqlSleepSeconds = 0, plsqlRunSeconds = 0, javaPlsqlMixRunSeconds = 100, javaSleepSeconds = 0, javaRunSeconds = 0

====== 1 Start plsqlSleepSeconds  ========= at 16:12:27.578
====== 1   End plsqlSleepSeconds  ========= at 16:12:27.579

====== 2 Start plsqlRunSeconds  ========= at 16:12:27.579
====== 2   End plsqlRunSeconds  ========= at 16:12:27.579

====== 3 Start javaPlsqlMixRunSeconds  ========= at 16:12:27.579
====== 3   End javaPlsqlMixRunSeconds  ========= at 16:14:07.698

====== 4 Start javaSleepSeconds  ========= at 16:14:07.698
====== 4   End javaSleepSeconds  ========= at 16:14:07.698

====== 5 Start javaRunSeconds  ========= at 16:14:07.698
====== 5   End javaRunSeconds  ========= at 16:14:07.698

============================================================
SESS_TIME_MODEL-stat_name (Sid=374, Run=3)               val
------------------------------------------------------------
DB time                                                99.75
sql execute elapsed time                               99.75
Java execution elapsed time                            52.99
DB CPU                                                 51.92
PL/SQL execution elapsed time                          19.07

============================================================
SYS_TIME_MODEL-stat_name                                 val
------------------------------------------------------------
DB time                                                99.74
sql execute elapsed time                               99.74
background elapsed time                                68.16
Java execution elapsed time                            52.99
DB CPU                                                 51.91
PL/SQL execution elapsed time                          19.07
background cpu time                                    16.64

Elapsed: 00:01:40.17


2.4 javaSleepSeconds 



SQL > exec TestOraJvmRun2_call(javaSleepSeconds=> 100);

***** TestOraJvmRun2: plsqlSleepSeconds = 0, plsqlRunSeconds = 0, javaPlsqlMixRunSeconds = 0, javaSleepSeconds = 100, javaRunSeconds = 0

====== 1 Start plsqlSleepSeconds  ========= at 16:14:07.757
====== 1   End plsqlSleepSeconds  ========= at 16:14:07.758

====== 2 Start plsqlRunSeconds  ========= at 16:14:07.758
====== 2   End plsqlRunSeconds  ========= at 16:14:07.758

====== 3 Start javaPlsqlMixRunSeconds  ========= at 16:14:07.758
====== 3   End javaPlsqlMixRunSeconds  ========= at 16:14:07.758

====== 4 Start javaSleepSeconds  ========= at 16:14:07.758
====== 4   End javaSleepSeconds  ========= at 16:15:47.759

====== 5 Start javaRunSeconds  ========= at 16:15:47.759
====== 5   End javaRunSeconds  ========= at 16:15:47.759

============================================================
SESS_TIME_MODEL-stat_name (Sid=374, Run=4)               val
------------------------------------------------------------
sql execute elapsed time                              100.01
DB time                                               100.00
Java execution elapsed time                           100.00

============================================================
SYS_TIME_MODEL-stat_name                                 val
------------------------------------------------------------
DB time                                               100.01
sql execute elapsed time                              100.01
Java execution elapsed time                           100.00
background elapsed time                                 1.80
background cpu time                                     1.71

Elapsed: 00:01:40.05


2.5 javaRunSeconds 



SQL > exec TestOraJvmRun2_call(javaRunSeconds=> 100);

***** TestOraJvmRun2: plsqlSleepSeconds = 0, plsqlRunSeconds = 0, javaPlsqlMixRunSeconds = 0, javaSleepSeconds = 0, javaRunSeconds = 100

====== 1 Start plsqlSleepSeconds  ========= at 16:15:47.819
====== 1   End plsqlSleepSeconds  ========= at 16:15:47.820

====== 2 Start plsqlRunSeconds  ========= at 16:15:47.820
====== 2   End plsqlRunSeconds  ========= at 16:15:47.820

====== 3 Start javaPlsqlMixRunSeconds  ========= at 16:15:47.820
====== 3   End javaPlsqlMixRunSeconds  ========= at 16:15:47.820

====== 4 Start javaSleepSeconds  ========= at 16:15:47.820
====== 4   End javaSleepSeconds  ========= at 16:15:47.820

====== 5 Start javaRunSeconds  ========= at 16:15:47.820
====== 5   End javaRunSeconds  ========= at 16:17:27.820

============================================================
SESS_TIME_MODEL-stat_name (Sid=374, Run=5)               val
------------------------------------------------------------
DB time                                               100.01
Java execution elapsed time                           100.01
sql execute elapsed time                              100.01
DB CPU                                                 99.56

============================================================
SYS_TIME_MODEL-stat_name                                 val
------------------------------------------------------------
sql execute elapsed time                              100.01
DB time                                               100.00
Java execution elapsed time                           100.00
DB CPU                                                 99.56
background elapsed time                                 3.74
background cpu time                                     2.17

Elapsed: 00:01:40.05


3. Test Code



3.1 Plsql Code 



create table test_tab_1 as select 1 k, 1234 val from dual;

create or replace procedure plsql_run(p_run number := 1e3) as
  l_x          number;
begin
  for f in 1..p_run loop
    update test_tab_1 set val = mod (l_x, p_run/10);
    commit;
  end loop;
  
  for f in 1..p_run*100 loop
    l_x := mod (l_x, p_run) + sqrt (f);
  end loop;
end;
/

-- exec plsql_run(1e3);

create or replace procedure plsql_run_seconds(p_run_sec number := 30) as
  l_x          number;
  l_start_time number := dbms_utility.get_time;
begin
  --dbms_session.sleep(p_sleep_sec);
  
  while ((dbms_utility.get_time - l_start_time)/100 < p_run_sec) loop 
    plsql_run(1e3);
  end loop;
end;
/

-- exec plsql_run_seconds(3);


3.2 Java Stored Procedure 



create or replace and compile java source named "TestOraJvmRun2" as
import java.io.*;
import java.sql.*;
import java.text.SimpleDateFormat;
import oracle.jdbc.OracleDriver;
public class TestOraJvmRun2
{
  public static String proc(String testName, int plsqlSleepSeconds, int plsqlRunSeconds, int javaPlsqlMixRunSeconds, int javaSleepSeconds, int javaRunSeconds) throws SQLException
  {
    String exceptMessage = "No Exception";
    String test_title = ("\n***** "+ testName + 
                                  ": plsqlSleepSeconds = "      + plsqlSleepSeconds +
                                  ", plsqlRunSeconds = "        + plsqlRunSeconds +
                                  ", javaPlsqlMixRunSeconds = " + javaPlsqlMixRunSeconds    + 
                                  ", javaSleepSeconds = "       + javaSleepSeconds  +
                                  ", javaRunSeconds = "         + javaRunSeconds);
    System.out.println(test_title);
    
    try {
      Connection connection = new OracleDriver().defaultConnection();
      CallableStatement cstmt;
      
      System.out.println("\n====== 1 Start plsqlSleepSeconds  ========= at " + java.time.LocalDateTime.now());
      cstmt = connection.prepareCall("begin dbms_session.sleep(?); end;");
      cstmt.setInt(1, plsqlSleepSeconds);
      cstmt.execute();
      cstmt.close();
      System.out.println("====== 1   End plsqlSleepSeconds  ========= at " + java.time.LocalDateTime.now());
      
      System.out.println("\n====== 2 Start plsqlRunSeconds  ========= at " + java.time.LocalDateTime.now());
      cstmt = connection.prepareCall("begin plsql_run_seconds(?); end;");
      cstmt.setInt(1, plsqlRunSeconds);
      cstmt.execute();
      cstmt.close();
      System.out.println("====== 2   End plsqlRunSeconds  ========= at " + java.time.LocalDateTime.now());
      
      System.out.println("\n====== 3 Start javaPlsqlMixRunSeconds  ========= at " + java.time.LocalDateTime.now());
      long sleepOneSecond = 1000*1000000L; // convert 1 second to nanoseconds
      long startTime;
      for (int i = 0; i < javaPlsqlMixRunSeconds; i++) {    // java loop calling plsql
          startTime = System.nanoTime();
          while ((System.nanoTime() - startTime) < sleepOneSecond) 
            {try {
                 cstmt = connection.prepareCall("begin plsql_run(1e1); end;");
                 Thread.sleep(1);
                 cstmt.execute();
                 cstmt.close();
                 } catch (Exception e) {
            	       exceptMessage = e.toString();
            	       //System.out.println(e);
                 }
            }
      }
      System.out.println("====== 3   End javaPlsqlMixRunSeconds  ========= at " + java.time.LocalDateTime.now());

      System.out.println("\n====== 4 Start javaSleepSeconds  ========= at " + java.time.LocalDateTime.now());
      {try {
            Thread.sleep(javaSleepSeconds*1000);
           } catch (Exception e) {
            	 exceptMessage = e.toString();
            	 //System.out.println(e);
           }
      }
      System.out.println("====== 4   End javaSleepSeconds  ========= at " + java.time.LocalDateTime.now());
      
      System.out.println("\n====== 5 Start javaRunSeconds  ========= at " + java.time.LocalDateTime.now());
      for (int i = 0; i < javaRunSeconds; i++) {
          startTime = System.nanoTime();
          while ((System.nanoTime() - startTime) < sleepOneSecond) 
            {}
      }
      System.out.println("====== 5   End javaRunSeconds  ========= at " + java.time.LocalDateTime.now());
    } catch (Exception e) {
      e.printStackTrace();
    }
    return test_title;
  }
}
/


create or replace function TestOraJvmRun2_proc(testName varchar2, plsqlSleepSeconds number, plsqlRunSeconds number, 
                                               javaPlsqlMixRunSeconds number, javaSleepSeconds number, javaRunSeconds number) 
return varchar2 as language java
name 'TestOraJvmRun2.proc(java.lang.String, int, int, int, int, int) return String';
/


3.3 Plsql Test Call 



drop table test_run_tm_stat;

create table test_run_tm_stat as select 0 run, 0 seq, sysdate datetime, sid, stat_name, round(value/1e6, 2) val from  V$SESS_TIME_MODEL where 1=2; 

select * from test_run_tm_stat;

drop sequence TestOraJvmRun_seq;

create sequence TestOraJvmRun_seq;

create or replace procedure TestOraJvmRun2_call (testName VARCHAR2 :='TestOraJvmRun2', plsqlSleepSeconds number :=0, plsqlRunSeconds number :=0, 
                                                 javaPlsqlMixRunSeconds number :=0, javaSleepSeconds number :=0, javaRunSeconds number :=0) as
  l_run number := TestOraJvmRun_seq.nextval;
  l_sid number := sys_context('userenv','sid');
  l_wid number := 60;
  l_ret VARCHAR2(200);
begin
  insert into test_run_tm_stat 
    select l_run, 1, sysdate, sid, stat_name, round(value/1e6, 2) from V$SESS_TIME_MODEL where sid = l_sid order by value desc;
  insert into test_run_tm_stat 
    select l_run, 1, sysdate, -1, stat_name, round(value/1e6, 2) from V$SYS_TIME_MODEL;   -- sid = -1 for V$SYS_TIME_MODEL

  l_ret := TestOraJvmRun2_proc(testName, plsqlSleepSeconds, plsqlRunSeconds, javaPlsqlMixRunSeconds, javaSleepSeconds, javaRunSeconds);   -- sleep or run x seconds
  --dbms_output.put_line(l_ret);
  commit;
  
  insert into test_run_tm_stat 
    select l_run, 2, sysdate, sid, stat_name, round(value/1e6, 2) from V$SESS_TIME_MODEL where sid = l_sid order by value desc;
  insert into test_run_tm_stat 
    select l_run, 2, sysdate, -1, stat_name, round(value/1e6, 2) from V$SYS_TIME_MODEL;   -- sid = -1 for V$SYS_TIME_MODEL
  commit;

  dbms_output.put_line(chr(10)||rpad('=', l_wid, '='));
  dbms_output.put_line(rpad('SESS_TIME_MODEL-stat_name (Sid='||l_sid||', Run='||l_run||')', l_wid-10, ' ')||lpad('val', 10, ' '));
  dbms_output.put_line(rpad('-', l_wid, '-'));
  for c in 
    (select * from 
      (select run, seq, sid, stat_name, val-lag(val, 1) over(partition by stat_name order by run, seq) delta from test_run_tm_stat where run = l_run and sid > 0)
     where delta >= 1 and seq=2 order by delta desc, stat_name)
  loop
    dbms_output.put_line(rpad(c.stat_name, l_wid-10, ' ')||lpad(to_char(c.delta, '999.99'), 10, ' '));
  end loop;
  
  dbms_output.put_line(chr(10)||rpad('=', l_wid, '='));
  dbms_output.put_line(rpad('SYS_TIME_MODEL-stat_name', l_wid-10, ' ')||lpad('val', 10, ' '));
  dbms_output.put_line(rpad('-', l_wid, '-'));
  for c in 
    (select * from 
      (select run, seq, sid, stat_name, val-lag(val, 1) over(partition by stat_name order by run, seq) delta from test_run_tm_stat where run = l_run and sid = -1)
     where delta >= 1 and seq=2 order by delta desc, stat_name)
  loop
    dbms_output.put_line(rpad(c.stat_name, l_wid-10, ' ')||lpad(to_char(c.delta, '999.99'), 10, ' '));
  end loop;
end;
/
Posted by at
Subscribe to: Posts (Atom)