Retrieving Oracle trace files via an external table

December 21st 2006: Correction to script

When talking about performance tuning, I will often tell developers that they need to use Oracle SQL*Trace and TKPROF because that is an absolutely reliable way to find out how their SQL executed, how long it took and hence where they should focus their attention to improve performance. However, that requires access to the trace files in the USER_DUMP_DEST directory on the database server, which is something that database administrators are justifiably reticent to provide. When I am on a customer site, I often experience the same difficulties.

Even if developers can get a log on to a development database server, trace files will only be readable on Unix servers within the DBA group unless _trace_file_public is set to true.

Another option is to retrieve trace files from the user_dump_dest directory via an external table. The idea is not mine. I've seen this technique demonstrated by Tanel Poder, there is an article by Jared Still that demonstrates how to retrieve the alert log, and there is also an posting on Ask Tom using utl_dir. However, I couldn't find a script to do trace files, so I wrote one.

The script assumes the trace file is created by the current session. The first thing it does is to create a database directory that maps to the USER_DUMP_DEST directory, and an external table that corresponds to the trace file. Then you can just query the trace file in SQL*PLus and spool the output to a local file.

Of course, this also shows that external tables are a significant security risk. The privilege to create and read from directories carefully controlled.

REM user_dump_dest.sql
REM (c) Go-Faster Consultancy Ltd.
REM 30.11.2006 initial version

REM trace the thing you are interested in.
ALTER SESSION SET tracefile_identifier = 'gfctest';
ALTER SESSION SET sql_trace = true;
SELECT * FROM dual;
ALTER SESSION SET sql_Trace = false;

REM determine path for user_dump_dest and create an database directory
set echo off feedback off verify on timi off
column dir new_value dir format a18
column path new_value path format a60
SELECT name dir, value path
FROM v$parameter
WHERE name = 'user_dump_dest'
/
CREATE OR REPLACE DIRECTORY &dir AS '&path';

REM determine the name of the trace file from show process ID, and database name and parameters
column tracefile_name new_value tracefile_name
SELECT LOWER(d.name)||'_ora_'||p.spid
||DECODE(p.value,'','','_'||value) tracefile_name
FROM v$parameter p, v$database d, sys.v_$session s, sys.v_$process p
,(SELECT sid FROM v$mystat WHERE rownum=1) m
WHERE p.name = 'tracefile_identifier'
AND s.paddr = p.addr
AND s.sid = m.sid
/

REM create an external table that corresponds to the trace file
DROP TABLE &tracefile_name;
CREATE TABLE &tracefile_name
(trace_line VARCHAR2(4000))
ORGANIZATION EXTERNAL
(TYPE ORACLE_LOADER DEFAULT DIRECTORY user_dump_dest
ACCESS PARAMETERS (
RECORDS DELIMITED BY NEWLINE NOBADFILE NODISCARDFILE NOLOGFILE
FIELDS MISSING FIELD VALUES ARE NULL
REJECT ROWS WITH ALL NULL FIELDS
(trace_line CHAR(4000)))
LOCATION ('&tracefile_name..trc')
);

REM just query the trace file back to a local spool file in SQL Plus
set head off pages 0 termout off
spool &tracefile_name..trc
SELECT * FROM &tracefile_name;
spool off
set termout on
DROP TABLE &tracefile_name;

Truncating a Table does not affect the Materialized View Log

I am working on a site that is replicating tables between databases using Materialized Views. I have realised that if a replicated table is truncated on the source database, that the rows remain in the materialized view on the target until a complete refresh is performed. Worse, if ROWID based Materialized View is used, then the fast refresh process will error with 'ORA-12034: materialized view log on "SYSADM"."T_R" younger than last refresh'. In PeopleSoft, there are no primary keys, and it is not possible to build them if any of the key columns are nullable, which is the case with non-required date fields in PeopleSoft. Here is an example. I will create two tables, and replicate them with Materialized Views. One by primary key, and the other by ROWID.

CREATE TABLE t_pk
(a NUMBER
,b VARCHAR2(20)
,CONSTRAINT t PRIMARY KEY(a));

CREATE TABLE t_r
(a NUMBER
,b VARCHAR2(20));

CREATE MATERIALIZED VIEW LOG ON t_pk WITH PRIMARY KEY;
CREATE MATERIALIZED VIEW t_pk_mv REFRESH FAST WITH PRIMARY KEY
AS SELECT * FROM t_pk ;

CREATE MATERIALIZED VIEW LOG ON t_r WITH ROWID;
CREATE MATERIALIZED VIEW t_r_mv REFRESH FAST WITH ROWID
AS SELECT * FROM t_r ;

INSERT INTO t_pk VALUES(1,'Old');
INSERT INTO t_pk VALUES(2,'Old');
INSERT INTO t_r VALUES(1,'Old');
INSERT INTO t_r VALUES(2,'Old');

BEGIN dbms_mview.refresh(list => 'T_PK_MV', method => 'f'); END;
BEGIN dbms_mview.refresh(list => 'T_R_MV', method => 'f'); END;

SELECT * FROM t_pk_mv;
A B
- ---
1 Old
2 Old

SELECT * FROM t_r_mv;
A B
- ---
1 Old
2 Old

So the data has replicated and everything seems to working fine. Now lets truncate the source tables, and put some new data in. One row has the same key value, one does not.

TRUNCATE TABLE t_pk;
TRUNCATE TABLE t_r;

INSERT INTO t_pk VALUES(2,'New');
INSERT INTO t_pk VALUES(3,'New');
INSERT INTO t_r VALUES(2,'New');
INSERT INTO t_r VALUES(3,'New');

The fast refresh of the Materialized View with the primary key appears to work. The new rows are inserted into the Materialized View, replacing existing rows with the same key values, but the old rows remain.

BEGIN dbms_mview.refresh(list => 'T_PK_MV', method => 'f'); END;
PL/SQL procedure successfully completed.

SELECT * FROM t_pk;
A B
- ---
2 New
3 New

SELECT * FROM t_pk_mv;
A B
- ---
1 Old
2 New
3 New

The fast refresh of the Materialized View by ROWID fails, and the old data remains in place.

BEGIN dbms_mview.refresh(list => 'T_R_MV', method => 'f'); END;
*
ERROR at line 1:
ORA-12034: materialized view log on "SYSADM"."T_R" younger than last refresh
ORA-06512: at "SYS.DBMS_SNAPSHOT", line 803
ORA-06512: at "SYS.DBMS_SNAPSHOT", line 860
ORA-06512: at "SYS.DBMS_SNAPSHOT", line 841
ORA-06512: at line 1

But rows 1 & 2 are in MV but not source table

SELECT * FROM t_r;
A B
- ---
2 New
3 New

SELECT * FROM t_r_mv;
A B
- ---
1 Old
2 Old

However, a full refresh corrects the discrepancy

BEGIN dbms_mview.refresh(list => 'T_PK_MV', method => 'c'); END;
BEGIN dbms_mview.refresh(list => 'T_R_MV', method => 'c'); END;

SELECT * FROM t_pk_mv;
A B
- ---
2 New
3 New

SELECT * FROM t_r_mv;
A B
- ---
2 New
3 New

It seems to me, that it would be appropriate to prevent a Truncate command executing if there is a Materialized View Log on the table. I have written such a trigger

CREATE OR REPLACE TRIGGER mvtrunc_lock
BEFORE TRUNCATE
ON SYSADM.SCHEMA
DECLARE
 e_generate_message EXCEPTION;
 l_recname  VARCHAR2(15 CHAR);
 l_msg      VARCHAR2(100 CHAR) := 'No Message.';
 l_msg2     VARCHAR2(100 CHAR) := 'Cannot '||ora_sysevent
   ||' '||lower(ora_dict_obj_type)
   ||' '||ora_dict_obj_owner||'.'||ora_dict_obj_name||'.  ';

 sql_text ora_name_list_t;
 l_sql_stmt VARCHAR2(1000 CHAR) := '';
 n          INTEGER;
 i          INTEGER;

BEGIN
 /*extract the originating SQL statement into a string variable*/
 n := ora_sql_txt(sql_text);
 FOR i IN 1..n LOOP
  l_sql_stmt := SUBSTR(l_sql_stmt || sql_text(i),1,1000);
 END LOOP;

 IF ora_dict_obj_type = 'TABLE' AND 
    ora_sysevent = 'TRUNCATE' THEN

  BEGIN /*if a materialized view log exists*/
   SELECT 'There is a materialized view log.'
   INTO   l_msg
   FROM   all_mview_logs l
   WHERE  ROWNUM = 1
   AND    l.master = ora_dict_obj_name
   AND    l.log_owner = ora_dict_obj_owner
   ;
   RAISE e_generate_message;
  EXCEPTION
   WHEN NO_DATA_FOUND THEN NULL;
  END;
 END IF;

 EXCEPTION
  WHEN NO_DATA_FOUND THEN NULL;
  WHEN e_generate_message THEN
   RAISE_APPLICATION_ERROR(-20042,
     'MVTRUNC_LOCK:'||l_msg2||l_msg||CHR(10)||'SQL:'||l_sql_stmt);
END;
/

show errors

The trigger MVTRUNC_LOCK can be downloaded from the Go-Faster website.

DDL Triggers to prevent loss of database objects not managed by PeopleTools

Sometimes you have to certain database techniques or create database objects on tables that
are maintained by PeopleTools, but which themselves are not maintained by PeopleTools. This is often as a result of performance tuning activities where you choose to use features of the Oracle database that PeopleSoft do not use because they are not available on other database platforms.

• Function-Based Indexes: In Oracle, it is possible to implement an index on a function. A typical example would be an index on UPPER(NAME) on PS_NAMES to facilitate case
  insensitive searching.
• Record-based auditing can be done with a database DML trigger, instead of the default functionality of the Application Server. This was implemented by PeopleSoft to improve performance of the auditing and is a rare example of PeopleSoft coding specific code for each platform because the trigger DDL is slightly different.

However, these objects are not created by the DDL scripts built by the Application Designer, and can accidentally be lost when the table is altered with an 'alter by recname' script generated by Application Designer. The implications can be quite serious. If the auditing trigger were to be lost, then the application would continue to run, but no audit data would be produced, and no error would be raised.
In Oracle, it is possible to build DDL triggers. Just as DML triggers fire when the data is changed, DDL triggers fire when particular DDL commands are issued. I have created a trigger called PSFT_DDL_LOCK (available from the Go-Faster psscripts github repository) that fires when an object is altered or dropped. In certain cases the trigger will raise an error, this causes the original DDL command to fail, and thus prevents loss of the unmanaged objects. If the table related to the object being dropped or altered is not managed by PeopleSoft (if it can't be found in PSRECDEFN), the trigger does not raise any error. Otherwise,

• If a trigger is being dropped or altered, and the name of that trigger does not start with PSU, then an error is raised. Triggers that are named PSU% are created by Application Designer for use with Mobile Agents If an index is dropped or altered, the trigger checks that it is defined in PeopleTools. Indexes that correspond to Unique, Duplicate and Alternate Keys in Application Designer (where the index name is 'PS', followed by either a digit or an underscore, followed by the record name) are ignored.
• If a table is dropped or altered, the DDL trigger checks that there are no user indexes or triggers not defined in PeopleSoft, nor any primary key constraints, materialized views or materialized view logs on the table. It also checks that the table or index is not partitioned, clustered, global temporary or index organised.

If any of the tests fail, then the trigger raises an exception the DDL statement fails with an error message generated in the trigger. The SQL that generated the error is also included in the error text.
When an error is generated by this trigger during development or migration activities, it usually indicates that there is another database object that you need to consider before issuing the command that errorred. It is not simply a matter of disabling the trigger and trying again.
The trigger does have a couple of side effects.

• There are several SQL statements that are run in the trigger, and this does impact the performance of DDL commands. If you are dropping all the tables in a schema, then it would be advisable to disable the trigger. The trigger definitely needs the following function-based index to be created on PSRECDEFN because it needs to look up the PeopleSoft record from the table name.

CREATE INDEX pszpsrecdefn
ON psrecdefn (DECODE(sqltablename,' ','PS_'recname,sqltablename))
TABLESPACE PSINDEX PCTFREE 0;

• If a user index is removed from the PeopleTools definition before it is dropped, the trigger will raise an error. However, in such cases it would be better to keep the definition of the index in Application Designer and set the platform radio button to 'None' so that PeopleTools does not build it. That way a comment can be preserved to explain why the index is no longer necessary.

Updated 2.6.2011: The checking behaviour trigger can be disabled for just the current session by calling this packaged procedure that sets a package global variable which is read by a function called by the trigger. For the one session where this is done, the checks are not performed by trigger are disabled:
execute psft_ddl_lock.set_ddl_permitted(TRUE);

The behaviour can be reenabled like this:
execute psft_ddl_lock.set_ddl_permitted(FALSE);

The previous version of this trigger (called T_LOCK) did not have this capability, so I suggested disabling the trigger, but this affected all sessions.

Nullable VARCHAR2 columns in PeopleSoft

Since time immemorial, we were told by PeopleSoft that all numeric, character or required fields in their applications are created as NOT NULL columns in the database. And so we confidently repeat the mantra and build our SQL accordingly.

But it is not completely true!

Long Character fields in PeopleSoft that are not defined as 'required' in the Application Designer are nullable in the database. Long Character field are usually created as LONG columns in the database unless their length is defined as between 1 and 2000 characters, in which case they are created as VARCHAR2 columns.

So a Long Character field of between 1 and 2000 characters becomes a nullable VARCHAR2 column in the database (it has taken me 10 years to find this, and it's yet another piece of errata in my book!).

The edit and key options in PeopleTools are restricted on a long field, but nonetheless it opens some interesting possibilities. Including sparse indexes on nullable VARCHAR2 columns, where you identify rows for a query with non-null flags, and set the flag to null afterwards, thus removing it from the index.

What not to Code: The evils of tables as sequence generators and timestamps for uniqueness

This is a story about the dangers of using tables as sequence generators and then the risks of using date/time functions to generate unique keys. In this case, a simple and initially effective change resulted in a time-delayed logic bomb of remarkable subtlety and devastating effect.
The story happens to be about a PeopleSoft system, but it could have happened to any application. It starts with a pair of ERP systems. Changes in the HR system generate cases in the CRM system that the back office HR helpdesk processes. The HR system sends a message to the CRM system, where it may turn into one or more workflow messages. Some HR actions can give rise to many hundreds or even thousands of CRM workflows. For each Workflow, a run control record is created on a table that is keyed on the operator ID and a Run Control ID (an arbitrary ID to identify the control record).
The vanilla version of this code used a sequence number generated, in the usual PeopleSoft platform agnostic way, from a table. In extreme situations, a batch HR process can generate many thousands of workflows. These messages are processed by the subscription servers of an application server domain. This system is busy enough to have several of these domains, each with several subscription handler processes. So isn't long before contention on the row level lock taken during the sequence generation table became an issue. It was noticed that adding additional subscription handlers didn't increase throughput, and that database locking also impeded online users who would also execute this code.

So a developer changed the code and now the run control was a string derived by concatenating the operator ID (originally it used just the first three characters of the operator ID) and the current Time. In case this run control already existed (usually because a message generated several work flows) the code goes into a loop, generating a new run control from the operator and time each time. Adding more subscription handlers still doesn't increase message throughput - if anything it makes it worse.
Three more facts to bear in mind:

1. The time is in the format HH24:MI:SS.
2. The publish and subscribe application server processes all connect as the operator PSAPPS.
3. The run control table is not purged.

Function CreateRunControl(...) Returns string

REM &run_cntl_id = String(GetNextNumberWithGaps( RB_WF_RTEKEYMAX.WF_SCHED_NBR_NEXT, 1999999999, 1));
/* workaround to avoid dead locks ... */
&run_cntl_id = %OperatorId String(%Time);
&chk_rc = "N";
SQLExec("SELECT 'Y' FROM PS_RB_RUN_CNTL_WF WHERE RUN_CNTL_ID = :1", &run_cntl_id, &chk_rc);
While &chk_rc = "Y"
&chk_rc = "N";
&run_cntl_id = %OperatorId String(%Time);
SQLExec("SELECT 'Y' FROM PS_RB_RUN_CNTL_WF WHERE RUN_CNTL_ID = :1", &run_cntl_id, &chk_rc);
End-While;
...
&return = &recRouteKeys.Insert(); /*Inserts run control*/

So yesterday when user FRED generated a workflow at 10.27.42 the run control is 'FRED10.27.42'. If today he generates another workflow at 10.27.42 the code will loop until 10.27.43 until it can generate run control that has not been used. In fact, Fred can never generate a run control at 10.27.42 ever again. Also, if a single operation generates 3 run controls then it will take at least 2 extra seconds to allocate the second and third run control.
The situation for the message processing application server is even more severe. It can generate hundreds or even thousands of workflows in an evening. The subscription handlers execute the loop in the code until a time of day when they have not processed a message before.
On a day that I was on this site, I heard that a worker in the HR call centre had had nothing to do all day, and then at 5.30 in the evening, as she was about to go home, 15 new cases appeared on her list and she was not happy (call centre workers are measured on the number of cases they process and the length of their queues). Sure enough, we found that there were over 50000 records, 3600 records per hour for user PSAPPS continuously from 3am to 5.30pm. When we got to 86400 records processing of workflow from inbound messages would have stopped completely! We also found that some operators have generated over 40 messages in a given minute and so the save time of some of their operations is starting to be seriously affected.
The correct solution to all of this would be to have used an Oracle sequence. You get a unique number every time, and there is no contention on its allocation. In this application, there is no objection to any gaps in the sequence.
The original code suffered from database locking problems that effectively serialised run control processing. The code change worked well in test and initially worked fairly well in production. Although the message processing application servers could only produce a maximum of one workflow per second before they would start to execute the loop, which they could do over 100 times per second. Thus database locking was replaced with high CPU consumption in the application server as it looped, and additional SQL execution and logical I/O in the database leading to increased latch contention and also increasing database CPU consumption. As the problem became more severe, other parts of the application also suffered as users waited for their requests to be processed by an available process in the application server. It all amounts to a viscous and downward spiral.

Conclusions

• Oracle recognised the problems of sequence generation, so they created Sequences. You've paid good money for them, so use them.
• While date and time functions can appear to produce unique values, you need to think carefully about what will happen in a busy multi-user system.