Mining the listener log with Perl
Update – 02-MAY-2012
I have had cause to use this script again at work so thought I’d develop it further. This post has been updated to reflect the new version.
Recently at work I was engaged by one of our application support teams because of application calls failing with “ORA-00020: maximum number of processes (300) exceeded”. We quickly identified that these errors were the symptom of another problem and not a concern in themselves, the real issue was slow database calls due to an infrastructure issue. The ORA-00020 errors were because the application was spawning new connections to try to work around the slow connections. Now I don’t know much about application servers but I know this is not uncommon. The application team however could not find any indication of this in their logs so it was up to me to prove it.
As far as I am aware there are 2 options for retrospectively proving this at a granular level (please share any other options I’ve missed):
1) Query the database audit trail – DBA_AUDIT_SESSION
2) Mine the listener log
On this database no auditing was enabled so I was left with the listener log as my data source.
I knocked up a quick KSH/AWK script to get my data and then massaged it via various means. The output was quite pleasing so over the recent long UK Easter holiday I Googled some Perl commands and had some fun with it, this post is to share the script and an example chart from Microsoft Excel based on the incident I described above.
The script can be downloaded from – llog-miner.pl
Below is an example of how to call the script – it works on *nix and Windows. The “-f” parameter is used to filter log entries on the date, this example is matching any minute between “11:00″ and “12:59″. I’ve included a full usage map further down this post.
C:\>perl llog-miner.pl -excel -f "04-APR-2012 1[12]" listener.log > llog.csv
This is the chart showing the logon spike – click to enlarge. You can see the connection spike at 12:56 of over 250 connection attempts.
The script allows a few other options such as allowing listener logs to be “piped” into the script to allow multiple files to be processed in one command. Usage notes below.
C:\>perl llog-miner.pl -help
Usage: llog-miner.pl [-help] [-filter <string>] [-[no]excel] [-[no]host] <listener_log_path|->
: -excel|noexcel : Output dates in Excel friendly format (default is noexcel)
: -help : Print this help
: -host|nohost : Include host on program (default is to include)
: -filter <string> : A regexp to match beginning of log line. e.g. "23-DEC-2012 0[12]" or "..-MAR-2013"
: listener_log_path|- : Input either a valid listener log name or "-" to read STDIN
Examples:
# Process listener.log looking for entries on the 21st and 22nd of Sept and format dates for Excel
C:\>perl llog-miner.pl -filter "2[12]-SEP-2011" -excel listener.log
# Process two listener log files looking for entries on Jan 3rd between 20:00 and 21:59 and exclude the hostname
$ cat listener.log listener_db.log | llog-miner.pl -filter "03-JAN-2012 2[01]" -nohost -
An improvement I may make in the future is to expand minutes where there are no connection attempts. I have drafted some code to fill in gaps but have kept it to myself for now as it’s too ugly to share (at the moment).
I hope someone finds this useful and if not, well I found it entertaining if nothing else 
A DBA_HIST_SQLSTAT query that I am very fond of
This is a quick post to share a SQL statement I use a lot at work. The query mines the AWR tables (beware the licence implications) for a specific SQL ID and date/time range and shows a few choice statistics for each snapshot period.
awrsql.sql:
prompt enter start and end times in format DD-MON-YYYY [HH24:MI]
column sample_end format a21
select to_char(min(s.end_interval_time),'DD-MON-YYYY DY HH24:MI') sample_end
, q.sql_id
, q.plan_hash_value
, sum(q.EXECUTIONS_DELTA) executions
, round(sum(DISK_READS_delta)/greatest(sum(executions_delta),1),1) pio_per_exec
, round(sum(BUFFER_GETS_delta)/greatest(sum(executions_delta),1),1) lio_per_exec
, round((sum(ELAPSED_TIME_delta)/greatest(sum(executions_delta),1)/1000),1) msec_exec
from dba_hist_sqlstat q, dba_hist_snapshot s
where q.SQL_ID=trim('&sqlid.')
and s.snap_id = q.snap_id
and s.dbid = q.dbid
and s.instance_number = q.instance_number
and s.end_interval_time >= to_date(trim('&start_time.'),'dd-mon-yyyy hh24:mi')
and s.begin_interval_time <= to_date(trim('&end_time.'),'dd-mon-yyyy hh24:mi')
and substr(to_char(s.end_interval_time,'DD-MON-YYYY DY HH24:MI'),13,2) like '%&hr24_filter.%'
group by s.snap_id
, q.sql_id
, q.plan_hash_value
order by s.snap_id, q.sql_id, q.plan_hash_value
/
Nothing ground breaking and I’m sure many will have a similar script.
Below I have example output showing one of the scripts many successful outings, quite a dramatic plan change I’m sure you’ll agree.
SQL> @awrsql enter start and end times in format DD-MON-YYYY [HH24:MI] Enter value for sqlid: 1jjpo2i4b313g Enter value for start_time: 15-NOV-2011 Enter value for end_time: 21-NOV-2011 13:00 Enter value for hr24_filter: SAMPLE_END SQL_ID PLAN_HASH_VALUE EXECUTIONS PIO_PER_EXEC LIO_PER_EXEC MSEC_EXEC --------------------- ------------- --------------- ---------- ------------ ------------ ---------- 15-nov-2011 TUE 08:00 1jjpo2i4b313g 3133159894 129629 0 5 0 16-nov-2011 WED 08:01 1jjpo2i4b313g 3133159894 115003 0 5 .1 17-nov-2011 THU 08:01 1jjpo2i4b313g 3133159894 115741 0 5 0 18-nov-2011 FRI 07:00 1jjpo2i4b313g 3133159894 30997 0 5 .1 18-nov-2011 FRI 08:00 1jjpo2i4b313g 3133159894 81034 0 5 0 21-nov-2011 MON 00:00 1jjpo2i4b313g 790865878 16 323091.6 323128.3 36905.8 21-nov-2011 MON 01:00 1jjpo2i4b313g 790865878 29 349676.2 349713.7 48387.2 21-nov-2011 MON 02:00 1jjpo2i4b313g 790865878 35 339474.6 339509.2 34057.7 21-nov-2011 MON 03:00 1jjpo2i4b313g 790865878 37 340934.6 340970.2 35899.4 21-nov-2011 MON 04:01 1jjpo2i4b313g 790865878 38 333469.1 333503.9 35450.8 21-nov-2011 MON 05:00 1jjpo2i4b313g 790865878 35 347559.3 347595.2 35231.8 21-nov-2011 MON 06:00 1jjpo2i4b313g 790865878 32 340224.8 340260 35208.3
I also like to use the query to track number of executions or LIO per execution over a longer time frame to see if either the frequency or individual impact of the SQL is changing over time. I can use the “hr24_filter” variable to do this, for example showing me all snapshots for hour “13″ over a whole month.
DBMS_METADATA.GET_DDL and SELECT_CATALOG_ROLE
It is quite common for sites to have a set of read only (or read mostly) privileges they grant DBAs and support technicians for day to day investigation. Such a set of privileges may be similar to the role below:
create role readonly_dba; grant create session to readonly_dba; grant select any dictionary to readonly_dba; grant select any table to readonly_dba; -- and maybe a few other bits and pieces such as below (site permitting) grant execute on dbms_monitor to readonly_dba;
With such a role a user can figure out most things including the DDL that defines an object. However with such a user DBMS_METADATA.GET_DDL on an object in a different schema returns an error (output below from 10.2 but 11.2 is similar):
SQL> create user mydba identified by mydba;
SQL> grant readonly_dba to mydba;
SQL> conn mydba/mydba
SQL> -- picked a table at random - DBSNMP.MGMT_SNAPSHOT
SQL> SELECT DBMS_METADATA.GET_DDL('TABLE','MGMT_SNAPSHOT','DBSNMP') FROM dual;
ERROR:
ORA-31603: object "MGMT_SNAPSHOT" of type TABLE not found in schema "DBSNMP"
ORA-06512: at "SYS.DBMS_SYS_ERROR", line 105
ORA-06512: at "SYS.DBMS_METADATA", line 2805
ORA-06512: at "SYS.DBMS_METADATA", line 4333
ORA-06512: at line 1
The solution to this is documented as below but I must admit I only discovered this once I’d figured things out the hard way. A classic case of something being obvious if you already know the answer.
The DBMS_METADATA package considers a privileged user to be one who is connected as user SYS or who has the SELECT_CATALOG_ROLE role.
So now anyone Googling “ORA-31603″ has a potential answer I’ll show you how this is implemented.
When faced with the error above I enabled SQL_TRACE and tried again.
SQL> exec dbms_monitor.session_trace_enable;
SQL> SELECT DBMS_METADATA.GET_DDL('TABLE','MGMT_SNAPSHOT','DBSNMP') FROM dual;
ERROR:
ORA-31603: object "MGMT_SNAPSHOT" of type TABLE not found in schema "DBSNMP"
ORA-06512: at "SYS.DBMS_SYS_ERROR", line 105
ORA-06512: at "SYS.DBMS_METADATA", line 2805
ORA-06512: at "SYS.DBMS_METADATA", line 4333
ORA-06512: at line 1
no rows selected
The penultimate fetch in the resulting trace file was for the statement below (reformatted for readability).
PARSING IN CURSOR #7 len=283 dep=1 uid=39 oct=3 lid=39 tim=2007863993 hv=2568162639 ad='af4fed2c'
SELECT /*+rule*/ SYS_XMLGEN(VALUE(KU$)
, XMLFORMAT.createFormat2('TABLE_T', '7'))
, KU$.OBJ_NUM
FROM SYS.KU$_HTABLE_VIEW KU$
WHERE NOT (BITAND (KU$.PROPERTY,8192)=8192)
AND NOT BITAND(KU$.SCHEMA_OBJ.FLAGS,128)!=0
AND KU$.SCHEMA_OBJ.NAME=:NAME1
AND KU$.SCHEMA_OBJ.OWNER_NAME=:SCHEMA2
END OF STMT
PARSE #7:c=0,e=721,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,tim=2007863991
EXEC #7:c=0,e=674,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,tim=2007864789
FETCH #7:c=0,e=120,p=0,cr=14,cu=0,mis=0,r=0,dep=1,og=3,tim=2007866558
The FETCH line shows no rows were returned (“r=0″). Next I checked the definition of the view – using DBA_VIEWS as DBMS_METADATA isn’t working for other schemas
SQL> set pages 100
SQL> select text from dba_views where view_name = 'KU$_HTABLE_VIEW';
TEXT
--------------------------------------------------------------------------------
... SNIP ...
AND (SYS_CONTEXT('USERENV','CURRENT_USERID') IN (o.owner_num, 0) OR
EXISTS ( SELECT * FROM session_roles
WHERE role='SELECT_CATALOG_ROLE' ))
The role is hardcoded in the view.
After granting SELECT_CATALOG_ROLE to the READONLY_DBA role DBMS_METADATA.GET_DDL returns the desired DDL.
SQL> SELECT DBMS_METADATA.GET_DDL('TABLE','MGMT_SNAPSHOT','DBSNMP') FROM dual;
DBMS_METADATA.GET_DDL('TABLE','MGMT_SNAPSHOT','DBSNMP')
--------------------------------------------------------------------------------
CREATE TABLE "DBSNMP"."MGMT_SNAPSHOT"
( "INSTANCE_NUMBER" NUMBER NOT NULL
Success.
Lessons learned:
1) Once again – read the documentation.
2) Shying away from the 1600+ privileges (2100+ in 11.2) in SELECT_CATALOG_ROLE is not always ideal.
3) Even Oracle aren’t averse to a bit of hardcoding
Ad-hoc Users and Undo Usage
Here is a quote from the Oracle Documentation about V$UNDOSTAT.MAXQUERYLEN:
MAXQUERYLEN NUMBER Identifies the length of the longest query (in seconds) executed in the instance during the period. You can use this statistic to estimate the proper setting of the UNDO_RETENTION initialization parameter. The length of a query is measured from the cursor open time to the last fetch/execute time of the cursor. Only the length of those cursors that have been fetched/executed during the period are reflected in the view.
And here is a quote from My Oracle Support note “V$UNDOSTAT MAXQUERYLEN Suddenly Appears With a High Value For a Simple Query [ID 1307600.1]“
the MAXQUERYLEN value is defined as “the length of a query measured from the cursor open time to the last fetch/execute time of the cursor”. Hence if the cursor is suspended (e.g. dbms_lock.sleep) or the session is switched out (session switching) then the MAXQUERYLEN time will continue to increase but will not be show as no current execution/fetch is occurring on the cursor.
…
This is expected behaviour
Nothing wrong with any of this but it is all relevant to the test that follows. In order to set up the test I change my local database to have a small undo tablespace and generate some workload. I’ve collapsed the code in case you want to jump straight to the story, in summary it generates some transactions and random queries with a duration between 1 and 10 minutes.
alter system set undo_tablespace = undo scope=both sid='*'; create undo tablespace undo_small datafile 'C:\ORACLEXE\ORADATA\XE\UNDO_SMALL.DBF' size 30m reuse autoextend on maxsize 500m; alter system set undo_tablespace = undo_small scope=both sid='*'; create or replace function slow_query(i_seconds_to_wait in number) return number as l_n number; l_pad2 bigtab.pad2%TYPE; cursor c_bigtab is select pad2 from bigtab; begin open c_bigtab; fetch c_bigtab into l_pad2; sys.dbms_lock.sleep(i_seconds_to_wait); fetch c_bigtab into l_pad2; close c_bigtab; return i_seconds_to_wait; end slow_query; / -- session #1 - generate trxns declare L_rno number; L_i number; L_pad1 bigtab.pad1%TYPE; begin while true loop L_i := L_i + 1; L_rno := round(dbms_random.value(1,1000000)); update bigtab set pad1 = pad1 where rno = L_rno; commit; dbms_lock.sleep(0.01); end loop; end; / -- session #2 - generate queries of random length betwen 1 min and 10 mins declare l_sleep number; l_slept number; begin while true loop l_sleep := round(dbms_random.value(60,600)); select slow_query(l_sleep) into l_slept from dual; end loop; end; /
Output from V$UNDOSTAT after the background workload has been running for a while is below along with the current size of the undo tablespace.
END_TIME_CHAR TXNCOUNT MAXQUERYLEN MAXQUERYID ACTIVEBLKS UNEXPIREDBLKS EXPIREDBLKS TUNED_UNDORETENTION
-------------------- ---------- ----------- ------------- ---------- ------------- ----------- -------------------
28-SEP-2011 19:45:50 38118 584 200k2np23z57q 160 912 496 1425
28-SEP-2011 19:55:50 38404 452 200k2np23z57q 160 1120 1280 1292
28-SEP-2011 20:05:50 38507 479 200k2np23z57q 160 1704 1464 1320
28-SEP-2011 20:15:50 38340 383 200k2np23z57q 160 2656 496 1224
FILE_ID FILE_NAME MB
---------- --------------------------------------------- ----------
5 C:\ORACLEXE\ORADATA\XE\UNDO_SMALL.DBF 30
Now a simple query is executed from SQL Developer and the first set of rows is fetched. V$SESSION output below.
SQL> select username,program,status,state,event,sql_id,seconds_in_wait siw 2 from v$session 3 where username = 'ADHOC'; USERNAME PROGRAM STATUS STATE EVENT SQL_ID SIW -------- --------------- -------- ------------------- --------------------------- ------------- ---------- ADHOC SQL Developer INACTIVE WAITING SQL*Net message from client 6fwqzurbc8y7k 7 SQL> select sql_text from v$sql where sql_id = '6fwqzurbc8y7k'; SQL_TEXT ----------------------------------------------------------------------- select * from bigtab
Another quote from the Oracle Documentation
SQL_ID VARCHAR2(13) SQL identifier of the SQL statement that is currently being executed
You can see from the V$SESSION output above that we have a SQL ID and therefore must be executing some SQL. But we also have a session status of “INACTIVE” and are waiting on event “SQL*Net message from client”. That is a nice way of spotting sessions that are similar to the focus of this post.
Around 15 minutes later the session is still waiting on the user to act and V$UNDOSTAT looks consistent with my steady state.
USERNAME PROGRAM STATUS STATE EVENT SQL_ID SIW -------- --------------- -------- ------------------- --------------------------- ------------- ---------- ADHOC SQL Developer INACTIVE WAITING SQL*Net message from client 6fwqzurbc8y7k 912 END_TIME_CHAR TXNCOUNT MAXQUERYLEN MAXQUERYID ACTIVEBLKS UNEXPIREDBLKS EXPIREDBLKS TUNED_UNDORETENTION -------------------- ---------- ----------- ------------- ---------- ------------- ----------- ------------------- 28-SEP-2011 19:45:50 38118 584 200k2np23z57q 160 912 496 1425 28-SEP-2011 19:55:50 38404 452 200k2np23z57q 160 1120 1280 1292 28-SEP-2011 20:05:50 38507 479 200k2np23z57q 160 1704 1464 1320 28-SEP-2011 20:15:50 38340 383 200k2np23z57q 160 2656 496 1224 28-SEP-2011 20:25:50 38557 985 200k2np23z57q 160 2592 816 1825 28-SEP-2011 20:31:28 20492 866 200k2np23z57q 160 2592 816 1706
We now fetch the next set of records and check V$SESSION and V$UNDOSTAT again.
USERNAME PROGRAM STATUS STATE EVENT SQL_ID SIW -------- --------------- -------- ------------------- --------------------------- ------------- ---------- ADHOC SQL Developer INACTIVE WAITING SQL*Net message from client 6fwqzurbc8y7k 35 END_TIME_CHAR TXNCOUNT MAXQUERYLEN MAXQUERYID ACTIVEBLKS UNEXPIREDBLKS EXPIREDBLKS TUNED_UNDORETENTION -------------------- ---------- ----------- ------------- ---------- ------------- ----------- ------------------- 28-SEP-2011 19:45:50 38118 584 200k2np23z57q 160 912 496 1425 28-SEP-2011 19:55:50 38404 452 200k2np23z57q 160 1120 1280 1292 28-SEP-2011 20:05:50 38507 479 200k2np23z57q 160 1704 1464 1320 28-SEP-2011 20:15:50 38340 383 200k2np23z57q 160 2656 496 1224 28-SEP-2011 20:25:50 38557 985 200k2np23z57q 160 2592 816 1825 28-SEP-2011 20:32:49 26370 992 6fwqzurbc8y7k 160 2592 816 1766
V$UNDOSTAT.MAXQUERYID is now that of the SQL Developer session. What if an extra 10 minutes had elapsed?
10 minutes later…
END_TIME_CHAR TXNCOUNT MAXQUERYLEN MAXQUERYID ACTIVEBLKS UNEXPIREDBLKS EXPIREDBLKS TUNED_UNDORETENTION -------------------- ---------- ----------- ------------- ---------- ------------- ----------- ------------------- 28-SEP-2011 19:45:50 38118 584 200k2np23z57q 160 912 496 1425 28-SEP-2011 19:55:50 38404 452 200k2np23z57q 160 1120 1280 1292 28-SEP-2011 20:05:50 38507 479 200k2np23z57q 160 1704 1464 1320 28-SEP-2011 20:15:50 38340 383 200k2np23z57q 160 2656 496 1224 28-SEP-2011 20:25:50 38557 985 200k2np23z57q 160 2592 816 1825 28-SEP-2011 20:35:50 41787 992 6fwqzurbc8y7k 160 3440 688 1833 28-SEP-2011 20:41:31 20088 1293 6fwqzurbc8y7k 160 3440 688 2134
The TUNED_UNDORETENTION is starting to climb but the number of expired blocks is unchanged because our UNDO tablespace is extending – it is now at 42M.
FILE_ID FILE_NAME MB
---------- --------------------------------------------- ----------
5 C:\ORACLEXE\ORADATA\XE\UNDO_SMALL.DBF 42
So let’s prevent it from extending and wait another 10 minutes before fetching the next set of rows.
alter database datafile 5 autoextend off; END_TIME_CHAR TXNCOUNT MAXQUERYLEN MAXQUERYID ACTIVEBLKS UNEXPIREDBLKS EXPIREDBLKS TUNED_UNDORETENTION -------------------- ---------- ----------- ------------- ---------- ------------- ----------- ------------------- 28-SEP-2011 20:05:50 38507 479 200k2np23z57q 160 1704 1464 1320 28-SEP-2011 20:15:50 38340 383 200k2np23z57q 160 2656 496 1224 28-SEP-2011 20:25:50 38557 985 200k2np23z57q 160 2592 816 1825 28-SEP-2011 20:35:50 41787 992 6fwqzurbc8y7k 160 3440 688 1833 28-SEP-2011 20:45:50 41534 1594 6fwqzurbc8y7k 160 4608 576 2752 28-SEP-2011 20:55:50 44669 2196 6fwqzurbc8y7k 160 5200 264 2766
We can see that the number of expired blocks is falling and the number of un-expired blocks is rising. 10 minutes later I click to fetch the next set of records and…
ORA-01555: snapshot too old: rollback segment number 17 with name "_SYSSMU17$" too small
01555. 00000 - "snapshot too old: rollback segment number %s with name \"%s\" too small"
*Cause: rollback records needed by a reader for consistent read are
overwritten by other writers
*Action: If in Automatic Undo Management mode, increase undo_retention
setting. Otherwise, use larger rollback segments
That was only after 35-40 minutes – well within reach of a normal trip to the canteen (admittedly my undo tablespace is sized modestly in order to help me prove a point).
So, here, in reverse order, are my top 3 undo related threats when giving read only access via a tool such as SQL Developer or Toad to application support staff (even though they have the best of intentions).
#3 Undo tablespace pressure.
Unbeknownst to the ad-hoc user he can quite easily cause pressure on the undo tablespace causing an AUTOEXTEND file to grow purely to satisfy their next page of data.
#2 Undo tablespace alerts
For undo tablespaces with no AUTOEXTEND files Grid Control or some other monitoring tool will alert as the number of unexpired blocks starts to fall causing unnecessary (albeit low priority) work for your first line DBAs.
#1 ORA-1555
For undo tablespaces with no AUTOEXTEND files and either a sufficiently high transaction rate or sufficiently high gap between page 1 and page X of our ad-hoc user’s query we may find that the undo required to construct page X has been overwritten. The user gets ORA-1555, thinks “no harm done” and re-starts the query. However the alert log now contains something like below and an alert is fired shortly afterwards.
Wed Sep 28 21:14:48 2011 ORA-01555 caused by SQL statement below (SQL ID: 6fwqzurbc8y7k, Query Duration=3538 sec, SCN: 0x0000.001aad4e):
If the hour is late and the company is pretty twitchy then this could involve someone getting out of bed to investigate a potentially failed batch run.
Have I missed any undo related threats?
DBMS_STATS And Direct Path Operations
Continuing my theme of (almost pointless) testing that DBMS_STATS does as you would hope, this post proves the answer to the question below that was posed at my work place.
Do direct path loads count as modifications for DBMS_STATS or do they bypass it?
My initial instinct was “of course it catches them” but I stopped myself. I’ve never actually seen it so it would be improper to say it out loud. Better dash home and test it (“dash” = 1 month later in this case).
This test is in from Database 11.2 and has been verified on 10.2 also. It has also been tested and tweaked thanks to Surachart’s input – see the first comment on the post. I thought I’d unearthed an interesting difference between 10g and 11g – it turns out I’d only discovered that ARCHIVELOG is not the same as NOARCHIVELOG – doh!
Create a test table, populate it and check that the modifications are caught.
DROP TABLE tab1; CREATE TABLE tab1 ( col1 NUMBER , col2 VARCHAR2(1)); INSERT INTO tab1 SELECT ROWNUM , 'Y' FROM dual CONNECT BY ROWNUM < 1000; COMMIT; exec DBMS_STATS.FLUSH_DATABASE_MONITORING_INFO column table_name format a10 select table_name,INSERTS,UPDATES,DELETES from USER_TAB_MODIFICATIONS where table_name = 'TAB1'; TABLE_NAME INSERTS UPDATES DELETES ---------- ---------- ---------- ---------- TAB1 999 0 0
All good. Now let’s try a direct path load.
ALTER TABLE tab1 NOLOGGING; INSERT /*+ APPEND */ INTO tab1 SELECT ROWNUM , 'Y' FROM dual CONNECT BY ROWNUM < 1000; COMMIT; exec DBMS_STATS.FLUSH_DATABASE_MONITORING_INFO column table_name format a10 select table_name,INSERTS,UPDATES,DELETES from USER_TAB_MODIFICATIONS where table_name = 'TAB1'; TABLE_NAME INSERTS UPDATES DELETES ---------- ---------- ---------- ---------- TAB1 1998 0 0
Looking good but the self doubter in me is asking:
How can you prove that was a direct path load?
Like this hopefully.
sqlplus / ALTER TABLE tab1 LOGGING; INSERT INTO tab1 SELECT ROWNUM , 'Y' FROM dual CONNECT BY ROWNUM < 1000; COMMIT; @mystat Enter value for namefilter: redo size NAME VALUE ---------------------------------------------------------------- ---------- redo size 19712
And…
sqlplus / ALTER TABLE tab1 NOLOGGING; INSERT /*+ APPEND */ INTO tab1 SELECT ROWNUM , 'Y' FROM dual CONNECT BY ROWNUM < 1000; COMMIT; @mystat Enter value for snamefilter: redo size NAME VALUE ---------------------------------------------------------------- ---------- redo size for direct writes 52 redo size 4500
All good, but…
What about DDL?
…shouts my annoying inner self.
TRUNCATE TABLE tab1; exec DBMS_STATS.FLUSH_DATABASE_MONITORING_INFO column table_name format a10 select table_name,INSERTS,UPDATES,DELETES from USER_TAB_MODIFICATIONS where table_name = 'TAB1'; TABLE_NAME INSERTS UPDATES DELETES ---------- ---------- ---------- ---------- TAB1 3996 0 3996
OK, so both my annoying inner voice and I am happy that direct writes are indeed caught by DBMS_STATS. I know this is as expected but heck, sometimes it’s good to see it in black and white.
YAPO-4068: Yet Another Post on ORA-04068
I’ve had discussions with developers over the last few months about how to deal with the dreaded ORA-04068.
oerr ora 04068 04068, 00000, "existing state of packages%s%s%s has been discarded" // *Cause: One of errors 4060 - 4067 when attempt to execute a stored // procedure. // *Action: Try again after proper re-initialization of any application's // state.
We talked about using the SERIALLY_REUSABLE pragma which is a great solution and is well covered by the post below from Lauren Schneider so I won’t go over it here.
This is a good way of protecting your application from ORA-04068 by changing the source package. But what if you have a package where sometimes the package state needs to be carried forward to a subsequent call and sometimes not?
You can control this behaviour from your calling code also, using the Oracle supplied procedure DBMS_SESSION.MODIFY_PACKAGE_STATE (or DBMS_SESSION.RESET_PACKAGE). These are documented in the Oracle Docs here – MODIFY_PACKAGE_STATE Procedure
An example using 2 different database sessions is below. First we demonstrate hitting the ORA-04068 exception:
-- session 1 -- create a test package create or replace package mypkg as G_var number := 1; function retvar return number; end mypkg; / create or replace package body mypkg as function retvar return number is begin return mypkg.G_var; end retvar; end mypkg; / -- test a call to the package declare L_num number; begin L_num := mypkg.retvar; end; / PL/SQL procedure successfully completed. -- session 2 -- alter the package alter package mypkg compile; -- session 1 -- when we come back to session 1 we have lost our package state declare L_num number; begin L_num := mypkg.retvar; end; / * ERROR at line 1: ORA-04068: existing state of packages has been discarded ORA-04061: existing state of package "NEIL.MYPKG" has been invalidated ORA-04065: not executed, altered or dropped package "NEIL.MYPKG" ORA-06508: PL/SQL: could not find program unit being called: "NEIL.MYPKG" ORA-06512: at line 4
Now we repeat the process but use a call to DBMS_SESSION.REINITIALIZE in order to protect ourselves. We are safe to do this as we know we do not want to carry forward the package state.
-- session 1
declare
L_num number;
begin
L_num := mypkg.retvar;
end;
/
PL/SQL procedure successfully completed.
-- session 2
-- alter the package
alter package mypkg compile;
-- session 1
-- we no longer hit ORA-04068
exec dbms_session.modify_package_state(dbms_session.reinitialize)
PL/SQL procedure successfully completed.
declare
L_num number;
begin
L_num := mypkg.retvar;
end;
/
PL/SQL procedure successfully completed.
So we can control this behaviour from the source package and from the calling code. Super.
Before posting this I did a quick Google to see if I was duplicating anything (I should really have done this first) and came across this post by Eddie Awads.
Here is How to Unpersist Your Persistent PL/SQL Package Data
This talks about the DBMS_SESSION.REINITIALIZE procedure used in this post and has a good comment from Paweł Barut regarding using this method in web applications.
DBMS_STATS.SET_TABLE_STATS and statistic staleness
Recently at work there was a discussion regarding setting optimiser statistics using DBMS_STATS SET_*_STATISTICS procedures. The question was asked:
If we set the statistics ourselves will the automatic stat’s job not overwrite them the following night?
Now I was confident that this was not the case but, having never tested this explicitly, thought it better to get my facts straight.
First some quotes from the Oracle Documentation
You can set table, column, index, and system statistics using the SET_*_STATISTICS procedures. Setting statistics in the manner is not recommended, because inaccurate or inconsistent statistics can lead to poor performance.
Monitoring tracks the approximate number of INSERTs, UPDATEs, and DELETEs for that table and whether the table has been truncated since the last time statistics were gathered. You can access information about changes of tables in the USER_TAB_MODIFICATIONS view. Following a data-modification, there may be a few minutes delay while Oracle Database propagates the information to this view. Use the DBMS_STATS.FLUSH_DATABASE_MONITORING_INFO procedure to immediately reflect the outstanding monitored information kept in the memory.
The GATHER_DATABASE_STATS or GATHER_SCHEMA_STATS procedures gather new statistics for tables with stale statistics when the OPTIONS parameter is set to GATHER STALE or GATHER AUTO. If a monitored table has been modified more than 10%, then these statistics are considered stale and gathered again.
The case under discussion was that old favourite – new partitions added to existing tables. The test that follows creates a simple table with four partitions. Three of the partitions are mature, each containing 10,000 rows. The fourth partition is quite new and only contains 1,000 rows.
drop table part_tab;
create table part_tab
( id number
, yrmon number(6)
, padcol varchar2(100))
partition by list (yrmon)
(partition p201101 values (201101)
,partition p201102 values (201102)
,partition p201103 values (201103)
,partition p201104 values (201104));
insert into part_tab
select rownum,201101,lpad('x',100,'y')
from dual connect by rownum <= 10000;
insert into part_tab
select rownum,201102,lpad('x',100,'y')
from dual connect by rownum <= 10000;
insert into part_tab
select rownum,201103,lpad('x',100,'y')
from dual connect by rownum <= 10000;
insert into part_tab
select rownum,201104,lpad('x',100,'y')
from dual connect by rownum <= 1000;
select PARTITION_NAME,NUM_ROWS,BLOCKS,AVG_ROW_LEN,LAST_ANALYZED
from user_tab_statistics
where table_name = 'PART_TAB';
PARTITION_NAME NUM_ROWS BLOCKS AVG_ROW_LEN LAST_ANALYZED
------------------------------ ---------- ---------- ----------- -----------------
31000 568 110 05-MAR-2011 21:24
P201101 10000 174 110 05-MAR-2011 21:24
P201102 10000 174 110 05-MAR-2011 21:24
P201103 10000 174 110 05-MAR-2011 21:24
P201104 1000 46 110 05-MAR-2011 21:24
The statistics on the fourth partition are now faked using DBMS_STATS.SET_TABLE_STATS to match the other partitions.
-- fake statistics in partition 201104
begin
dbms_stats.set_table_stats(null
, 'part_tab'
, 'P201104'
, numrows=>10000
, numblks=>174
, avgrlen=>110);
end;
/
PARTITION_NAME NUM_ROWS BLOCKS AVG_ROW_LEN LAST_ANALYZED
------------------------------ ---------- ---------- ----------- -----------------
31000 568 110 05-MAR-2011 21:24
P201101 10000 174 110 05-MAR-2011 21:24
P201102 10000 174 110 05-MAR-2011 21:24
P201103 10000 174 110 05-MAR-2011 21:24
P201104 10000 174 110 05-MAR-2011 21:24
Now we update the partitions in a variety of ways as described by the comments in the code below.
-- partition "P201101": update 11% of rows (> staleness threshold) and commit
update part_tab
set padcol = lpad('x',100,'z')
where yrmon = 201101 and rownum <= 1100;
commit;
-- partition "P201102": update 11% of rows (> staleness threshold) and rollback
update part_tab
set padcol = lpad('x',100,'z')
where yrmon = 201102 and rownum <= 1100;
rollback;
-- partition "P201103": update 9% of rows (< staleness threshold) and commit
update part_tab
set padcol = lpad('x',100,'z')
where yrmon = 201103 and rownum <= 900;
commit;
-- partition "P201104": update 9% of rows according to optimiser statistics
-- (< staleness threshold) but 90% or actual rows (> staleness threshold)
update part_tab
set padcol = lpad('x',100,'z')
where yrmon = 201104 and rownum <= 900;
commit;
exec DBMS_STATS.FLUSH_DATABASE_MONITORING_INFO
select PARTITION_NAME,INSERTS,UPDATES,DELETES
from USER_TAB_MODIFICATIONS
where table_name = 'PART_TAB';
PARTITION_NAME INSERTS UPDATES DELETES
------------------------------ ---------- ---------- ----------
0 4000 0
P201101 0 1100 0
P201102 0 1100 0
P201103 0 900 0
P201104 0 900 0
From the output above we can see that the rolled back modifications on partition “P201102″ still increase the counters in USER_TAB_MODIFICATIONS. Interesting.
Now we gather optimiser statistics. If DBMS_STATS respects the faked statistics then partition P201104′s statistics should remain unchanged. If DBMS_STATS can see through our fakery then partition P201104′s statistics should be recollected.
Watch to see which partitions’ LAST_ANALYZED value change from “21:24″ to “21:26″.
exec dbms_stats.GATHER_DATABASE_STATS(options=>'gather auto')
select PARTITION_NAME,NUM_ROWS,BLOCKS,AVG_ROW_LEN,LAST_ANALYZED
from user_tab_statistics
where table_name = 'PART_TAB';
PARTITION_NAME NUM_ROWS BLOCKS AVG_ROW_LEN LAST_ANALYZED
------------------------------ ---------- ---------- ----------- -----------------
31000 568 110 05-MAR-2011 21:26
P201101 10000 174 110 05-MAR-2011 21:26
P201102 10000 174 110 05-MAR-2011 21:26
P201103 10000 174 110 05-MAR-2011 21:24
P201104 10000 174 110 05-MAR-2011 21:24
As expected USER_TAB_STATISTICS is the truth as far DBMS_STATS is concerned. The partitions with 11% modifications have new statistics collected. The partitions with 9% modifications keep their existing statistics, including partition “P201104″.
Nothing new or surprising here but I now have the hard facts to put in front of my colleague, remaining mindful of the comment “Setting statistics in the manner is not recommended” at all times
Martin Nash
Neil Johnson
Pawel Krol
Ben Thompson
Eter Pani
3 comments