Waiting for 9.4 – auto_explain: Add logging of trigger execution

On 4th of March, Alvaro Herrera committed patch:

auto_explain: Add logging of trigger execution
 
Author: Kyotaro HORIGUCHI
Reviewed-by: Jaime Casanova

The change is pretty simple, and for most people invisible. But – if you're using auto_explain, which you should. And you're using it's log_analyze mode (which you shouldn't on production, but might want to in certain cases on development databases, there is a new setting:

log_triggers

which, when turned on, will log also information about trigger timings.

For example, let's assume simple table:

CREATE TABLE test (
    id serial PRIMARY KEY,
    whatever text
);
 
CREATE FUNCTION test_trg() RETURNS TRIGGER AS $$
BEGIN
    NEW.whatever := LOWER(NEW.whatever);
    RETURN NEW;
END;
$$ LANGUAGE plpgsql;
 
CREATE TRIGGER test_trg
    BEFORE INSERT OR UPDATE ON test
    FOR each ROW EXECUTE PROCEDURE test_trg();

Let's also enable auto_explain and it's analyze mode:

$ LOAD 'auto_explain';
LOAD
 
$ SET auto_explain.log_min_duration = 0;
SET
 
$ SET auto_explain.log_analyze = ON;
SET

With this in place, in the session with auto_explain loaded, I run:

$ INSERT INTO test (whatever) VALUES ('123');
INSERT 0 1

In pg logs, I get:

2014-03-11 20:19:48.475 CET depesz@depesz 18167 [LOCAL] LOG:  duration: 8.015 ms  plan:
        Query Text: INSERT INTO test (whatever) VALUES ('123');
        INSERT ON test  (cost=0.00..0.01 ROWS=1 width=0) (actual TIME=8.014..8.014 ROWS=0 loops=1)
          ->  RESULT  (cost=0.00..0.01 ROWS=1 width=0) (actual TIME=0.069..0.069 ROWS=1 loops=1)
2014-03-11 20:19:48.492 CET depesz@depesz 18167 [LOCAL] LOG:  duration: 25.789 ms  statement: INSERT INTO test (whatever) VALUES ('123');

Now, if I'll also set log_triggers to true, and rerun the insert:

$ SET auto_explain.log_triggers = ON;
SET
 
$ INSERT INTO test (whatever) VALUES ('567');
INSERT 0 1

Logged information will have one more line:

2014-03-11 20:22:04.940 CET depesz@depesz 18167 [LOCAL] LOG:  duration: 0.082 ms  plan:
        Query Text: INSERT INTO test (whatever) VALUES ('567');
        INSERT ON test  (cost=0.00..0.01 ROWS=1 width=0) (actual TIME=0.082..0.082 ROWS=0 loops=1)
          ->  RESULT  (cost=0.00..0.01 ROWS=1 width=0) (actual TIME=0.015..0.015 ROWS=1 loops=1)
        TRIGGER test_trg: TIME=0.036 calls=1
2014-03-11 20:22:04.950 CET depesz@depesz 18167 [LOCAL] LOG:  duration: 10.770 ms  statement: INSERT INTO test (whatever) VALUES ('567');

That is: “Trigger test_trg: time=0.036 calls=1“.

Nice. It certainly has its uses, and can help debugging complicated situations/queries. Thanks you, Kyotaro.

4 thoughts on “Waiting for 9.4 – auto_explain: Add logging of trigger execution”

  2. Nice one.

    Is there any way to log the plan of the select statements in the trigger body.

    Thanks,
    Dinesh

Comments are closed.