How to find out which session caused ORA-01555?

Some times ago, my colleague asked me this question since we frequently recieved ORA-01555 alert email from our reporting database. The alerts came from the alert log monitoring job, which contains sql text but nothing more than that. I searched the internet and was excited to find a thread on the AskTom site, which appeared to be exactly addressing our needs.

Based on that thread, I tested and installed the following database event trigger in our reporting database:

create or replace trigger servererror_trig
after servererror on database
declare
   var_id        number; 
   var_user      varchar2(30);
   var_osuser    varchar2(30);
   var_machine   varchar2(64);
   var_process   varchar2(8);
   var_program   varchar2(48);
   var_txt       varchar2(4000);
   l_sql_text    ora_name_list_t;
   l_n           number;
begin
  if ( is_servererror(1555) )
  then
     select
      username,
      osuser,
      machine,
      process,
      program
    into
      var_user,
      var_osuser,
      var_machine,
      var_process,
      var_program
    from
      v$session
    where
     audsid=userenv('sessionid');
 
     l_n := ora_sql_txt( l_sql_text );
     var_txt :=  'ora_sysevent = ' || ora_sysevent || ' ora_login_user = ' || ora_login_user || 
                   ' ora_server_error = ' || ora_server_error(1) || chr(10); 
 
     for i in 1 .. l_n
     loop
        var_txt := var_txt || l_sql_text(i); 
     end loop;
 
     insert into
      db_admin.servererror_log
     values(
      dbms_standard.server_error(1),
      sysdate,
      var_user,
      var_osuser,
      var_machine,
      var_process,
      var_program,
      var_txt);
  end if;
end;
/

At begining, it looked good, however, soon I found that not all ORA-01555s that were appeared in the alert log were captured by this trigger. Being aware that some tables in the reporting database are referred by remote SQLs through dblink, I set up a test to see if this trigger workes for remote queries.

First of all, I did everything in the local database:

denis@DBWRKEV1> -- create undo tablespace small datafile  '/tmp/small.dbf' size 2m autoextend OFF;
denis@DBWRKEV1> drop table ora_1555;
 
Table dropped.
 
denis@DBWRKEV1> create table ora_1555 as select * from all_objects;
 
Table created.
 
denis@DBWRKEV1> alter system set undo_tablespace = small;
 
System altered.
 
denis@DBWRKEV1> 
denis@DBWRKEV1> --  Now open a cursor -- it is read consistent as of NOW
denis@DBWRKEV1> variable x refcursor
denis@DBWRKEV1> exec open :x for select * from ora_1555;
 
PL/SQL procedure successfully completed.
 
denis@DBWRKEV1> 
denis@DBWRKEV1> -- generate lots of undo and commit and do it over again and again,
denis@DBWRKEV1> 
denis@DBWRKEV1> begin
  2    for i in 1 .. 10
  3    loop
  4         loop
  5            delete from ora_1555 where rownum <= 1000;
  6            exit when sql%rowcount = 0;
  7            commit;
  8         end loop;
  9             commit;
 10      insert into ora_1555 select * from all_objects;
 11      commit;
 12    end loop;
 13  end;
 14  /
 
PL/SQL procedure successfully completed.
 
denis@DBWRKEV1> 
denis@DBWRKEV1> print x
ERROR:
ORA-01555: snapshot too old: rollback segment number 19 with name "_SYSSMU19$" too small
 
 
 
no rows selected
 
denis@DBWRKEV1> 
denis@DBWRKEV1> 
denis@DBWRKEV1> select * from db_admin.servererror_log;
 
ERROR                                                             TIMESTAMP           USERNAME
----------------------------------------------------------------- ------------------- ------------------------------
OSUSER                         MACHINE                                                          PROCESS
------------------------------ ---------------------------------------------------------------- --------
PROGRAM
------------------------------------------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------
1555                                                              2010-03-19 12:12:01 DENIS
oracle                         sjscqdd1                                                         19823
sqlplus@sjscqdd1 (TNS V1-V3)
ora_sysevent = SERVERERROR ora_login_user = DENIS ora_server_error = 1555
SELECT * FROM ORA_1555
 

Check the alert log, I can find:

Fri Mar 19 12:12:01 2010
ORA-01555 caused by SQL statement below (SQL ID: 0kj3gdzq34dk9, Query Duration=100 sec, SCN: 0x09e8.6a0a74a2):
Fri Mar 19 12:12:01 2010
SELECT * FROM ORA_1555

Now I do a test from remote db:

-- At remote, open a curor for the test table through db link

denis@REMOTEDB>variable x refcursor
denis@REMOTEDB>exec open :x for select * from ora_1555@dbwrkev1;

PL/SQL procedure successfully completed.

-- At local

denis@DBWRKEV1> begin
  2    for i in 1 .. 10
  3    loop
  4         loop
  5            delete from ora_1555 where rownum <= 1000;
  6            exit when sql%rowcount = 0;
  7            commit;
  8         end loop;
  9             commit;
 10      insert into ora_1555 select * from all_objects;
 11      commit;
 12    end loop;
 13  end;
 14  /

PL/SQL procedure successfully completed.

-- At remote

denis@REMOTEDB>print x
ERROR:
ORA-01555: snapshot too old: rollback segment number 19 with name "_SYSSMU19$" too small
ORA-02063: preceding line from DBWRKEV1



no rows selected

-- Local alert log (PST)

Fri Mar 19 12:20:11 2010
ORA-01555 caused by SQL statement below (SQL ID: 7xnnz01z88xhp, Query Duration=249 sec, SCN: 0x09e8.6a135bd3):
Fri Mar 19 12:20:11 2010
SELECT "A1"."OWNER","A1"."OBJECT_NAME","A1"."SUBOBJECT_NAME","A1"."OBJECT_ID","A1"."DATA_OBJECT_ID","A1"."OBJECT_TYPE","
A1"."CREATED","A1"."LAST_DDL_TIME","A1"."TIMESTAMP","A1"."STATUS","A1"."TEMPORARY","A1"."GENERATED","A1"."SECONDARY" FRO
M "ORA_1555" "A1"

Note: it is intereting to see Oracle rewrites the original SQL in such a way that the '*' is expanded to full column list and charaters are capitalized.

-- Remote alert log
Not see any 1555, I am a little surprized.

-- at local note the ORA-01555 in alert log at time 12:20 not captured by the trigger.

denis@DBWRKEV1> select * from db_admin.servererror_log;
 
ERROR                                                             TIMESTAMP           USERNAME
----------------------------------------------------------------- ------------------- ------------------------------
OSUSER                         MACHINE                                                          PROCESS
------------------------------ ---------------------------------------------------------------- --------
PROGRAM
------------------------------------------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------
1555                                                              2010-03-19 12:12:01 DENIS
oracle                         sjscqdd1                                                         19823
sqlplus@sjscqdd1 (TNS V1-V3)
ora_sysevent = SERVERERROR ora_login_user = DENIS ora_server_error = 1555
SELECT * FROM ORA_1555

In conclusion, the database event trigger solution to identify sessions cause ORA-01555 has its limitation when the session is initiated by a remote query through dblink.