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 :
Note how the "select * from tmp_data" portion passed to PDBTMP is rewritten as
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.
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.
(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.
No comments:
Post a Comment