Tuesday, June 17, 2025

Blog List

Posted by at

ORA-01002: fetch out of sequence: One Case Test 


drop table test_tab;
 
create table test_tab (x number, y varchar2(100)); 

declare
  l_cnt number := 0;
begin
  execute immediate 'truncate table test_tab';
  insert into test_tab select level x, lpad('A', 90, 'B')||level from dual connect by level <= 500;
  
  for c in (select x, y from test_tab) loop
    l_cnt := l_cnt + 1;
    dbms_output.put_line(c.x);
    if c.x > 300 then
      rollback;
    end if;
  end loop;
  
  exception when others then
    dbms_output.put_line('Row CNT = '||l_cnt);
    raise;
end;
/

--------------- Test Output -----------------
310
311
312
313
Row CNT = 100
declare
*
ERROR at line 1:
ORA-01002: fetch out of sequence
ORA-06512: at line 17
ORA-06512: at line 7
ORA-06512: at line 7
For Temporary Table ORA-01002, see Blog: One Test on the Different Errors of Oracle Global Temporary Tables vs. Private Temporary Tables
(https://ksun-oracle.blogspot.com/2024/01/one-test-on-different-errors-of-oracle.html)
Posted by at

Friday, May 23, 2025

Oracle ORA-00600 [pfrsfm: stack mismatch] and [pfrsfm: stack mismatch] Reproducing

This Blog will demonstrate how to generate Oracle ORA-00600 [pfrsfm: stack mismatch] and [pfrsfm: stack mismatch].

Note: Tested on Oracle 19c


1. ORA-00600: internal error code, arguments: [pfrsfm: stack mismatch]


Open one Sqlplus window, start 400 Jobs to test (see Section 3. Test Code): 

  SQL > exec start_test(400, 1e4, 1e6, 0, 5);
During and after test (it takes about 15 minutes), check DB alert.log and incident files if they contain error text like: 

  ORA-00600: internal error code, arguments: [pfrsfm: stack mismatch]
If with 400 Jobs, it is not reproduced, increase it and re-run the test.

Here the incident file: 

ORA-00600: internal error code, arguments: [pfrsfm: stack mismatch], [0x7F1F08BB3BF8], [0xFFFFFFFFFFFFFFFF], [0x7F1F08506000], [0x7F1F08BB33F0], 
                                                                     [0xFFFFFFFFFFFFFFFF], [0xFFFFFFFFFFFFFFFF], [], [], [], [], []
ORA-27403: scheduler stop job event
ORA-27403: scheduler stop job event

========= Dump for incident 14217 (ORA 600 [pfrsfm: stack mismatch]) ========

----- Current SQL Statement for this session (sql_id=f44xkpcgqsatb) -----
SELECT * FROM TABLE(PIPELINE_TAB(:B1 , :B2 )) WHERE ROWNUM <= :B1 -5

----- Parser State -----
Parser state1: len1=0 len2=0 pos1=0 pos2=0
Parser state2: flg=0x0 xflg=0x0 xxflg=0x400
Parser state3: tty=0 tlen=0
Parser string: prx=0x7f1f0e8a9d60 base=(nil) cur=(nil)

----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x9def1680         5  procedure K.TEST_JOB_PROC
0x7e82e800         1  anonymous block

[TOC00006]
----- Call Stack Trace -----
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
dbgexProcessError()  call     dbgexPhaseII()       7F1F0E83B6D8 7F1F0E7ED1F0
+1872                                              7FFD1ED4C800 7FFD1ED450C8 ?
                                                   000000000 ? 000000000 ?
dbgePostErrorKGE()+  call     dbgexProcessError()  7F1F0E83B6D8 7F1F0E7ED1F0
1853                                               000000001 000000000
                                                   000000000 ? 000000000 ?
dbkePostKGE_kgsf()+  call     dbgePostErrorKGE()   7F1F0E87B9C0 7F1F08BB0050
71                                                 000000258 000000000 ?
                                                   000000000 ? 000000000 ?
kgeadse()+448        call     dbkePostKGE_kgsf()   7F1F0E87B9C0 7F1F08BB0050
                                                   000000258 000000000 ?
                                                   000000000 ? 000000000 ?
kgerinv_internal()+  call     kgeadse()            7F1F0E87B9C0 ? 7F1F08BB0050
44                                                 000000258 ? 016036C24
                                                   000000000 000000006
kgerinv()+40         call     kgerinv_internal()   7F1F0E87B9C0 ? 7F1F08BB0050 ?
                                                   000000258 ? 016036C24 ?
                                                   000000000 ? 000000006 ?
kgeasnmierr()+146    call     kgerinv()            7F1F0E87B9C0 ? 7F1F08BB0050 ?
                                                   000000258 ? 016036C24 ?
                                                   000000000 ? 000000006 ?
pfrsfm()+1233        call     kgeasnmierr()        7F1F0E87B9C0 ? 7F1F08BB0050 ?
                                                   000000258 ? 016036C24 ?
                                                   000000002 7F1F08BB3BF8
pfrspopstks()+103    call     pfrsfm()             7F1F0E87B9C0 ? 7F1F08BB0050 ?
                                                   000000258 ? 016036C24 ?
                                                   000000002 ? 7F1F08BB3BF8 ?
kksumc()+526         call     pfrspopstks()        7F1F0E87B9C0 ? 7F1F08507910
                                                   000000258 ? 016036C24 ?
                                                   000000002 ? 7F1F08BB3BF8 ?
opiodr()+4705        call     kksumc()             7F1F0864F5C8 000000005


2. ORA-00600: internal error code, arguments: [pfrsfm: Stack disordered]


Open one Sqlplus window, start test by: 

SQL>  exec test_job_proc(1, 1e4, 1e6, 0, 5);
Get its session SPID (1055599) and its (sid, serial#) = (915.49648).

In UNIX Terminal, run kill command: 

  kill -URG 1055599
or In another Sqlplus window, run cancel statement: 

  alter system cancel sql '915,49648';
(see Blog:
   How to CANCEL a query running in another session? (https://tanelpoder.com/2010/02/17/how-to-cancel-a-query-running-in-another-session/)
   DBMS_SCHEDULER Job Not Running and Used Slaves (https://ksun-oracle.blogspot.com/2021/01/dbmsscheduler-job-not-running-and-used.html)
)

You will see either: 

SQL>  exec test_job_proc(1, 1e4, 1e6, 0, 5);
BEGIN test_job_proc(1, 1e4, 1e6, 0, 5); END;

*
ERROR at line 1:
ORA-01013: user requested cancel of current operation
or 

SQL>  exec test_job_proc(1, 1e4, 1e6, 0, 5);
BEGIN test_job_proc(1, 1e4, 1e6, 0, 5); END;

*
ERROR at line 1:
ORA-00603: ORACLE server session terminated by fatal error
ORA-24557: error 600 encountered while handling error 1013; exiting server
process
ORA-00600: internal error code, arguments: [pfrsfm: Stack disordered],
[0x7F0FE0BA14F8], [0x7F0FE0BA22F0], [0x7F0FE0BA1850], [0x7F0FE0BA34F8], [], [],
[], [], [], [], []
ORA-01013: user requested cancel of current operation
Process ID: 1055599
Session ID: 915 Serial number: 49648
If it is the first case, in the same Oracle session (ORA-01013 does not terminate session), re-run: 

   exec test_job_proc(1, 1e4, 1e6, 0, 5);
re-run UNIX kill command or SQL cancel statement.

Repeat above steps till the session hit "ORA-00600: [pfrsfm: Stack disordered]".

Then the session incident file shows: 

ORA-00600: internal error code, arguments: [pfrsfm: Stack disordered], [0x7F0FE0BA14F8], [0x7F0FE0BA22F0], [0x7F0FE0BA1850], [0x7F0FE0BA34F8], 
                                                                       [], [], [], [], [], [], []
ORA-01013: user requested cancel of current operation

========= Dump for incident 11485 (ORA 600 [pfrsfm: Stack disordered]) ========

*** 2025-05-20T09:54:22.541566+02:00
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
[TOC00003]
----- Current SQL Statement for this session (sql_id=b7vzj4s3qw97g) -----
SELECT * FROM TABLE(GET_TAB_PTF(:B1 , :B2 )) WHERE ROWNUM <= :B1 -5
[TOC00004]
----- Parser State -----
Parser state1: len1=0 len2=36 pos1=0 pos2=5
Parser state2: flg=0x0 xflg=0x4300000 xxflg=0x400
Parser state3: tty=0 tlen=5
Parser string: prx=0x7f0fe6887d60 base=(nil) cur=0x7ffce65bdbed

----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0xa0fb7940         5  procedure K.TEST_ORA_600_DISCONNET
0x95391e58         1  anonymous block

----- Call Stack Trace -----
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
dbgexProcessError()  call     dbgexPhaseII()       7F0FE68196D8 7F0FE67CB1F0
+1872                                              7FFCE65B7000 7FFCE65AF908 ?
                                                   000000000 ? 000000000 ?
dbgePostErrorKGE()+  call     dbgexProcessError()  7F0FE68196D8 7F0FE67CB1F0
1853                                               000000001 000000000
                                                   000000000 ? 000000000 ?
dbkePostKGE_kgsf()+  call     dbgePostErrorKGE()   7F0FE68599C0 7F0FE0B90050
71                                                 000000258 000000000 ?
                                                   000000000 ? 000000000 ?
kgeadse()+448        call     dbkePostKGE_kgsf()   7F0FE68599C0 7F0FE0B90050
                                                   000000258 000000000 ?
                                                   000000000 ? 000000000 ?
kgerinv_internal()+  call     kgeadse()            7F0FE68599C0 ? 7F0FE0B90050
44                                                 000000258 ? 016036BEC
                                                   000000000 000000004
kgerinv()+40         call     kgerinv_internal()   7F0FE68599C0 ? 7F0FE0B90050 ?
                                                   000000258 ? 016036BEC ?
                                                   000000000 ? 000000004 ?
kgeasnmierr()+146    call     kgerinv()            7F0FE68599C0 ? 7F0FE0B90050 ?
                                                   000000258 ? 016036BEC ?
                                                   000000000 ? 000000004 ?
pfrsfm()+1055        call     kgeasnmierr()        7F0FE68599C0 ? 7F0FE0B90050 ?
                                                   000000258 ? 016036BEC ?
                                                   000000002 7F0FE0BA14F8
pfrspopstks()+103    call     pfrsfm()             7F0FE68599C0 ? 7F0FE0B90050 ?
                                                   000000258 ? 016036BEC ?
                                                   000000002 ? 7F0FE0BA14F8 ?
kksumc()+526         call     pfrspopstks()        7F0FE68599C0 ? 7F0FE0BA22F0
                                                   000000258 ? 016036BEC ?
                                                   000000002 ? 7F0FE0BA14F8 ?
opiodr()+4705        call     kksumc()             7F0FE0298488 000000005
                                                   000000258 ? 7F0FE68599C0
                                                   000000002 ? 7F0FE0BA14F8 ?
If we compare incident file of [pfrsfm: stack mismatch] and [pfrsfm: Stack disordered], we can see that they hit ORA-00600 at different pfrsfm locations: 

pfrsfm()+1233

pfrsfm()+1055


3. Test Code 



create or replace procedure clearup_test as
begin
  for c in (select * from dba_scheduler_jobs where job_name like '%TEST_JOB%') loop
    begin
      --set DBA_SCHEDULER_JOBS.enabled=FALSE
	    dbms_scheduler.disable (c.job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
	    --set DBA_SCHEDULER_JOBS.enabled=TRUE, so that it can be scheduled to run (state='RUNNING')
	    --  dbms_scheduler.enable (c.job_name, commit_semantics =>'ABSORB_ERRORS');
	  exception when others then null;
	  end;
	end loop;
	
  for c in (select * from dba_scheduler_running_jobs where job_name like '%TEST_JOB%') loop
    begin
      --If force=FALSE, gracefully stop the job, slave process can update the status of the job in the job queue.
      --If force= TRUE, the Scheduler immediately terminates the job slave.
      --For repeating job with attribute "start_date => systimestamp" and enabled=TRUE, 
      --re-start immediate (state changed from 'SCHEDULED' to 'RUNNING'), DBA_SCHEDULER_JOBS.run_count increases 1.
	    dbms_scheduler.stop_job (c.job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
	  exception when others then null;
	  end;
	end loop;
	
  for c in (select * from dba_scheduler_jobs where job_name like '%TEST_JOB%') loop
    begin
      --If force=TRUE, the Scheduler first attempts to stop the running job instances 
      --(by issuing the STOP_JOB call with the force flag set to false), and then drops the jobs.
	    dbms_scheduler.drop_job (c.job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
	  exception when others then null;
	  end;
	end loop;
end;
/

drop type t_tab;
drop type t_row;

create type t_row as object (id number, name varchar2(50));
/

create type t_tab is table of t_row;
/

create or replace function pipeline_tab (p_rows in number, p_seconds number) return t_tab pipelined as
begin
  for i in 1 .. p_rows loop
    dbms_output.put_line('row: ' || i);
    pipe row(t_row(i, 'Name_' || i));
    if p_seconds > 0 then 
      dbms_session.sleep(p_seconds);
    end if;
  end loop;
  return;
end;
/

-- not needed
drop table test_tab;
create table test_tab(id number, label varchar2(10));
insert into test_tab(id, label) values(1, 'label');
commit;

create or replace procedure test_pipeline_proc_recur(p_rows number, p_seconds number, p_depth number) as
begin
  if p_depth = 0 then
    for c in (select * from table(pipeline_tab(p_rows, p_seconds)) where  rownum <= p_rows-5) 
    loop
      dbms_output.put_line('id = '||c.id);
    end loop;
  else 
    test_pipeline_proc_recur(p_rows, p_seconds, p_depth - 1);
  end if;
  exception when others then 
    dbms_output.put_line('p_depth = '||p_depth||', ERROR: ' || sqlerrm);
end;
/

create or replace procedure test_job_proc(p_job_id number, p_loop_count number, p_rows number, p_seconds number, p_depth number) as
begin
  update test_tab set id = id+1;
  for i in 1..p_loop_count loop
    execute immediate 'begin test_pipeline_proc_recur('||p_rows||', '||p_seconds||', '||p_depth||'); end; ';
  end loop;
  commit;
end;
/

create or replace procedure start_jobs(p_job_count number, p_loop_count number, p_rows number, p_seconds number, p_depth number) as
begin
  for i in 1..p_job_count loop
    dbms_scheduler.create_job (
      job_name        => 'TEST_JOB_CRASHED_1'||i,
      job_type        => 'PLSQL_BLOCK',
      job_action      => 'begin test_job_proc('||i||', '||p_loop_count||', '||p_rows||', '||p_seconds||', '||p_depth||'); end;',    
      start_date      => systimestamp,
      --repeat_interval => 'systimestamp',
      auto_drop       => true,
      enabled         => true);
  end loop;
end;
/

create or replace procedure start_test(p_job_count number, p_loop_count number, p_rows number, p_seconds number, p_depth number) as
  l_cnt number := 0;
begin
  dbms_output.put_line('Start '||p_job_count||' Jobs at '||sysdate);
  start_jobs(p_job_count, p_loop_count, p_rows, p_seconds, p_depth);
  
  -- wait for all jobs running
  dbms_output.put_line('Wait all Jobs running at '||sysdate);
  loop
    dbms_session.sleep(1);
    select count(*) into l_cnt from dba_scheduler_running_jobs where job_name like 'TEST_JOB_CRASHED%';
    exit when l_cnt >= p_job_count;
  end loop;
  
  dbms_output.put_line('Start clearup at '||sysdate);
  clearup_test;
 
  -- wait for all jobs stopped
  dbms_output.put_line('Wait clearup at '||sysdate);
  loop
    dbms_session.sleep(1);
    select count(*) into l_cnt from dba_scheduler_running_jobs where job_name like 'TEST_JOB_CRASHED%';
    exit when l_cnt = 0;
  end loop;
  dbms_output.put_line('Test End at '||sysdate);
end;
/

-- exec start_jobs(1e2, 1e4, 1e6, 0, 5);
-- exec clearup_test;
-- exec test_job_proc(1, 1e4, 1e6, 0, 5);

--================== Test Run ==================--
--  exec start_test(400, 1e4, 1e6, 0, 5);
Posted by at

Tuesday, February 18, 2025

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
Subscribe to: Posts (Atom)