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.