07 September, 2022

SCN Synchronization when using a Database Link

 In my previous blog post about querying across a Database Link, I had stated "when running a query (just a SELECT statement) requires the two databases to synchronise SCN.  Whichever is the database with the lower SCN has to increment its SCN to the other database's (higher) SCN "


Here is a quick demonstration :


-- First I verify the current SCN in two databases "ORCLCDB" and "CDB2"
ORCLCDB SQL>select name, systimestamp, current_scn from v$database;

NAME      SYSTIMESTAMP                         CURRENT_SCN
--------- ------------------------------------ -----------
ORCLCDB   07-SEP-22 10.10.49.643026 PM +08:00     19617903

ORCLCDB SQL>

NAME      SYSTIMESTAMP                         CURRENT_SCN
--------- ------------------------------------ -----------
CDB2      07-SEP-22 10.10.52.378969 PM +08:00     18562711

CDB2 SQL>
-- there is a wide gap between the two -- with ORCLCDB being ahead by approximately 1million
============================================================================================



-- now I connect a client to a PDB in ORCLCDB
-- and run a SELECT query that queries across a DBLink a table in a PDB in CDB2
-- this query is NOT a user transaction, only a SELECT statement
SQL> connect hemant/hemant@orclpdb1
Connected.
SQL> set time on
22:11:33 SQL>
22:11:48 SQL> select count(*) from tmp_data@pdbtmp_data;

  COUNT(*)
----------
     73181

22:12:05 SQL>


-- Now I check the SCNs in the two databases
ORCLCDB SQL>select name, systimestamp, current_scn from v$database;

NAME      SYSTIMESTAMP                         CURRENT_SCN
--------- ------------------------------------ -----------
ORCLCDB   07-SEP-22 10.12.19.955477 PM +08:00     19620089

ORCLCDB SQL>

CDB2 SQL>select name, systimestamp, current_scn from v$database;

NAME      SYSTIMESTAMP                         CURRENT_SCN
--------- ------------------------------------ -----------
CDB2      07-SEP-22 10.12.23.499409 PM +08:00     19620089

CDB2 SQL>
-- I can see that CDB2's SCN has "mysteriously" caught up with ORCLCDB 
-- in fact they are exactly the same
-- in the real world there would still be some difference by the time I query again
-- because other transactions in either or both the databases would have incremented the SCN(s)
================================================================================================



-- now I disconnect from the client
-- this *closes* the database link
22:12:58 SQL> disconnect
Disconnected from Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0

-- and reconnect to the client
22:13:04 SQL> connect hemant/hemant@orclpdb1
Connected.
22:13:14 SQL>

-- I compare the SCNs in the two databases
ORCLCDB SQL>select name, systimestamp, current_scn from v$database;

NAME      SYSTIMESTAMP                         CURRENT_SCN
--------- ------------------------------------ -----------
ORCLCDB   07-SEP-22 10.13.22.738662 PM +08:00     19620223

ORCLCDB SQL>

CDB2 SQL>select name, systimestamp, current_scn from v$database;

NAME      SYSTIMESTAMP                         CURRENT_SCN
--------- ------------------------------------ -----------
CDB2      07-SEP-22 10.13.30.874874 PM +08:00     19620229

CDB2 SQL>
-- the gap is very small
-- in fact some internal operations in CDB2 have slightly incremented it ahead
===============================================================================



-- I run a PLSQL procedure in my client that does 1million COMMITs in the PDB
-- to increase the SCN only in ORCLCDB
22:14:06 SQL> execute onemillioncommits;

PL/SQL procedure successfully completed.

22:15:03 SQL>
22:15:07 SQL>


-- I now compare the two SCNs
ORCLCDB SQL>select name, systimestamp, current_scn from v$database;

NAME      SYSTIMESTAMP                         CURRENT_SCN
--------- ------------------------------------ -----------
ORCLCDB   07-SEP-22 10.15.21.713518 PM +08:00     20654338

ORCLCDB SQL>
CDB2 SQL>select name, systimestamp, current_scn from v$database;

NAME      SYSTIMESTAMP                         CURRENT_SCN
--------- ------------------------------------ -----------
CDB2      07-SEP-22 10.15.23.779855 PM +08:00     19620296

CDB2 SQL>
-- and find that there is again a huge gap between the two databases, with ORCLCDB ahead again
==============================================================================================



-- I query across the Database Link again from my client session
22:15:46 SQL>  select count(*) from tmp_data@pdbtmp_data;

  COUNT(*)
----------
     73181

22:15:50 SQL>


-- and now compare the two SCNs
ORCLCDB SQL>select name, systimestamp, current_scn from v$database;
NAME      SYSTIMESTAMP                         CURRENT_SCN
--------- ------------------------------------ -----------
ORCLCDB   07-SEP-22 10.16.02.362146 PM +08:00     20654373

ORCLCDB SQL>
CDB2 SQL>select name, systimestamp, current_scn from v$database;

NAME      SYSTIMESTAMP                         CURRENT_SCN
--------- ------------------------------------ -----------
CDB2      07-SEP-22 10.16.14.122201 PM +08:00     20654453

CDB2 SQL>
-- now the gap is very small
-- some other operations in ORCLCDB have already incremented the SCN after the query
====================================================================================


So, simply running a SELECT statement (not even a User-Initiated COMMIT causes the two databases to synchronise SCNs.  The database with the lower SCN "inherits" the higher SCN.

So, the next time you see database SCNs mysteriously jump (e.g. in V$DATABASE.CURRENT_SCN  or in V$ARCHIVED_LOG.FIRST_CHANGE#  or in V$DATAFILE.CHECKPOINT_SCN) very significantly, check to see if you have queries to/from the database that use one or more Database Links.

23 August, 2022

Querying across a Database Link

 In this demonstration, assume that I have a local table called "TARGET_DATA" with a list of Countries and Products.  A new company is being acquired and that organisations's product list has been loaded into a table called TMP_DATA in a different database PDBTMP.

So, I run a MINUS query to find the local products that are not in the new company's product list -- but this query is run across a Database Link.

Here is how I create the Database Link, run the MINUS query and then obtain a tkprof of the trace file generated for the query.


SQL> create database link pdbtmp_data
  2  connect to data_load identified by data_load using 'pdbtmp';

Database link created.

SQL>
SQL> alter session set tracefile_identifier='MY_DBLINK_QRY';

Session altered.

SQL> alter session set statistics_level='ALL';

Session altered.

SQL>
SQL> exec dbms_session.session_trace_enable(waits=>TRUE,binds=>FALSE);

PL/SQL procedure successfully completed.

SQL>
SQL> select * from target_data
  2  minus
  3  select * from tmp_data@pdbtmp_data
  4  /

...
...

600 rows selected.

SQL> select 'x' from dual;

'
-
x

SQL> show array
arraysize 15
SQL>
SQL> quit
Disconnected from Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
oracle19c>


-- tkprof of the trace file

select * from target_data
minus
select * from tmp_data@pdbtmp_data

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.02       0.24          0          0          1           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       41      0.17       0.30        453        455          0         600
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       43      0.19       0.55        453        455          1         600

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 106
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
       600        600        600  MINUS  (cr=455 pr=453 pw=0 time=306868 us starts=1)
     71682      71682      71682   SORT UNIQUE (cr=455 pr=453 pw=0 time=142899 us starts=1 cost=872 size=2876679 card=73761)
     73761      73761      73761    TABLE ACCESS FULL TARGET_DATA (cr=455 pr=453 pw=0 time=80877 us starts=1 cost=130 size=2876679 card=73761)
     71143      71143      71143   SORT UNIQUE (cr=0 pr=0 pw=0 time=148559 us starts=1 cost=831 size=2927240 card=73181)
     73181      73181      73181    REMOTE  TMP_DATA (cr=0 pr=0 pw=0 time=96385 us starts=1 cost=80 size=2927240 card=73181)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                          135        0.00          0.00
  SQL*Net message to client                      41        0.00          0.00
  Disk file operations I/O                        1        0.00          0.00
  db file sequential read                         1        0.00          0.00
  db file scattered read                         21        0.00          0.04
  SQL*Net message to dblink                       4        0.00          0.00
  SQL*Net message from dblink                     4        0.00          0.00
  SQL*Net more data from dblink                 352        0.01          0.05
  SQL*Net message from client                    41        8.84          8.89
********************************************************************************
SQL ID: 04vfkrajpkrnj Plan Hash: 1388734953

select 'x'
from
 dual


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          0          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 106
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  FAST DUAL  (cr=0 pr=0 pw=0 time=1 us starts=1 cost=2 size=0 card=1)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2       11.31         11.31



********************************************************************************


OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.02       0.24          0          0          1           0
Execute      3      0.01       0.01          0        676          0           1
Fetch       43      0.17       0.30        453        455          0         601
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       48      0.20       0.56        453       1131          1         602

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

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                          137        0.00          0.00
  SQL*Net message to client                      44        0.00          0.00
  SQL*Net message from client                    44       16.85         37.06
  db file sequential read                         1        0.00          0.00
  single-task message                             1        0.02          0.02
  SQL*Net message from dblink                    15        0.05          0.15
  SQL*Net message to dblink                      14        0.00          0.00
  Disk file operations I/O                        1        0.00          0.00
  db file scattered read                         21        0.00          0.04
  SQL*Net more data from dblink                 352        0.01          0.05
  
  


The query returns 600 rows but with an ARRAYSIZE of 15 for the sqlplus session, it results in 40 round trips (SQL*Net message to/from client)  (plus 1 additional for the parse) resulting a total of 41 SQL*Net messages.
However, the 73,181 rows from the remote database (PDBTMP) appear as 4 DBLink messages (SQL*Net message to/from dblink) and 352 "more data from dblink" waits.  So, there were many more network packets from PDBTMP to my local database.
But the total count of dblink messages is 15 (from dblink) and 14 (to dblink) -- an excess of about 11 over the initial 4.  Which means that there were some additional "chatty" interaction between my local database session and the one created in PDBTMP.


I also trace the session that is created by the Database Link operation in PDBTMP.  The tkprof for the trace file of that session is below :

SQL ID: bv2zwsyu4hq3k Plan Hash: 0

SELECT /*+ FULL(P) +*/ *
FROM
 "TMP_DATA" P


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.04       0.05          4        101          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.04       0.05          4        101          0           0

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 109

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.14          0.14
********************************************************************************
SQL ID: 33v4pbtw6zjxt Plan Hash: 3633341221

SELECT "COUNTRY","PRODUCT_NAME"
FROM
 "TMP_DATA" "TMP_DATA"


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        4      0.05       0.08        450        455          0       73181
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.05       0.08        450        455          0       73181

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 109
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
     73181      73181      73181  TABLE ACCESS FULL TMP_DATA (cr=455 pr=450 pw=0 time=66315 us starts=1 cost=124 size=2927240 card=73181)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       4        0.00          0.00
  db file sequential read                         1        0.00          0.00
  db file scattered read                         19        0.00          0.03
  SQL*Net message from client                     4       20.26         20.31
  SQL*Net more data to client                   352        0.00          0.00



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ----------- ---------- ----------  ----------
Parse        2      0.04       0.05          4        101          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        4      0.05       0.08        450        455          0       73181
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        7      0.09       0.13        454        556          0       73181

Misses in library cache during parse: 2

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                            1        0.00          0.00
  log file sync                                   1        0.00          0.00
  SQL*Net message to client                      11        0.00          0.00
  SQL*Net message from client                    11       20.26         20.47
  db file sequential read                         1        0.00          0.00
  db file scattered read                         19        0.00          0.03
  SQL*Net more data to client                   352        0.00          0.00




Note how the "select * from tmp_data" portion passed to PDBTMP is rewritten as 
SELECT /*+ FULL(P) +*/ *
FROM
 "TMP_DATA" P
- and then as 
SELECT "COUNTRY","PRODUCT_NAME"
FROM
 "TMP_DATA" "TMP_DATA"

The remote database also shows that it sent 4 messages to/from "client" (in this case the client was my database session in my local database, not the sqlplus program) and 352 "more data" packets.  These numbers match what we see in the local trace file.
However, this also shows an additional 11 messages to/from "client".
There are some additional lines in the raw trace file which indicate what these overheads are.

One of them is for the logon trigger in PDBTMP that I have created to ensure that the DBLink connection generates a trace file.
The others are for recursive parse and other calls in PDBTMP (where parse success is sent to my "client" session in my local database).  Calls like :
select decode(upper(failover_method), NULL, 0 , 'BASIC', 1, 'PRECONNECT', 2 , 'PREPARSE', 4 , 0), decode(upper(failover_type), NULL, 1,  'NONE', 1, 'SESSION', 2, 'SELECT',  4, 'TRANSACTION',  8, 'AUTO' , 32,  1 ), failover_retries, failover_delay, flags, nvl(replay_initiation_timeout, 900), decode(upper(session_state_consistency), 'STATIC', 16, 0), failover_restore from sys.service$ where name = :1

insert into link_logons$(logon_time , source_id)  VALUES ( SYSTIMESTAMP AT TIME ZONE 'UTC', :srcid )

XCTEND rlbk=0, rd_only=0, tim=....

XCTEND rlbk=1, rd_only=1, tim=...

XCTEND rlbk=0, rd_only=1, tim=...


So, a Database Link query has overheads. Also, when running a query (just a SELECT statement) requires the two databases to synchronise SCN.  Whichever is the database with the lower SCN has to increment its SCN to the other database's (higher) SCN  
A distributed query is effectively a *transaction* which requires implicit COMMIT/ROLLBACK. To clarify : Oracle automatically re-synchronizes the SCN -- not that your distributed transaction is automatically commit.

(also notice the "insert into link_logon$"  which seems to be an audit implementation in the remote database PDBTMP).


Bonus : This is the ON LOGON TRIGGER in PDTMP which causes it to write to a Trace File :


SQL> select dbms_metadata.get_ddl('TRIGGER','DATA_LOAD_LOGON_TRIG') from dual;

DBMS_METADATA.GET_DDL('TRIGGER','DATA_LOAD_LOGON_TRIG')
--------------------------------------------------------------------------------

  CREATE OR REPLACE NONEDITIONABLE TRIGGER "SYS"."DATA_LOAD_LOGON_TRIG"
after logon on database
 WHEN (user = 'DATA_LOAD') begin
   execute immediate 'alter session set tracefile_identifier=''DATA_LOAD''';
   execute immediate 'alter session set statistics_level=''ALL''';
   dbms_session.session_trace_enable(waits=>TRUE,binds=>FALSE);
end;
ALTER TRIGGER "SYS"."DATA_LOAD_LOGON_TRIG" ENABLE


Such a trigger is useful when you want to trace every logon by a particular user but don't know when the logon will occur.