Inserting Custom Messages in Oracle Alert/Trace files

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

Get the Free Newsletter!

Subscribe to Cloud Insider for top news, trends & analysis

Latest Articles