PL/SQL backtraces for debugging

For many PL/SQL developers, this might be common sense, but for one of our customers, this was an unknown PL/SQL feature: Backtraces.

When your application raises an error somewhere deep down in the call stack, you don’t get immediate information about the exact source of the error. For large PL/SQL applications, this can be a pain. One workaround is to keep track of statement numbers that were last executed before any error occurred:

DECLARE
  v_statement_no := 0;
BEGIN
  v_statement_no := 1;
  SELECT ...

  v_statement_no := 2;
  INSERT ...

  v_statement_no := 3;
  ...
EXCEPTION
  WHEN OTHERS THEN
    -- Log error message somewhere
    logger.error(module, v_statement_no, sqlerrm);
END;

The above looks an awful lot like println-debugging, a thing that isn’t really known to Java developers ;-)

But println-debugging isn’t necessary in PL/SQL either. Use the DBMS_UTILITY.FORMAT_ERROR_BACKTRACE function, instead! An example:

DECLARE
  PROCEDURE p4 IS BEGIN
    raise_application_error(-20000, 'Some Error');
  END p4;
  PROCEDURE p3 IS BEGIN
    p4;
  END p3;
  PROCEDURE p2 IS BEGIN
    p3;
  END p2;
  PROCEDURE p1 IS BEGIN
    p2;
  END p1;

BEGIN
  p1;
EXCEPTION
  WHEN OTHERS THEN
    dbms_output.put_line(sqlerrm);
    dbms_output.put_line(
      dbms_utility.format_error_backtrace
    );
END;
/

The above PL/SQL block generates the following output:

ORA-20000: Some Error
ORA-06512: at line 3
ORA-06512: at line 6
ORA-06512: at line 9
ORA-06512: at line 12
ORA-06512: at line 16

You can see exactly what line number generated the error. If you’re not using local procedures in anonymous blocks (which you quite likely aren’t), this gets even more useful:

CREATE PROCEDURE p4 IS BEGIN
  raise_application_error(-20000, 'Some Error');
END p4;
/
CREATE PROCEDURE p3 IS BEGIN
  p4;
END p3;
/
CREATE PROCEDURE p2 IS BEGIN
  p3;
END p2;
/
CREATE PROCEDURE p1 IS BEGIN
  p2;
END p1;
/

BEGIN
  p1;
EXCEPTION
  WHEN OTHERS THEN
    dbms_output.put_line(sqlerrm);
    dbms_output.put_line(
      dbms_utility.format_error_backtrace
    );
END;
/

The above now outputs:

ORA-20000: Some Error
ORA-06512: at "PLAYGROUND.P4", line 2
ORA-06512: at "PLAYGROUND.P3", line 2
ORA-06512: at "PLAYGROUND.P2", line 2
ORA-06512: at "PLAYGROUND.P1", line 2
ORA-06512: at line 2

To learn more about the DBMS_UTILITY package, please consider the manual. True to the nature of all things called “UTILITY”, it really contains pretty much random things that you wouldn’t expect there :-)

Debug logging SQL with jOOQ

This nice little feature is not much advertised in the jOOQ manual, but probably it’s something that most of us developers want and love when we have it. When you put log4j or slf4j on the classpath along with jOOQ, then jOOQ will use those frameworks for logging according to your configuration. While jOOQ is pretty quiet on ERROR/WARN/INFO level logging, it becomes quite a chatty tool on DEBUG/TRACE level.

DEBUG level logging example

Check out some sample DEBUG level output when executing this query:

Result<Record> result = create
  .select(TAuthor.LAST_NAME, create.count().as("c"))
  .from(T_BOOK)
  .join(T_AUTHOR)
  .on(TBook.AUTHOR_ID.equal(TAuthor.ID))
  .where(TBook.TITLE.notEqual("1984"))
  .groupBy(TAuthor.LAST_NAME)
  .having(create.count().equal(2))
  .fetch();

And the output is:


Executing query          : select "t_author"."last_name", 
  count(*) as "c" from "t_book" join "t_author" on 
  "t_book"."author_id" = "t_author"."id" where 
  "t_book"."title" <> '1984' group by "t_author"."last_name"
  having count(*) = 2

Fetched result           : +---------+----+
                         : |last_name|   c|
                         : +---------+----+
                         : |Coelho   |   2|
                         : +---------+----+
Statement executed       : Total: 3.911ms


The query text is printed to the log output with inlined parameters (i.e. bind variables are replaced for logging). Then a text table representation of the result’s first 5 rows is printed before the query execution time.

TRACE level logging example

On trace level, you can see even more of jOOQ’s internals, although usually this is only needed when debugging jOOQ:


Executing query          : select "t_author"."last_name", 
  count(*) as "c" from "t_book" join "t_author" on 
  "t_book"."author_id" = "t_author"."id" where 
  "t_book"."title" <> '1984' group by "t_author"."last_name"
  having count(*) = 2

Preparing statement      : select "t_author"."last_name", 
  count(*) as "c" from "t_book" join "t_author" on 
  "t_book"."author_id" = "t_author"."id" where 
  "t_book"."title" <> cast(? as varchar) 
  group by "t_author"."last_name" 
  having count(*) = cast(? as int)

Statement prepared       : Total: 1.451ms, +0.435ms
Binding variable 1       : 1984 (class java.lang.String)
Binding variable 2       : 2 (class java.lang.Integer)
Variables bound          : Total: 1.808ms, +0.356ms
Attaching                : RecordImpl [ RecordImpl [values=[null, null]] ]
Fetching record          : RecordImpl [values=[Coelho, 2]]
Fetched result           : +---------+----+
                         : |last_name|   c|
                         : +---------+----+
                         : |Coelho   |   2|
                         : +---------+----+
Statement executed       : Total: 6.29ms, +4.481ms


In addition to the previously shown DEBUG-level output, you’ll also find the true SQL statement that is executed, including bind variables and some additional type-casts introduced by jOOQ. Time measuring is divided into 3 steps: statement preparing, variable binding, and statement execution. Also, all bind variables are documented, and every fetched record is documented. That’s a lot of logging. Be sure to turn it off when not needed!

Logging configuration

In future versions of jOOQ, logging will become more configurable