Oracle SQL Tracing Processes from Startup

Sometimes, ASH and AWR are not enough.  SQL may not be sampled by ASH if it is short-lived, and even if it is sampled, the SQL may not be captured by AWR.  Sometimes, in order to investigate a problem effectively, it is necessary to use database session SQL trace.  

It is easy to trace a process initiated by the process scheduler with a trigger (see Enabling Oracle Database Trace on PeopleSoft processes with a Trigger).

Another tactic is to use an AFTER LOGON trigger with logic to look at the program name.  The program name can be read using SYS_CONTEXT().  If it matches what I am looking for, I can enable session trace.

Here is an example I used for the OpenXML nVision server PSNVSSRV

• I want to trace SQL and not any wait events or bind variables.  Therefore, I will set event 10046 at level 1.
• I also set a tracefile_identifier that will be included in the trace file name, so I can more easily identify the trace file.

REM additional SQL trace triggers
CREATE OR REPLACE TRIGGER sysadm.gfc_nvision_trace_on_logon
AFTER LOGON
ON sysadm.schema
DECLARE
  l_process_instance INTEGER;
  l_program          VARCHAR2(64 CHAR);
  l_sql              VARCHAR2(100);
BEGIN

  SELECT sys_context('USERENV', 'CLIENT_PROGRAM_NAME')
  INTO   l_program
  FROM   dual;

  IF l_program like 'PSNVSSRV%' THEN --then this is a NVISION session
    EXECUTE IMMEDIATE 'ALTER SESSION SET tracefile_identifier = ''PSNVSSRV''';
    EXECUTE IMMEDIATE 'ALTER SESSION SET events ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 1''';
  END IF;

EXCEPTION 
  WHEN OTHERS THEN NULL;
END;
/
show errors
ALTER TRIGGER sysadm.gfc_nvision_trace_on_logon ENABLE;

See also Reading Trace files with SQL

nVision Performance Tuning: 6. Logging Selector Usage

This blog post is part of a series that discusses how to get optimal performance from PeopleSoft nVision reporting as used in General Ledger.

Static selectors are tracked by entries in the PSTREESELCTL table.  It is maintained after the tree is extracted to the selector table.  The version number on PSTREESELCTL is compared with the corresponding version number on the PSTREEDEFN to determine whether the extract of the tree to the selector table is still valid, or whether it needs to be reextracted because the tree has been updated.  Selectors that do not have an entry in PSTREESELCTL are therefore dynamic.
Static selectors are left in the PSTREESELECTnn table after the report completes so that they can be reused.  However, many customers periodically create new effective dated versions of many trees, and so static selectors on old effective dated versions of the tree will accumulate as there is nothing to purge them.
Dynamic selectors are extracted every time the report runs.  They should normally be deleted by nVision before the report finishes.  However, if a report crashes dynamic selectors can be left behind.  That creates a number of problems

• The size of the selector tables will tend to increase over time as old static and dynamic selectors are left behind.
• That in turn affects the statistics on these tables.  The range of values for SELECTOR_NUM will become wider faster than the number of rows in the table grows.  The minimum value will either be the oldest static selector number, or the oldest dynamic selector left after a crash.  The maximum value will be the last selector number inserted when statistics were collected.

Therefore, it is useful to be able to track creation and deletion of dynamic selectors by the various nVision reports and queries.  I have therefore created a logging table PS_NVS_TREESLCTLOG (see nvision_dynamic_selectors.sql), a PL/SQL package XX_NVISION_SELECTORS and compound DML triggers on every tree selector table.
The column names in the log table have been chosen for compatibility with the PeopleSoft data dictionary, so that a record can be defined in Application Designer.

Column Name	Data Type	Description
SELECTOR_NUM	NUMBER	Unique identifier for tree selector records.
PROCESS_INSTANCE	NUMBER	PeopleSoft process instance number for nVision/Query
LENGTH	NUMBER	Length of tree selector
NUM_ROWS	NUMBER	Number of rows inserted into tree selector.  Counted by the AFTER ROW part of the triggers.
TIMESTAMP	TIMESTAMP	Time when rows inserted
MODULE	VARCHAR2(64)	Module attribute of session inserting selector rows.
APPINFO_ACTION	VARCHAR2(64)	Action attribute of session inserting selector rows
CLIENTINFO	VARCHAR2(64)	CLIENT_INFO attribute of session inserting selector rows.  This will include: PeopleSoft Operator ID. Name of the application server or process scheduler domain. Name of the machine where the client process is executing. Name of the client executable process.
STATUS_FLAG	VARCHAR2(1)	I=Selectors Inserted S=Static Selectors Inserted D=Selectors Deleted X=Selectors Deleted and Partition Dropped
TREE_NAME	VARCHAR2(18)	Name of the tree from which selector extracted. Obtained by querying statement from V$SQL.
OWNER_ID	VARCHAR2(8)	Schema under which nVision report run
PARTITION_NAME	VARCHAR2(128)	Name of partition where selectors stored
JOB_NO	NUMBER	Database Job number to collect statistics on the partition.

All of the logic is kept in the PL/SQL package because it is common to the triggers on all the tree selector tables.  Insert triggers track population of selectors and delete triggers track the successful removal of dynamic selectors.  After row triggers track the selector number and count the number of rows inserted.  After statement triggers call the logging procedures.

CREATE OR REPLACE TRIGGER sysadm.pstreeselect10_insert
FOR INSERT ON sysadm.PSTREESELECT10 compound trigger
  l_err_msg VARCHAR2(100 CHAR);
AFTER EACH ROW IS
BEGIN
  sysadm.xx_nvision_selectors.rowins(:new.selector_num,:new.range_from_10,:new.range_to_10);
EXCEPTION WHEN OTHERS THEN NULL;
END after each row;

AFTER STATEMENT IS
BEGIN
  sysadm.xx_nvision_selectors.logins(10,'SYSADM');
EXCEPTION WHEN OTHERS THEN
  l_err_msg := SUBSTR(SQLERRM,1,100);
  dbms_output.put_line('Error:'||l_err_msg);
END after statement;
END;
/

CREATE OR REPLACE TRIGGER sysadm.pstreeselect10_delete
FOR DELETE ON sysadm.PSTREESELECT10 compound trigger
  l_err_msg VARCHAR2(100 CHAR);
AFTER EACH ROW IS
BEGIN
  sysadm.xx_nvision_selectors.rowdel(:old.selector_num);
EXCEPTION WHEN OTHERS THEN NULL;
END after each row;

AFTER STATEMENT IS
BEGIN
  sysadm.xx_nvision_selectors.logdel(10);
EXCEPTION WHEN OTHERS
THEN
  l_err_msg := SUBSTR(SQLERRM,1,100);
  dbms_output.put_line('Error:'||l_err_msg);
END after statement;
END;
/

Once the decision to bear the overhead of triggers on the selector tables is made, there are then various pieces of additional information that can be captured and stored in the logging table for very little additional overhead.  It is easy to record the current session attributes such as module, action, and client_info.  The process instance number is captured on startup and can then be read by the psftapi package.  The tree is identified by scanning the V$SQL for the SQL that fired the triggers.
It is also possible to maintain statistics on the selector tables.

Purging Selectors

The selector log can be used to drive purging of selectors not cleared by nVisions that failed to complete.  The package includes a purge procedure to clear selectors that are not already marked as having been deleted either when the logged process instance is no longer running, or if there is no known process instance then if it is more than 2 days since the selector was inserted.  If the selector table is also interval partitioned, then the partition will be dropped.
A trigger on PSTREESELCTL (see pstreeselctl.sql) tracks the logs static selector maintenance.
The purge process is invoked by a trigger on PSPRCSRQST that fires when nVision process status is changed away from processing.  The selector purge process should also be scheduled to run daily.
The selector log itself is not purged as it contains useful information about tree usage.

Recommendations

• If the tree selector tables are not partitioned create a histogram on SELECTOR_NUM.  However, up to Oracle 11g, this will not be effective as the number of distinct values reaches the maximum number of buckets, 254.  Dynamic selectors should be purged before this happens.  From Oracle 12c the maximum number of buckets is 2048, and hybrid histograms can be used.

Enabling Oracle Extended SQL Trace by Module and Action

I have written previously about the value of assigning meaningful values to the module and action attributes on a database session (see Using Oracle Enterprise Manager (Grid Control) with PeopleSoft). Oracle added instrumentation to PeopleTools 8.50 (see PeopleTools 8.50 uses DBMS_APPLICATION_INFO to Identify Database Sessions) that sets module and action for on-line and batch sessions.  However, I still use my own trigger to set these attributes for processes initiated by the Process Scheduler.

I originally became interested in module and action because it made it possible to analyse performance problems in specific processes with Active Session History (see Practical Use of ASH). However, since Oracle 10g there is also a very easy way to enable Oracle's extended session trace in the sessions relating to specific processes.

In the Oracle supplied PL/SQL package DBMS_MONITOR, there are two programs to specify combinations of module and action for which SQL trace will be enabled.  It is rather like setting a watchpoint in a debugger. SERV_MOD_ACT_TRACE_ENABLE is used to create a watchpoint, and SERV_MOD_ACT_TRACE_DISABLE removes it. Trace is then enabled in a session when the module and action is set to a value that matches a watchpoint and disabled when the module and/or action is changed to a value for which there is no watchpoint.

This screenshot from OEM shows that a query is being run within a PeopleSoft component RECV_PO, page PO_PICK_ORDERS.

It would be a simple matter to have Oracle trace the session for that component by setting a watchpoint.

BEGIN
 sys.dbms_monitor.serv_mod_act_trace_enable
 (service_name=>'P1PPP'
 ,module_name =>'RECV_PO'
 ,waits=>TRUE
 ,binds=>TRUE);
END;
/

Note that the service name must be specified as part of the watchpoint.  This will usually be the same as the PeopleSoft database name.  Thus, watchpoints copied to another database by cloning won't be effective because the service name will be different.

I could also have specified an action in the example above, but I want to trace all pages in the component and the search dialogue.

As with the other programs in dbms_monitor, information on wait events is included in traces by default.  In the above example, I have also requested information on bind variables to be included in the trace.

When setting a SQL trace for an on-line component it is possible that many different users could trigger tracing.  Trace will be enabled and disabled for each user. The result is that you will get a trace file for each application server process, and each trace file might contain the activity for more than one user if the application server process handled more than one service request.

Watchpoints can be removed in a similar way.

BEGIN
 sys.dbms_monitor.serv_mod_act_trace_disable
 (service_name=>'P1PPP'
 ,module_name =>'RECV_PO'
 ,action_name =>'PO_PICK_ORDERS');
END;
/

Watchpoints are held the table SYS.WRI$_TRACING_ENABLED.

SELECT * FROM sys.wri$_tracing_enabled
/

TRACE_TYPE PRIMARY_ID QUALIFIER_ID1 QUALIFIER_ID2   INSTANCE_NAME FLAGS
---------- ---------- ------------- --------------- ------------- -----
         5 P1PPP      RECV_PO       PO_PICK_ORDERS                   12

This technique is also effective for processes initiated by the Process Scheduler. The default behaviour from PeopleTools 8.50 is to set Action to the process name, my trigger sets Module to the process name.

 

If I specify only the Module in SERV_MOD_ACT_TRACE_ENABLE, then it trace will be enabled for that module and for any action.

BEGIN
 sys.dbms_monitor.serv_mod_act_trace_disable
 (service_name=>'AAAAAAA'
 ,module_name =>'GPPDPRUN');
END;
/

I choose to set the action to the Process Instance number because I find it useful to relate ASH data to a specific batch process. The above screenshot from OEM shows a streamed Global Payroll calculation running with many concurrent GPPDPRUN processes. The watchpoint would cause each and every process to trace.

However, it has been suggested that if the Action was set to the process run control ID then the watchpoint could be set to the specific run control value used by a user or scheduled job. It would be a simple matter of changing the trigger (I'll leave that as an exercise).  Then, a user could be told to use a specific value for run control ID that would then invoke trace.

BEGIN
 sys.dbms_monitor.serv_mod_act_trace_disable
 (service_name=>'AAAAAAA'
 ,action_name =>'TRACEME');
END;
/

Update 24.11.2012 This technique will not work for Application Engine from PeopleTools 8.52 because it now sets MODULE to a value that includes a session number and so cannot be predicted.

Enabling Oracle Database Trace on PeopleSoft processes with a Trigger (improved)

In Chapter 11 of PeopleSoft for the Oracle DBA, I suggested using a database trigger to enable Oracle's SQL Trace facility. Then, in chapter 14, I introduced a further trigger to disable trace for Application Engine processes, in case they are run with the PSAESRV process.

This was not a good idea because the cursors opened by the Application Engine program are still open when the AE program completed, and the process updates its status from 7 (processing) to 9 (success) or 3 (error). This causes the unset_trace trigger to fire and disable SQL Trace. Consequently, the STAT lines for these cursors are never emitted to the trace file. The STAT lines contain the execution plans and a wealth of other information.

Updated 26.4.2021: Instead, I have a new version of the trace trigger (trace_trigger.sql can be downloaded from my Github repository of PeopleSoft scripts).

spool trace_trigger
rem (c)Go-Faster Consultancy Ltd. 2008

rem 1.5.2008 - moved logic to disable trace from unset_trace trigger into main trigger 
rem because cursors in AE not shut until after status is changed away from processing

ROLLBACK;
----------------------------------------------------------------
REM explicit grants by sys required on following privileges
----------------------------------------------------------------
GRANT ALTER SESSION TO sysadm;
GRANT EXECUTE ON sys.dbms_monitor TO sysadm;
GRANT EXECUTE ON sys.dbms_application_info TO SYSADM;
----------------------------------------------------------------

CREATE OR REPLACE TRIGGER sysadm.set_trace
BEFORE UPDATE OF runstatus ON sysadm.psprcsrqst
FOR EACH ROW
WHEN (new.runstatus = 7 AND old.runstatus != 7 AND new.prcstype != 'PSJob')(1)
DECLARE
  l_waits BOOLEAN := TRUE;(2)
  l_binds BOOLEAN := FALSE;
BEGIN
  --set module and action whether we are tracing or not
  sys.dbms_application_info.set_module((3)
 module_name => :new.prcsname,
 action_name => 'PI='||:new.prcsinstance
  );
   
  IF ( :new.runcntlid LIKE 'TRACEME%'(5)
  ----------------------------------------------------------------
  --code conditions for enabling trace here instead of when clause
  ----------------------------------------------------------------
  --  OR (    SUBSTR(:new.prcsname,1,3) = 'TL_'
  --      AND :new.rqstdttm <= TO_DATE('20080509','YYYYMMDD'))
  ----------------------------------------------------------------
     ) THEN

    --if we are going to trace, then set tracefile identifier
    EXECUTE IMMEDIATE 'ALTER SESSION SET TRACEFILE_IDENTIFIER(4) = '''||
      TRANSLATE(:new.prcstype     ,' -','__')||'_'||
      TRANSLATE(:new.prcsname     ,' -','__')||'_'||
      :new.prcsinstance||'_'||
       TRANSLATE(:new.servernamerun,' -','__')||
       '''';

    EXECUTE IMMEDIATE 'ALTER SESSION SET TIMED_STATISTICS = TRUE';
    EXECUTE IMMEDIATE 'ALTER SESSION SET MAX_DUMP_FILE_SIZE = 2097152'; --1Gb
    EXECUTE IMMEDIATE 'ALTER SESSION SET STATISTICS_LEVEL=ALL';

    ----------------------------------------------------------------
    --logic to determine whether you want to trace binds also
    ----------------------------------------------------------------
    IF :new.runcntlid LIKE 'TRACE%BIND%' THEN(6)
      l_binds := TRUE;
    END IF;
    ----------------------------------------------------------------

    sys.dbms_monitor.session_trace_enable(waits=>TRUE,binds=>l_binds);(7)
--  EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 12''';

  ELSIF :new.prcstype = 'Application Engine' THEN(8)
    --explicitly disable trace if application server process
    sys.dbms_monitor.session_trace_disable;

    --reset max dump file size AFTER disabling trace
    EXECUTE IMMEDIATE 'ALTER SESSION SET MAX_DUMP_FILE_SIZE = 5M';

    --if not tracing, then reset tracefile identifier
    EXECUTE IMMEDIATE 'ALTER SESSION SET TRACEFILE_IDENTIFIER(4) = ''''';
  END IF;
EXCEPTION WHEN OTHERS THEN NULL;
END;
/

show errors

DROP TRIGGER sysadm.unset_trace;

rem test that the trigger fires by updating something
UPDATE  sysadm.psprcsrqst new
SET     runstatus = 7
WHERE   runstatus != 7
AND     new.prcstype != 'PSJob'
AND    rownum < 1
--AND 1=2
;

ROLLBACK;
spool off

1. The trigger fires when any process begins. Previously I used logic in the WHEN clause to restrict when it fired.
2. Wait events are collected in the trace by default.
3. Irrespective of whether trace is enabled, the trigger also calls the dbms_application_info package to set the module name to the PeopleSoft Process Name, and action to the PeopleSoft Process Instance number.
4. Also irrespective of whether trace is enabled, the trace file identifier is set so that the trace file name includes the Process Type, Process Name, Process Instance Number, and the name of the Process Scheduler.
(Updated 6.2.2009) Previous versions of this trigger set tracefile identifier irrespective of whether trace was enabled. Unfortunately, this causes a small trace file to be generated for every process.5. Logic in the trigger determines whether a SQL Trace will be enabled. The supplied version of the trigger traces processes whose run controls begin with 'TRACE'
6. Additional logic has been added to also enable bind variables to be captured if the run control begins with 'TRACEBIND'.
7. The dbms_monitor package is new in Oracle 10g and is the only officially supported way to enable extended trace. If using the trigger on earlier versions of the database, it should be replaced with the commented code to set event 10046.
8. If it is not required to SQL Trace a process, and the process is an Application Engine program, then trace is explicitly disabled. Thus, if a PSAESRV process has traced an AE program, trace is disabled when it next handles a request. This has the advantage that the stat lines for the cursors are written to the trace file. However, the disadvantage is that the process continues to trace between requests, and the time between requests is reported as 'SQL*Net message from client'.