Database Journal
MS SQL Oracle DB2 Access MySQL PostgreSQL Sybase PHP SQL Etc SQL Scripts & Samples Links Database Forum

» Database Journal Home
» Database Articles
» Database Tutorials
MS SQL
Oracle
DB2
MS Access
MySQL
» RESOURCES
Database Tools
SQL Scripts & Samples
Links
» Database Forum
» Sitemap
Free Newsletters:
DatabaseDaily  
News Via RSS Feed


follow us on Twitter
Database Journal |DBA Support |SQLCourse |SQLCourse2
 

Featured Database Articles

Oracle

Posted Jul 28, 2004

Inserting Custom Messages in Oracle Alert/Trace files

By Amar Kumar Padhi

A colleague of mine showed me a link on the OTN site regarding writing messages to alert log and trace files. I probed further and came across a couple of routines in the DBMS_SYSTEM package that allows us to insert our own customized messages in Alert log and/or trace files. I tried this feature and found it to be quite powerful as regards its usage. For example, I use it for the following purposes:

1. A scheduled routine checks the available space and puts an alert for tablespaces left with less than 100MB of space (or as is the case for your site).

2. Any changes in the Application profiles are recorded in Alerts. Profile setup is important and changing it results in problems for some of the modules running at my site.

One may argue that these can be inserted in a table and monitored rather than over loading the Alert or Trace files. This is also a good way of doing it. However, what I have found is that Alert log and Trace files are the focal points that DBAs will monitor to check on their databases. Inserting customized messages could help, to a great extent, to identify not only database issues but also application problems that are critical for running the system.

I could not find any information regarding these routines in the manuals and believe they are undocumented features (Just like some other very good features). So use it at your own risk. I, for one, am already using this in production. Apart from this article, you can search the web for more intricate details.

Routines in DBMS_SYSTEM package

The following routines can be used to write vital information to Alerts and Trace files.

KSDIND:
Does an indent in the form of inserting colons (:) before the next write is carried out.

The indent levels are from 0 to 30. This option could be used to separate the custom messages from the existing oracle messages. For example, I could search the Alert Log for messages starting with 5 colons to identify Application generated messages. The default is 0. This process fails to work in some cases (mentioned below). As a safety, I also add a standard prefix to all messages to identify application related messages.

KSDWRT:
Writes a message to the alert file. The first parameter DEST takes input as 1 (write to trace file), 2 (write to alert log) or 3 (write to both trace and alert log files). The second parameter TST is the actual text message that should go into the file(s).

KSDDDT:
Writes the timestamp to a trace file, this cannot be used for the Alert log.

KSDFLS:
Used for flushing any pending output to the files.

Example of inserting in alert log

Below is a sequence from SQL*Plus to insert a line in the Alert log:

SQL> exec dbms_system.ksdind(10);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.87
SQL> exec dbms_system.ksdwrt(2, 'testing for alert log writing');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00

Below is the extract from the Alert log file. Ten colons have been added because of the first call to DBMS_SYSTEM.KSDIND. The second call to DBMS_SYSTEM.KSDWRT actually writes the text message, appended to the colon line.

$ tail -10 alert_PROD.log
Sat Jul 24 09:38:40 2004
ARC0: Beginning to archive log# 4 seq# 35469
Sat Jul 24 09:38:40 2004
Thread 1 advanced to log sequence 35470
  Current log# 1 seq# 35470 mem# 0: /redolog/log01a.dbf
  Current log# 1 seq# 35470 mem# 1: /redolog.mirror/log01b.dbf
Sat Jul 24 09:39:00 2004
ARC0: Completed archiving log# 4 seq# 35469
Sat Jul 24 11:07:50 2004
::::::::::testing for alert log writing

Below is a sequence from SQL*Plus to insert a line in a trace file:

jaJA>exec dbms_system.ksdind(10);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.47
jaJA>exec dbms_system.ksdwrt(1, 'testing for writing in trace file');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.15
jaJA>exec dbms_system.ksdind(10);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.16
jaJA>exec dbms_system.ksdwrt(1, 'testing for writing in trace file 2');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.16

jaJA>exec dbms_system.ksdddt;

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
jaJA>exec dbms_system.ksdwrt(1, 'end of testing.');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.16

The example above is the trace file generated by the session
below:

$ more prod_ora_19156.trc
Dump file /proddb/oracle/proddb/8.1.7/admin/udump/prod_ora_19156.trc
Oracle8i Enterprise Edition Release 8.1.7.4.0 - Production
With the Partitioning option
JServer Release 8.1.7.4.0 - Production
ORACLE_HOME = /proddb/oracle/proddb/8.1.7
System name:    SunOS
Node name:      oratester
Release:        5.8
Version:        Generic_108528-27
Machine:        sun4u
Instance name: PROD
Redo thread mounted by this instance: 1
Oracle process number: 54
Unix process pid: 19156, image: oracle@oratester (TNS V1-V3)

*** 2004-07-24 11:23:55.065
*** SESSION ID:(66.30889) 2004-07-24 11:23:55.028
*** 2004-07-24 11:24:08.524
::::::::::testing for writing in trace file
::::::::::testing for writing in trace file 2
*** 2004-07-24 11:26:28.020
*** 2004-07-24 11:26:41.279
end of testing.

No COMMIT/ROLLBACK is required for the above procedure calls. These are carried instantly, once executed.

However, some issues were identified regarding these calls.

In certain conditions, when I issued the Alert log insertion first (using a value of 2 for the first parameter in KSDWRT) and then the Trace file insertion (using a value of 1 for the first parameter in KSDWRT), the trace file was not created. Even using the DBMS_SYSTEM.KSDFLS procedure did not help. This behavior is not constant for me as sometimes it does actually generate a trace file and one time it did not. If the session already has a trace file generated, then the above condition inserts into the existing trace file. I am mentioning this here in case you plan to do something along similar lines and encounter it.

In another instance, the DBMS_SYSTEM.KSDIND refused to put colons in the Alert file. This setup was on Oracle 10g on Fedora core 1 (characterset UTF8). Your production box will definitely not have this combination but while testing you may encounter this scenario.

The written messages do not show up in the alert log if SQL_TRACE is set to true. However, it will show up in Trace file as part of the parsing process. Setting trace event 10046 should behave the same way, but the messages actually show up in the alert log file and trace file on my setup (level 1 trace with level 3 writing from KSDWRT). Moreover, the KSDIND call was ignored and no indentation was produced along with the messages.

Look at the example below and the output in the trace file:

orAP>exec dbms_system.ksdind(10);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.46
orAP>exec dbms_system.ksdwrt(1, 'testing for trace');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.15
orAP>alter session set sql_trace=true;

Session altered.

Elapsed: 00:00:00.15
orAP>exec dbms_system.ksdind(10);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.15
orAP>exec dbms_system.ksdwrt(1, 'testing for trace2');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
orAP>alter session set sql_trace=false;

Session altered.

Elapsed: 00:00:00.00
orAP>exec dbms_system.ksdind(10);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.16
orAP>exec dbms_system.ksdwrt(1, 'testing for trace3');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.16

The output in the trace file is as below:

$ tail -30 prod_ora_7034.trc
*** 2004-07-25 08:34:19.876
::::::::::testing for trace
*** 2004-07-25 08:34:57.826
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
=====================
PARSING IN CURSOR #1 len=33 dep=0 uid=173 oct=42 lid=173 tim=1698827382 hv=3732290820 ad='83c36624'
alter session set sql_trace=true
END OF STMT
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1698827382
=====================
PARSING IN CURSOR #1 len=36 dep=0 uid=173 oct=47 lid=173 tim=1698827678 hv=3340943640 ad='8292b41c'
BEGIN dbms_system.ksdind(10); END;
END OF STMT
PARSE #1:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1698827678
::::::::::EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1698827678
=====================
PARSING IN CURSOR #1 len=57 dep=0 uid=173 oct=47 lid=173 tim=1698827901 hv=3895572068 ad='842819e8'
BEGIN dbms_system.ksdwrt(1, 'testing for trace2'); END;
END OF STMT
PARSE #1:c=1,e=1,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1698827901
testing for trace2
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1698827901
*** 2004-07-25 08:35:55.634
=====================
PARSING IN CURSOR #1 len=34 dep=0 uid=173 oct=42 lid=173 tim=1698833163 hv=1582735206 ad='8243df50'
alter session set sql_trace=false
END OF STMT
PARSE #1:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1698833163
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1698833163
::::::::::testing for trace3

Procedure for inserting alert text

Below, is a custom routine that will insert messages into Alert log as well as create a trace file. Instead of giving direct access on the DBMS_SYSTEM package, a custom routine can be written and execute privilege given on it to other users. Please note the below routine can be further modified to insert messages in alert log only or trace file only or both, by passing another parameter that indicates the same.

The parameter L_INDLVL is set to 5, i.e., five colons will be placed before the custom message in the alert/trace files.

create or replace procedure app_alert(pi_mesg in varchar2) is
  l_indlvl pls_integer := 5;
  l_msglvl pls_integer := 3;
begin
  if pi_mesg is not null then
    dbms_system.ksdind(l_indlvl);
    dbms_system.ksdwrt(l_msglvl, 'App Custom mesg: ' || substr(pi_mesg, 1, 150));
  end if;
end;
/

I call the above routine in one of my application programs, APP_ASO_CLEARING. The routine exits with an error if the concerned table is locked by someone. The error is then inserted into the alert log and trace file using the above custom routine.

Running app_aso_clearing routine:

SQL> exec app_aso_clearing;

PL/SQL procedure successfully completed.

Alert log output:

$ tail -5 alert_PROD.log
ARC0: Completed archiving log# 1 seq# 35306
Mon Jun 14 08:48:17 2004
:::::APP Custom mesg: The ASO_ORDER_FEEDBACK_T was locked in moment, 
the purging process was not executed. [app_aso_clearing]
Mon Jun 14 08:52:07 2004
Completed checkpoint up to RBA [0x89eb.2.10], SCN: 0x0000.32830d6a

Trace file output:

$ more prod_ora_6339.trc
Dump file /proddb/oracle/proddb/8.1.7/admin/udump/prod_ora_6339.trc
Oracle8i Enterprise Edition Release 8.1.7.4.0 - Production
With the Partitioning option
JServer Release 8.1.7.4.0 - Production
ORACLE_HOME = /proddb/oracle/proddb/8.1.7
System name:    SunOS
Node name:      jashan
Release:        5.8
Version:        Generic_108528-07
Machine:        sun4u
Instance name: PROD
Redo thread mounted by this instance: 1
Oracle process number: 65
Unix process pid: 6339, image: oracle@jashan (TNS V1-V3)

*** 2004-06-14 08:48:17.021
*** SESSION ID:(83.32) 2004-06-14 08:48:16.965
*** 2004-06-14 08:48:17.021
:::::APP Custom mesg: The ASO_ORDER_FEEDBACK_T was locked in moment, 
the purging process was not executed. [app_aso_clearing]

Conclusion

Use at your own risk! As the above features are not documented, there is no telling what changes they might go through or whether they will be available in the future. I have tried the above features on Oracle 8i and Oracle 10g.

» See All Articles by Columnist Amar Kumar Padhi



Oracle Archives

Comment and Contribute

 


(Maximum characters: 1200). You have characters left.

 

 




Latest Forum Threads
Oracle Forum
Topic By Replies Updated
Oracle Data Mining: Classification jan.hasller 0 July 5th, 07:19 AM
Find duplicates - Unique IDs Lava 5 July 2nd, 08:30 AM
no matching unique or primary key rcanter 1 April 25th, 12:32 PM
Update values of one table based on condition of values in other table using Trigger Gladiator 3 February 29th, 06:01 PM


















Thanks for your registration, follow us on our social networks to keep up-to-date