Open World 2011 Presentations
I want to thank everyone for attending my two sessions yesterday. I also want to thank the OAUG Database SIG for the opportunity to present how we’re using DBFS HS at NIF and the IOUG for letting me speak about instrumenting applications for Oracle databases. Since I ran short on time in the instrumentation talk, I wanted to post the details of the logging and debugging examples.
The first example shows setting the level to INFO and then running two different anonymous PL/SQL blocks. The first doesn’t set the module and action and so it doesn’t output anything. The second block does set module and action and so the dblog calls output to the console and the log table.
INFO Level:
SQL> !cat insert_info.sql
insert into dblog_settings values(1,'module','action',null,null,null,'INFO','N');
commit;
SQL> @insert_info
1 row created.
Commit complete.
SQL> @show_settings
USERNAME SID INST_ID module action level trace
-------- ---------- ---------- -------- -------- ------ -----
module action INFO N
SQL> !cat dblog_info.sql
declare
l_num number;
begin
dblog.info('Before statement');
select 1 into l_num from dual;
dblog.info('After statement');
exception
when others then
dblog.error('Error message');
end;
/
SQL> @dblog_info
PL/SQL procedure successfully completed.
SQL> @show_log
no rows selected
SQL> !cat dblog_info_task.sql
declare
l_num number;
begin
ilo_task.begin_task(
module => 'module',
action => 'action');
--
dblog.info('Before statement');
select 1 into l_num from dual;
dblog.info('After statement');
--
ilo_task.end_task;
end;
/
SQL> @dblog_info_task.sql
INFO:DBAMON:51:1:03-OCT-11 02.36.40.269133 PM:module:action
INFO:DBAMON.ANONYMOUS BLOCK:Line 8:Before statement
INFO:DBAMON:51:1:03-OCT-11 02.36.40.275672 PM:module:action
INFO:DBAMON.ANONYMOUS BLOCK:Line 10:After statement
PL/SQL procedure successfully completed.
SQL> @show_log
USERNAME SID INST_ID DATETIME module action level TASKTIME OBJECT_NAME LINE_NO TEXT
-------- ---------- ---------- ------------------ -------- -------- ------ ---------- ---------------------- ---------- --------------------
DBAMON 51 1 03-OCT-11 02.36.40 module action INFO DBAMON.ANONYMOUS BLOCK 8 Before statement
DBAMON 51 1 03-OCT-11 02.36.40 module action INFO DBAMON.ANONYMOUS BLOCK 10 After statement
SQL>
The next example shows how task times can be recorded using the ILO to mark the begin and end times:
SQL> @clean_log
Table truncated.
SQL> !cat dblog_info_tasktime.sql
declare
l_num number;
begin
ilo_task.begin_task(
module => 'module',
action => 'action',
comment => 'Task1',
begin_time => systimestamp);
--
dblog.info('Before statement');
select 1 into l_num from dual;
dblog.info('After statement');
--
ilo_task.end_task(
end_time => systimestamp);
end;
/
SQL> @dblog_info_tasktime.sql
INFO:DBAMON:60:1:03-OCT-11 02.41.48.059157 PM:module:action
INFO:DBAMON.ANONYMOUS BLOCK:Line 10:Before statement
INFO:DBAMON:60:1:03-OCT-11 02.41.48.107721 PM:module:action
INFO:DBAMON.ANONYMOUS BLOCK:Line 12:After statement
TASK_TIME:DBAMON:60:1:03-OCT-11 02.41.48.114385 PM:module:action
TASK_TIME:ILO.ILO_TIMER:Line 127:Task1
PL/SQL procedure successfully completed.
SQL> @show_log
USERNAME SID INST_ID DATETIME module action level TASKTIME OBJECT_NAME LINE_NO TEXT
-------- ---------- ---------- ------------------ -------- -------- ------ ---------- ---------------------- ---------- --------------------
DBAMON 60 1 03-OCT-11 02.41.48 module action INFO DBAMON.ANONYMOUS BLOCK 10 Before statement
DBAMON 60 1 03-OCT-11 02.41.48 module action INFO DBAMON.ANONYMOUS BLOCK 12 After statement
DBAMON 60 1 03-OCT-11 02.41.48 module action .057362 ILO.ILO_TIMER 127 Task1
SQL>
The third example shows how to invoke tracing when a task is matched and the trace_enabled flag has been set:
SQL> !cat delete_info.sql
delete from dblog_settings;
commit;
SQL> @delete_info.sql
1 row deleted.
Commit complete.
SQL> !cat insert_trace.sql
insert into dblog_settings values(1,'module','action',null,null,null,'INFO','Y');
commit;
SQL> @insert_trace.sql
1 row created.
Commit complete.
SQL> @show_settings
USERNAME SID INST_ID module action level trace
-------- ---------- ---------- -------- -------- ------ -----
module action INFO Y
SQL> !cat dblog_trace.sql
declare
l_num number;
begin
ilo_task.begin_task(
module => 'module',
action => 'action');
--
dblog.info('Before statement');
select 1 into l_num from dual;
dblog.info('After statement');
--
ilo_task.end_task;
end;
/
SQL> @dblog_trace.sql
GET_CONFIG: tracing has been enabled
INFO:DBAMON:60:1:03-OCT-11 02.44.49.047982 PM:module:action
INFO:DBAMON.ANONYMOUS BLOCK:Line 8:Before statement
INFO:DBAMON:60:1:03-OCT-11 02.44.49.105359 PM:module:action
INFO:DBAMON.ANONYMOUS BLOCK:Line 10:After statement
PL/SQL procedure successfully completed.
SQL>
SQL> @dispusr
Enter value for 1: dbamon
User Inst Oracle Serial OS User Client Client Service
Name ID SID Number PID ID Status Identifier Info Module Action Name
----------- ----- ------- ------- ------ ----- -------- ---------- ---------- -------------------- -------------------- ---------------
DBAMON 1 50 131 4585 262 INACTIVE SQL Developer SYS$USERS
DBAMON 1 60 473 5466 262 INACTIVE SQL*Plus SYS$USERS
DBAMON 1 48 193 5526 262 ACTIVE SQL*Plus SYS$USERS
SQL>
[oracle@localhost debugging]$ cd /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace
[oracle@localhost trace]$ ls -lrt
total 3108
-rw-rw---- 1 oracle oracle 85 Sep 8 12:16 orcl_ora_2613.trm
-rw-rw---- 1 oracle oracle 828 Sep 8 12:16 orcl_ora_2613.trc
-rw-rw---- 1 oracle oracle 59 Sep 8 12:16 orcl_mman_2690.trm
-rw-rw---- 1 oracle oracle 874 Sep 8 12:16 orcl_mman_2690.trc
< lines deleted >
-rw-rw---- 1 oracle oracle 4021 Oct 3 12:52 orcl_lgwr_2660.trc
-rw-rw---- 1 oracle oracle 412070 Oct 3 12:55 alert_orcl.log
-rw-rw---- 1 oracle oracle 265 Oct 3 14:44 orcl_ora_5466.trm
-rw-rw---- 1 oracle oracle 31902 Oct 3 14:44 orcl_ora_5466.trc
-rw-rw---- 1 oracle oracle 506 Oct 3 14:46 orcl_mmon_2668.trm
-rw-rw---- 1 oracle oracle 5177 Oct 3 14:46 orcl_mmon_2668.trc
[oracle@localhost trace]$ more orcl_ora_5466.trc
Trace file /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_5466.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /home/oracle/app/oracle/product/11.2.0/dbhome_2
System name: Linux
Node name: localhost.localdomain
Release: 2.6.18-194.17.1.0.1.el5
Version: #1 SMP Wed Sep 29 15:40:03 EDT 2010
Machine: i686
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 40
Unix process pid: 5466, image: oracle@localhost.localdomain (TNS V1-V3)
*** 2011-10-03 14:44:49.029
*** SESSION ID:(60.473) 2011-10-03 14:44:49.029
*** CLIENT ID:() 2011-10-03 14:44:49.029
*** SERVICE NAME:(SYS$USERS) 2011-10-03 14:44:49.029
*** MODULE NAME:(SQL*Plus) 2011-10-03 14:44:49.029
*** ACTION NAME:() 2011-10-03 14:44:49.029
=====================
PARSING IN CURSOR #44032292 len=70 dep=1 uid=260 oct=47 lid=260 tim=1317678288954581 hv=3588952050 ad='3ad591d8' sqlid='2qkj5qvayq3zk'
BEGIN dbms_monitor.session_trace_enable (NULL, NULL, TRUE, TRUE); END;
END OF STMT
EXEC #44032292:c=0,e=771,p=0,cr=0,cu=0,mis=1,r=1,dep=1,og=1,plh=0,tim=1317678288954565
CLOSE #44032292:c=0,e=4,dep=1,type=3,tim=1317678289029614
ILO_TASK.BEGIN_TASK[][module][action][oracle~pts/1~sqlplus@localhost.localdomain (TNS V1-V3)~SYS$USERS][]
*** 2011-10-03 14:44:49.030
*** MODULE NAME:(module) 2011-10-03 14:44:49.030
*** ACTION NAME:(action) 2011-10-03 14:44:49.030
=====================
PARSING IN CURSOR #67389968 len=51 dep=1 uid=260 oct=47 lid=260 tim=1317678289030201 hv=3782099507 ad='3ad8fad0' sqlid='0dk9kgvhqwhjm'
BEGIN DBMS_SESSION.SET_IDENTIFIER(:client_id); END;
END OF STMT
BINDS #67389968:
Bind#0
oacdty=01 mxl=2000(255) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=01 csi=873 siz=2000 off=0
kxsbbbfp=03fdcd24 bln=2000 avl=64 flg=09
value="oracle~pts/1~sqlplus@localhost.localdomain (TNS V1-V3)~SYS$USERS"
*** CLIENT ID:(oracle~pts/1~sqlplus@localhost.localdomain (TNS V1-V3)~SYS$USERS) 2011-10-03 14:44:49.047
EXEC #67389968:c=0,e=17330,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=0,tim=1317678289047514
CLOSE #67389968:c=0,e=5,dep=1,type=3,tim=1317678289047606
< Truncated >
[oracle@localhost trace]$
And finally calling the error level in an exception handler. Notice the backtrace information with the line number where the error occurred:
SQL> @dblog_error.sql
FATAL:DBAMON:51:1:03-OCT-11 02.28.30.231192 PM:SQL*Plus:
FATAL:DBAMON.DBLOG:Line 861:Error message
FATAL Oracle error code: 100
FATAL Oracle error message: ORA-01403: no data found
FATAL Backtrace: ORA-06512: at line 4
PL/SQL procedure successfully completed.
SQL> l
1 declare
2 l_num number;
3 begin
4 select 1 into l_num from dummy;
5 exception
6 when others then
7 dblog.error('Error message');
8* end;
SQL> @show_error
USERNAME DATETIME level OBJECT_NAME LINE_NO SQL_ERRNO SQL_ERRMSG SQL_BACKTRACE
-------- ------------------ ------ ---------------------- ---------- ---------- ------------------------- -------------------------
DBAMON 30-SEP-11 01.15.10 ERROR DBAMON.ANONYMOUS BLOCK 7 100 ORA-01403: no data found ORA-06512: at line 4
SQL>
I hope this helps and I’ll post links to the presentations and the instrumentation paper shortly.
Entries
April 9th, 2012 at 1:12 am
[...] There is finally something to publish about the Oracle Logging Framework (OLF). This was a project that I have been thinking about for a long time. I even registered it as a SourceForge project back in 2008. Since then I’ve written about the framework in a paper title “Oracle Instrumentation” that was published in the IOUG SELECT magazine in 2009, and I spoke about the framework at last year’s Oracle Open World. I’ve written about it on this blog, once about integrating with the Method-R ILO here and summarizing the Open World presentations here. [...]