Wednesday, May 9, 2007

Tracing errors

One of the Java developers at my work was having issues with his application generating a "ORA-01401: inserted value too large for column", but we didn't know where, the stack trace from jdbc wasn't giving us anything useful. Previously this hasn't really been problem for me previously, as with perl if I came across something like this, I'd just drop a few quick print's to STDERR to find the errornous statement, however doing so in our Java applications would have taken a quite awhile to go through build cycles and then wait for the next deployment.

Luckily, the Java application has a dedicated user, so it was quite easy to use a login trigger to turn on tracing. The first thing we tried doing was use DBMS_SESSION.SET_SQL_TRACE(TRUE), which is something I had done before for tuning applications. However the volume of data generated made it difficult to find the errors, if they were even logged. After searching around, I found that traps can be set to trace given events, in this case ORA-1401 is what we wanted.

This is exactly what we were after, now we could limit the logging to just the user causing the problems and trap the actual SQL statement causing the problem.

create or replace trigger
logon_trig
AFTER LOGON ON DATABASE
BEGIN

IF USER = 'JAVA_APP' THEN
execute immediate 'alter session set events ''1401 trace name errorstack forever, level 1''';
END IF;

END;

After waiting awhile, the alert_log let me know that the application had thrown the error again.

Errors in file /db/admin/DEV/udump/dev_ora_12720.trc:
ORA-01401: inserted value too large for column


Checking the trace file gave me the SQL

*** SESSION ID:(81.1552) 2007-05-09 13:01:18.282
*** 2007-05-09 13:01:18.282
ksedmp: internal or fatal error
ORA-01401: inserted value too large for column
Current SQL statement for this session:
insert into test.xx values (:"SYS_B_0")
----- Call Stack Trace -----


but not the bind variables, which was a bit of problem, since we wanted to know what was actually too large.

Changing the trace level in the login trigger to level 8 added the bind variables into the trace, and quickly gave us our answer.

bind 0: dty=1 mxl=32(24) mal=00 scl=00 pre=00 oacflg=10 oacfl2=100 size=32 offset=0
bfp=ffffffff7ca76558 bln=32 avl=24 flg=09
value="this is my bind variable"


The ability to set traps for any "ORA-" error is something I will certainly be taking advantage of in the future.

No comments: