-
November 2024 (1)
-
October 2024 (1)
-
September 2024 (1)
-
April 2024 (3)
-
January 2024 (1)
-
October 2023 (1)
-
September 2023 (3)
-
August 2023 (1)
-
June 2023 (1)
-
April 2023 (3)
-
March 2023 (2)
-
February 2023 (1)
-
January 2023 (1)
-
December 2022 (2)
-
October 2022 (2)
-
September 2022 (2)
-
August 2022 (2)
-
July 2022 (1)
-
June 2022 (1)
-
May 2022 (2)
-
April 2022 (2)
-
March 2022 (1)
-
February 2022 (2)
-
January 2022 (1)
-
December 2021 (1)
-
November 2021 (1)
-
October 2021 (2)
-
July 2021 (1)
-
June 2021 (1)
-
May 2021 (1)
-
April 2021 (3)
-
March 2021 (2)
-
January 2021 (1)
-
November 2020 (3)
-
September 2020 (1)
-
August 2020 (1)
-
May 2020 (3)
-
April 2020 (3)
-
February 2020 (2)
-
January 2020 (1)
-
December 2019 (2)
-
August 2019 (2)
-
April 2019 (1)
-
November 2018 (5)
- Oracle row cache objects Event: 10222, Dtrace Script (I)
- Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II)
- Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-2) (III)
- Row Cache and Sql Executions (IV)
- Latch: row cache objects Contentions and Scalability (V)
-
October 2018 (2)
-
July 2018 (3)
-
April 2018 (1)
-
March 2018 (2)
-
February 2018 (1)
-
January 2018 (4)
-
October 2017 (2)
-
September 2017 (2)
-
July 2017 (3)
-
May 2017 (8)
- JDBC, Oracle object/collection, dbms_pickler, NOPARALLEL sys.type$ query
- PLSQL Context Switch Functions and Cost
- Oracle Datetime (1) - Concepts
- Oracle Datetime (2) - Examples
- Oracle Datetime (3) - Assignments
- Oracle Datetime (4) - Comparisons
- Oracle Datetime (5) - SQL Arithmetic
- Oracle Datetime (6) - PLSQL Arithmetic
-
March 2017 (3)
-
February 2017 (1)
-
January 2017 (1)
-
November 2016 (1)
-
September 2016 (2)
-
August 2016 (1)
-
June 2016 (1)
-
May 2016 (1)
-
April 2016 (1)
-
February 2016 (1)
-
January 2016 (3)
-
December 2015 (1)
-
November 2015 (1)
-
September 2015 (2)
-
August 2015 (1)
-
July 2015 (2)
-
June 2015 (1)
-
April 2015 (2)
-
January 2015 (1)
-
December 2014 (1)
-
November 2014 (2)
-
May 2014 (3)
-
March 2014 (2)
-
November 2013 (3)
-
September 2013 (1)
-
June 2013 (2)
-
April 2013 (2)
-
March 2013 (3)
-
December 2012 (1)
-
November 2012 (2)
-
July 2012 (1)
-
May 2012 (1)
-
April 2012 (1)
-
February 2012 (1)
-
November 2011 (2)
-
July 2011 (1)
-
May 2011 (3)
-
April 2011 (1)
On Oracle
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)
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.
In Linux window, start bpftrace script below:
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):
If we change it as (require DB restart):
If we disable the Self-tune by (require DB restart):
Of course, if we want to watch "Completed checkpoint", we can force a checkpoint by:
(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;
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.
We create one test table and one procedure to detect skipped rows.
We open two Sqlplus sessions, and make following test.
We first lock 3 rows with x between 5 and 7 in Session_1:
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.
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:
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.
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)
Similar to Section 1 Test Setup, we first code one Plsql procedure:
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)
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.
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".
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".
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.
We run 5 different Scenarios (see Blog appended Test Code), each for 100 seconds.
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;
/
Thursday, April 18, 2024
Oracle AQ Dequeue 'KTC latch subh' Memory Leak and Dequeue Long Running Test
Following previous Blog: "Oracle dbms_aq.dequeue_array Shared Pool "KTC Latch Subh" Memory Leak"
(http://ksun-oracle.blogspot.com/2021/11/oracle-dbmsaqdequeuearray-shared-pool.html),
we will reproduce another case of AQ Dequeue 'KTC latch subh' Memory Leak test in Orale 19.11
with Patch 31666684, and shows dequeue long (hours) running.
Note: Tested in 19.11 with following DB settings (also reproduced in 19.22. In 19.22, there is no Patch 31666684):
We open 3 Sqlplus sessions.
In SID-1, we enqueue 1e6 messages with commit.
In SID-2, dequeue all 1e6 messages without commit to observe 'KTC latch subh' Memory Leak.
Then in SID-3, dequeue one portion (1e3) of messages to show dequeue long running.
We can see 7 hours long dequeue by:
Note: Tested in 19.11 with following DB settings (also reproduced in 19.22. In 19.22, there is no Patch 31666684):
Patch 31666684 (Patch Description: MEMORY LEAK KTC LATCH SUBH ON AQ DEQUEUE)
-- set small shared_pool to observe memory resize between shared pool and buffer cache due to "KTC latch subh"
alter system set shared_pool_size=1008M scope=spfile;
-- set 3 subpools in shared_pool
alter system set "_kghdsidx_count"=3 scope=spfile;
-- disable autosga to generate ORA-04031
--alter system set "_memory_imm_mode_without_autosga"=false;
1. Test Setup
drop type k.t_test_obj force;
create or replace noneditionable type k.t_test_obj is object (id integer, type_id integer);
/
begin sys.dbms_aqadm.drop_queue_table(queue_table => 'K.Q_TEST_TAB', force=> TRUE); end;
/
begin
sys.dbms_aqadm.create_queue_table
( queue_table => 'K.Q_TEST_TAB'
,queue_payload_type => 'K.T_TEST_OBJ'
,compatible => '10.0.0' --'8.1'
,storage_clause => 'nocompress
tablespace u1'
,sort_list => 'PRIORITY,ENQ_TIME'
,multiple_consumers => false
,message_grouping => 0
,comment => 'MEMORY LEAK KTC LATCH SUBH AQ test'
,secure => false
);
end;
/
begin
sys.dbms_aqadm.stop_queue (queue_name => 'K.TEST_QUEUE');
sys.dbms_aqadm.drop_queue (queue_name => 'K.TEST_QUEUE');
end;
/
begin
sys.dbms_aqadm.create_queue
( queue_name => 'K.TEST_QUEUE'
,queue_table => 'K.Q_TEST_TAB'
,queue_type => sys.dbms_aqadm.normal_queue
,max_retries => 100
,retry_delay => 2
,retention_time => 604800
,comment => 'AQ Queue Test'
);
end;
/
begin sys.dbms_aqadm.start_queue(queue_name => 'K.TEST_QUEUE', enqueue => true, dequeue => true); end;
/
create or replace procedure test_enq(p_cnt number := 1, p_sleep number := 0) as
l_enqueue_options dbms_aq.enqueue_options_t;
l_message_properties dbms_aq.message_properties_t;
l_message_handle raw(16);
l_msg t_test_obj;
begin
--visibility:
-- dbms_aq.immediate: no commit is required, message is enqueued and committed for dequeue immediately in an autonomous transaction.
-- dbms_aq.on_commit (default): commit is required, message is visibile for dequeue after COMMIT. enqueue session has an open transaction before commit.
--l_enqueue_options.visibility := dbms_aq.immediate;
for i in 1..p_cnt loop
l_msg := t_test_obj(i, 2);
dbms_aq.enqueue(queue_name => 'K.TEST_QUEUE',
enqueue_options => l_enqueue_options,
message_properties => l_message_properties,
payload => l_msg,
msgid => l_message_handle);
--commit; -- no commit
if p_sleep > 0 then
dbms_lock.sleep(p_sleep);
end if;
end loop;
end;
/
create or replace procedure test_deq(p_cnt number := 1, p_dur number := 0, p_sleep number := 0) as
l_dequeue_options dbms_aq.dequeue_options_t;
l_message_properties dbms_aq.message_properties_t;
l_message_handle raw(16);
l_msg t_test_obj;
l_cnt number := 0;
begin
for i in 1..p_cnt loop
begin
l_dequeue_options.wait := p_dur;
if p_sleep > 0 then
dbms_lock.sleep(p_sleep);
end if;
dbms_aq.dequeue(queue_name => 'K.TEST_QUEUE',
dequeue_options => l_dequeue_options,
message_properties => l_message_properties,
payload => l_msg,
msgid => l_message_handle);
--dbms_output.put_line ('id = ' || l_msg.id || ', type_id = ' || l_msg.type_id);
--commit; -- no commit
l_cnt := l_cnt + 1;
exception when others then null;
end;
end loop;
dbms_output.put_line ('l_cnt = ' || l_cnt);
end;
/
-- purge queue for repeated test
declare
po dbms_aqadm.aq$_purge_options_t;
begin
dbms_aqadm.purge_queue_table('K.Q_TEST_TAB', null, po);
end;
/
2. Test Run
We open 3 Sqlplus sessions.
In SID-1, we enqueue 1e6 messages with commit.
In SID-2, dequeue all 1e6 messages without commit to observe 'KTC latch subh' Memory Leak.
Then in SID-3, dequeue one portion (1e3) of messages to show dequeue long running.
3.1. Queue Filling: SID-1 Enqueue with commit
SQL > exec test_enq(1e6);
Elapsed: 00:01:55.93
SQL > commit;
SQL > select segment_name, segment_type, bytes from dba_segments where segment_name like '%Q_TEST_TAB%';
SEGMENT_NAME SEGMENT_TYPE BYTES
-------------------- ------------------ ----------
Q_TEST_TAB TABLE 125829120
AQ$_Q_TEST_TAB_T INDEX 65536
AQ$_Q_TEST_TAB_I INDEX 51380224
SQL > select count(*) from q_test_tab;
COUNT(*)
----------
1000000
3.2. AQ Dequeue 'KTC latch subh' Memory Leak: SID-2 Dequeue without commit
SQL > select round(bytes/1024/1024, 2) mb, t.* from v$sgastat t where pool='shared pool' and name = 'KTC latch subh';
MB POOL NAME BYTES
---- ----------- -------------- ------
.04 shared pool KTC latch subh 46992
SQL > exec test_deq(1e6);
l_cnt =1000000
PL/SQL procedure successfully completed.
Elapsed: 01:26:32.57
SQL > select round(bytes/1024/1024, 2) mb, t.* from v$sgastat t where pool='shared pool' and name = 'KTC latch subh';
MB POOL NAME BYTES
---- ----------- -------------- -------------
992 shared pool KTC latch subh 1,039,969,240
We can list all SGA memory resize operations:
SQL > select component, parameter, oper_type, initial_size, final_size, final_size-initial_size delta, start_time, end_time
from v$memory_resize_ops where parameter in ('db_cache_size', 'shared_pool_size') order by start_time, parameter;
COMPONENT PARAMETER OPER_TYPE INITIAL_SIZE FINAL_SIZE DELTA START_TI END_TIME
--------------------- ----------------- ---------- -------------- ---------------- -------------- -------- --------
DEFAULT buffer cache db_cache_size STATIC 0 2,097,152,000 2,097,152,000 13:46:14 13:46:14
shared pool shared_pool_size STATIC 0 1,056,964,608 1,056,964,608 13:46:14 13:46:14
DEFAULT buffer cache db_cache_size SHRINK 2,097,152,000 2,080,374,784 -16,777,216 14:31:36 14:31:36
shared pool shared_pool_size GROW 1,056,964,608 1,073,741,824 16,777,216 14:31:36 14:31:36
DEFAULT buffer cache db_cache_size SHRINK 2,080,374,784 2,063,597,568 -16,777,216 14:32:37 14:32:37
shared pool shared_pool_size GROW 1,073,741,824 1,090,519,040 16,777,216 14:32:37 14:32:37
DEFAULT buffer cache db_cache_size SHRINK 2,063,597,568 2,046,820,352 -16,777,216 14:33:41 14:33:41
shared pool shared_pool_size GROW 1,090,519,040 1,107,296,256 16,777,216 14:33:41 14:33:41
.....
shared pool shared_pool_size GROW 1,694,498,816 1,711,276,032 16,777,216 15:34:06 15:34:06
DEFAULT buffer cache db_cache_size SHRINK 1,442,840,576 1,426,063,360 -16,777,216 15:36:18 15:36:18
shared pool shared_pool_size GROW 1,711,276,032 1,728,053,248 16,777,216 15:36:18 15:36:18
DEFAULT buffer cache db_cache_size SHRINK 1,426,063,360 1,409,286,144 -16,777,216 15:38:33 15:38:33
shared pool shared_pool_size GROW 1,728,053,248 1,744,830,464 16,777,216 15:38:33 15:38:33
DEFAULT buffer cache db_cache_size SHRINK 1,409,286,144 1,392,508,928 -16,777,216 15:41:14 15:41:14
shared pool shared_pool_size GROW 1,744,830,464 1,761,607,680 16,777,216 15:41:14 15:41:14
88 rows selected.
There are 42 resize operations from 14:31:36 to 15:41:14, each time shift 16MB from DEFAULT buffer cache to shared pool.
The memory changes are:
shared_pool_size GRO 1,008M -> 1,680M
db_cache_size SHR 2,000M -> 1,328M
KTC latch subh 0M -> 992M
By the way, we can observe many ORA-04031 errors if disable SGA auto resize with:
-- disable autosga to generate ORA-04031
alter system set "_memory_imm_mode_without_autosga"=false;
3.3. Dequeue Long Running: SID-3 Dequeue
We can see 7 hours long dequeue by:
SQL > exec test_deq(1e3);
l_cnt =0
PL/SQL procedure successfully completed.
Elapsed: 07:51:02.15
If we trace SID-3, they are all about 'db file sequential read' on file#=3 (UNDO file) to construct CR block of AQ Queue messages.
PARSING IN CURSOR #139862144662288 len=587 dep=1 uid=0 oct=3 lid=0 tim=25914746826315 hv=3930832701 ad='7f7cb148' sqlid='1y072amp4rgtx'
select /*+ INDEX(TAB AQ$_Q_TEST_TAB_I) */ tab.rowid, tab.msgid, tab.corrid, tab.priority, tab.delay, tab.expiration ,tab.retry_count,
tab.exception_qschema, tab.exception_queue, tab.chain_no, tab.local_order_no, tab.enq_time, tab.time_manager_info, tab.state,
tab.enq_tid, tab.step_no, tab.sender_name, tab.sender_address, tab.sender_protocol, tab.dequeue_msgid, tab.user_prop, tab.user_data
from "K"."Q_TEST_TAB" tab where q_name = :1 and (state = :2 ) order by q_name, state, priority, enq_time, step_no, chain_no,
local_order_no for update skip locked
END OF STMT
EXEC #139862144662288:c=12383,e=39484,p=4,cr=55,cu=0,mis=1,r=0,dep=1,og=1,plh=1032419615,tim=25914746866093
WAIT #139862144662288: nam='db file sequential read' ela= 5849 file#=3 block#=621 blocks=1 obj#=0 tim=25914746872095
WAIT #139862144662288: nam='db file sequential read' ela= 5476 file#=3 block#=620 blocks=1 obj#=0 tim=25914746877756
WAIT #139862144662288: nam='db file sequential read' ela= 11281 file#=3 block#=619 blocks=1 obj#=0 tim=25914746889170
WAIT #139862144662288: nam='db file sequential read' ela= 5466 file#=3 block#=618 blocks=1 obj#=0 tim=25914746894797
WAIT #139862144662288: nam='db file sequential read' ela= 5655 file#=3 block#=617 blocks=1 obj#=0 tim=25914746900588
WAIT #139862144662288: nam='db file sequential read' ela= 5374 file#=3 block#=616 blocks=1 obj#=0 tim=25914746906117
WAIT #139862144662288: nam='db file sequential read' ela= 5522 file#=3 block#=615 blocks=1 obj#=0 tim=25914746911793
WAIT #139862144662288: nam='db file sequential read' ela= 5488 file#=3 block#=614 blocks=1 obj#=0 tim=25914746917451
WAIT #139862144662288: nam='db file sequential read' ela= 108815 file#=3 block#=613 blocks=1 obj#=0 tim=25914747026421
Tuesday, April 9, 2024
One Test of Oracle Object Collection MEMBER OF Function
Following previous Blog: Performance of Oracle Object Collection Comparisons - Part1
(http://ksun-oracle.blogspot.com/2016/01/performance-of-oracle-object-collection_13.html),
we will make one test of MEMBER OF Method.
Oracle Docu writes:
The MEMBER [OF] or NOT MEMBER [OF] condition tests whether or not an element is a member of a nested table, returning the result as a Boolean value.
It seems that order method of object type is used in MEMBER OF Function to make direct one-to-one object comparisons.
Therefore, we use order method to record the number of comparisons.
Note: Tested in Oracle 19c and 22c.
At first, we fill test_tab with 1000 rows, each row has one nested table and one varray of 100 different numbers (values are 1..100).
The first element is always 1, the others (2-100) are sorted by dbms_random.value.
With positive numbers, "MEMBER OF" returns true for first element.
With negative numbers, "MEMBER OF" returns false after going all elements.
In case of varray, with positive numbers, the number of Comparisons is the same as table rows; with negative numbers, the number of Comparisons is ("table rows" * "varray size" * "number of positive numbers");
In case of nested table, with positive numbers, the number of Comparisons is more than table rows because nested table in each row is physically stored in "test_tab_obj_store" (nested table storage), and its physical sequence is not the same as its logical sequence (one can dump "test_tab_obj_store" data block to check them).
With negative numbers, the number of Comparisons is ("table rows" * "varray size" * "number of positive numbers");
Oracle Docu writes:
The MEMBER [OF] or NOT MEMBER [OF] condition tests whether or not an element is a member of a nested table, returning the result as a Boolean value.
It seems that order method of object type is used in MEMBER OF Function to make direct one-to-one object comparisons.
Therefore, we use order method to record the number of comparisons.
Note: Tested in Oracle 19c and 22c.
1. Test Setup
drop type t_obj_tab force;
drop type t_obj_varray force;
drop type t_obj force;
create or replace noneditionable package recorder as
p_cnt number := 0;
end;
/
create or replace noneditionable type t_obj as object (
p_num number,
order member function comp (c t_obj) return integer
);
/
create or replace noneditionable type body t_obj as
order member function comp (c t_obj) return integer is
begin
recorder.p_cnt := recorder.p_cnt + 1; -- count the number of calling
-- for debug
-- dbms_output.put_line('COMP Debug: p_cnt: (p_num > c.p_num) ? sign = '||recorder.p_cnt||
-- ' ('||p_num||' > '||c.p_num||' ?) = '||sign(p_num - c.p_num));
return sign(p_num - c.p_num); -- return 1, -1, 0 for bigger, less, equal
end;
end;
/
create or replace noneditionable type t_obj_tab as table of t_obj;
/
create or replace noneditionable type t_obj_varray as varray(100) of t_obj;
/
drop table test_tab;
create table test_tab (id number, obj_tab t_obj_tab, obj_varray t_obj_varray)
nested table obj_tab store as test_tab_obj_store
/
create or replace procedure fill_tab(p_rows number := 1000, p_obj_tab_size number := 100) as
l_obj_tab t_obj_tab;
l_obj_varray t_obj_varray;
begin
execute immediate'truncate table test_tab';
-- If inserting the same l_obj_tab (or same l_obj_varray), Oracle observes the same objects and optimizes (reduce) to one for the same objects.
--select cast(collect(t_obj(level)) as t_obj_tab) into l_obj_tab from dual connect by level <= l_obj_tab_size;
--select t_obj(level) bulk collect into l_obj_varray from dual connect by level <= l_obj_tab_size;
--insert into test_tab select level, l_obj_tab, l_obj_varray from dual connect by level <= l_rows;
-- Insert 1000 rows, each row has one l_obj_tab and one l_obj_varray with 100 different numbers (values are 1..100)
-- The first element is always 1, the others (2-100) are sorted by dbms_random.value.
-- For each row, insert different l_obj_tab/l_obj_varray by dbms_random.value.
dbms_random.seed(31); -- to make test stable
for i in 1..p_rows loop
with sq as (select level+1 id from dual connect by level <= (p_obj_tab_size -1) order by trunc(dbms_random.value(1, p_rows)))
select t_obj(id), t_obj(id) bulk collect into l_obj_tab, l_obj_varray
from (select 1 id from dual
union all
select * from sq);
insert into test_tab values (i, l_obj_tab, l_obj_varray);
end loop;
commit;
end;
/
-- exec fill_tab(1000, 100);
create or replace procedure memberof_test (p_size number := 100, p_sign number := 1, p_tab varchar2 := 'varray') as
l_obj_tab t_obj_tab := t_obj_tab();
l_obj_varray t_obj_varray := t_obj_varray();
l_start_time number;
l_elapsed number;
l_cnt number := 0;
begin
select cast(collect(t_obj(p_sign*level)) as t_obj_tab) into l_obj_tab from dual connect by level <= p_size order by level;
recorder.p_cnt := 0;
l_start_time := dbms_utility.get_time;
if p_tab = 'varray' then
for c in (
select * from test_tab p
where exists
(select 1 from table (p.obj_varray) t
where t_obj(t.p_num) member of cast (l_obj_tab as t_obj_tab))
) loop
l_cnt := l_cnt + 1;
end loop;
else
for c in (
select * from (select * from test_tab p order by p.id) p
where exists
(select 1 from table (p.obj_tab) t
where t_obj(t.p_num) member of cast (l_obj_tab as t_obj_tab))
-- in COMP method, "(c t_obj)" is "t_obj(t.p_num)"; (self t_obj) is from "l_obj_tab"
) loop
l_cnt := l_cnt + 1;
end loop;
end if;
l_elapsed := dbms_utility.get_time - l_start_time;
dbms_output.put_line('Selected Rows = ' || l_cnt);
dbms_output.put_line('Elapsed(centi) = ' || l_elapsed);
dbms_output.put_line('Comparisons = ' || recorder.p_cnt);
dbms_output.put_line('obj_tab.size = ' || cardinality(l_obj_tab));
end;
/
2. Test Run
At first, we fill test_tab with 1000 rows, each row has one nested table and one varray of 100 different numbers (values are 1..100).
The first element is always 1, the others (2-100) are sorted by dbms_random.value.
exec fill_tab(1000, 100);
Then we run test for varray and nested table by using "MEMBER OF" with 10 or 100 elements, once with all positive numbers, once with all negative numbers.With positive numbers, "MEMBER OF" returns true for first element.
With negative numbers, "MEMBER OF" returns false after going all elements.
exec memberof_test(10, +1, 'varray');
exec memberof_test(10, -1, 'varray');
exec memberof_test(100, +1, 'varray');
exec memberof_test(100, -1, 'varray');
exec memberof_test(10, +1, 'ntab');
exec memberof_test(10, -1, 'ntab');
exec memberof_test(100, +1, 'ntab');
exec memberof_test(100, -1, 'ntab');
3. Test Outcome
In case of varray, with positive numbers, the number of Comparisons is the same as table rows; with negative numbers, the number of Comparisons is ("table rows" * "varray size" * "number of positive numbers");
In case of nested table, with positive numbers, the number of Comparisons is more than table rows because nested table in each row is physically stored in "test_tab_obj_store" (nested table storage), and its physical sequence is not the same as its logical sequence (one can dump "test_tab_obj_store" data block to check them).
With negative numbers, the number of Comparisons is ("table rows" * "varray size" * "number of positive numbers");
SQL > exec memberof_test(10, +1, 'varray');
Selected Rows = 1000
Elapsed(centi) = 16
Comparisons = 1000
obj_tab.size = 10
SQL > exec memberof_test(10, -1, 'varray');
Selected Rows = 0
Elapsed(centi) = 325
Comparisons = 1000000
obj_tab.size = 10
SQL > exec memberof_test(100, +1, 'varray');
Selected Rows = 1000
Elapsed(centi) = 16
Comparisons = 1000
obj_tab.size = 100
SQL > exec memberof_test(100, -1, 'varray');
Selected Rows = 0
Elapsed(centi) = 3174
Comparisons = 10000000
obj_tab.size = 100
SQL > exec memberof_test(10, +1, 'ntab');
Selected Rows = 1000
Elapsed(centi) = 16
Comparisons = 4491
obj_tab.size = 10
SQL > exec memberof_test(10, -1, 'ntab');
Selected Rows = 0
Elapsed(centi) = 328
Comparisons = 1000000
obj_tab.size = 10
SQL > exec memberof_test(100, +1, 'ntab');
Selected Rows = 1000
Elapsed(centi) = 16
Comparisons = 2662
obj_tab.size = 100
SQL > exec memberof_test(100, -1, 'ntab');
Selected Rows = 0
Elapsed(centi) = 3174
Comparisons = 10000000
obj_tab.size = 100
Subscribe to:
Posts (Atom)