Hi
Apologies for the somewhat puzzling subject, but more details below.
To start, config:
Oracle 10.2.0.3 Enterprise Edition on Redhat Linux (2.6.18-128.el5)
We audit all logons and logoffs as part of the DB audit trail.
Before we kick off our nightly batch we take an export of some of the main schemas of the database. This usually takes approximately 1hr and 20min. Nothing else runs against the DB at that time. The last export took just over 2 hours with no significant increase in data volumes.
I have checked disk latency, did a general check of server activity and couldn't see anything obvious (No swap used, no I/O peaks, CPU not excessively busy, load average low, memory fine etc.)
The export ran from 03:47 am to 05:51 am. I ran an AWR report against the DB for the time period 04:00 to 05:00. I wanted to make sure the snapshot I was analysing didn't include any batch processing.
As per AWR, top 5 waits:
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
read by other session 540,291 8,128 15 54.6 User I/O
Streams AQ: enqueue blocked on 26 3,023 116,258 20.3 Configurat
db file scattered read 233,657 1,693 7 11.4 User I/O
db file sequential read 179,903 1,209 7 8.1 User I/O
CPU time 561 3.8
The top 2 events are new and used to never pop up in any AWR reports until recently.
So what was running:
SQL ordered by Elapsed Time DB/Inst: FLXPRD63/FLXPRD63 Snaps: 15024-15025
-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> % Total DB Time is the Elapsed Time of the SQL statement divided
into the Total Database Time multiplied by 100
Elapsed CPU Elap per % Total
Time (s) Time (s) Executions Exec (s) DB Time SQL Id
---------- ---------- ------------ ---------- ------- -------------
11,190 397 195 57.4 75.1 3frffgw69abb8
update sys.aud$ set action#=:2, returncode=:3, logoff$time=sysdate, logoff$pread
=:4, logoff$lread=:5, logoff$lwrite=:6, logoff$dead=:7, sessioncpu=:8 where sess
ionid=:1 and entryid=1 and action#=100
3,233 270 0 N/A 21.7 973p4gyb8wwp7
BEGIN SYS.KUPW$WORKER.MAIN('SYS_EXPORT_SCHEMA_03', 'AGDBA'); END; *<-- This is the export*
528 0 34 15.5 3.5 8rgw5q94paqsg
Module: Data Pump Master
BEGIN sys.kupc$que_int.send(:1, :2, :3); END;
Logical reads (gets):
SQL ordered by Gets DB/Inst: FLXPRD63/FLXPRD63 Snaps: 15024-15025
-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> Total Buffer Gets: 52,335,067
-> Captured SQL account for 72.7% of Total
Gets CPU Elapsed
Buffer Gets Executions per Exec %Total Time (s) Time (s) SQL Id
-------------- ------------ ------------ ------ -------- --------- -------------
37,180,232 195 190,667.9 71.0 396.97 11189.91 3frffgw69abb8
update sys.aud$ set action#=:2, returncode=:3, logoff$time=sysdate, logoff$pread
=:4, logoff$lread=:5, logoff$lwrite=:6, logoff$dead=:7, sessioncpu=:8 where sess
ionid=:1 and entryid=1 and action#=100
12,019,105 0 N/A 23.0 270.29 3233.24 973p4gyb8wwp7
BEGIN SYS.KUPW$WORKER.MAIN('SYS_EXPORT_SCHEMA_03', 'AGDBA'); END;
Physical reads:
LSQL ordered by Reads DB/Inst: FLXPRD63/FLXPRD63 Snaps: 15024-15025
-> Total Disk Reads: 11,556,407
-> Captured SQL account for 19.1% of Total
Reads CPU Elapsed
Physical Reads Executions per Exec %Total Time (s) Time (s) SQL Id
-------------- ----------- ------------- ------ -------- --------- -------------
9,426,902 0 N/A 81.6 270.29 3233.24 973p4gyb8wwp7
BEGIN SYS.KUPW$WORKER.MAIN('SYS_EXPORT_SCHEMA_03', 'AGDBA'); END;
2,168,715 195 11,121.6 18.8 396.97 11189.91 3frffgw69abb8
update sys.aud$ set action#=:2, returncode=:3, logoff$time=sysdate, logoff$pread
=:4, logoff$lread=:5, logoff$lwrite=:6, logoff$dead=:7, sessioncpu=:8 where sess
ionid=:1 and entryid=1 and action#=100
Until recently we had 6.3 million rows in the SYS.AUD$TABLE. We archive most of that data off to another schema and now have about 300k rows in sys.aud$. However, the sys.aud$ table was not analyzed (dbms_stats) since the cleanup and the update above does a full table scan every time it does an update of the aud$ table.
FYI, when a user logs on, an entry is inserted into the aud$ table. When that user logs off or is timed out, that row is updated and the status changed from LOGON to LOGOFF - hence the update.
We are in the process of analyzing the aud$ table now.
My questions (after all of that):
1. Why do 195 update executions of aud$ have a 40 minute performance impact on the export?
Writing this thread it occurred to me that the additional physical and logical reads cause by aud$ updates may have impacted the export.
2. Is the read by other session wait event caused by the aud$ update (seems likely)
3. What is causing the event Streams AQ: enqueue blocked on (low memory)? SGA_TARGET is set to 8GB, aq_tm_processes is set to 0 and the streams_pool_size is set to 0 (so the amount of memory allocated to the streams_pool should be 20% of shared pool by default)...
I'm kinda convincing myself that the aud$ thing is causing all the problems by flushing buffers out of the cache every time it does an update...
Any thoughts appreciated and thanks for actually reading all of this :-)
Andreas