Thread: How to EXPLAIN a trigger function

As part of our monitoring system we have a process that on every incomming
event inserts a row into a dummy table. This INSERT is intercepted by BEFORE
INSERT trigger that checks if the event matches some existing incident, if
yes, then it updates the incident data, else it creates a new incident.

There was a major malfunction in our network, and the system generated about
300 events per second. We found that during this eriod our monitoring
contained obsolete data, because the trigger bottlenecked whole system. We
would like to know if there is simple way to EXPLAIN the trigger function, so
we could optimize it.

We are using PostgreSQL 9.4.3. All processes are single-threaded and there
were no problems caused by concurrency anomalies (we checked by temporarily
using SERIALIZABLE - there were no failing transactions and the obsoleteness
was still there).

Simplified version looks like this:

CREATE TABLE dummytable (id int, data text, ...);
CREATE TABLE incidents (id int, data text, lastupdate timestamp, ...);

The monitoring process does:
INSERT INTO dummytable VALUES (id, data);

The trigger does
BEGIN
    SELECT id INTO vid FROM incidents WHERE field1 = NEW.field1 AND (field2 =
NEW.field2 OR field3 = NEW.field3);

    IF vid IS NULL THEN
        UPDATE incidents SET lastupdate = NOW();
    ELSE
        INSERT INTO incidents VALUES (id, data)
    END IF;

    RETURN NULL;
END;


The trigger took about 12 ms to do its work, as we found out by doing
EXPLAIN ANALYZE INSERT INTO dummytable;
so it was clearly a problem.

I looked the various Internet resources and found an information that stored
procedures are similar to prepared statements by computing the execution plan
once at creation time. We thought the first SELECT could use some suboptimal
plan and changed it to

EXECUTE 'SELECT id FROM incidents WHERE field1 = NEW.field1 AND (field2 =
NEW.field2 OR field3 = NEW.field3);' INTO vid USING ...;

We did it by trial and error, because we couldn't find any way to EXPLAIN the
trigger function. Is there any way to do it? For now we were lucky to hit the
right solution quickly, but in some future case we could waste many hours by
looking basically everywhere.

Notes:
* The SQL is simplified, because I am not very interested in finding solution
to this exact case. I want to "learn to fish" not have a "fish given to me".
* We could skip the trigger and just do it in application, but we fear about
the cost of round trips
* We are currently thinking about doing  the INSERTs in parallel, and we are
aware of potential problems with concurrent transaction

Zdenek Belehrádek wrote:
> We
> would like to know if there is simple way to EXPLAIN the trigger function, so
> we could optimize it.

I believe that the auto_explain module could help you:
http://www.postgresql.org/docs/current/static/auto-explain.html

If you turn on "auto_explain.log_nested_statements" and set
"auto_explain.log_min_duration" low enough, the execution plans of
all SQL statements calle from a function will be logged.

Yours,
Laurenz Albe

Dne Po 17. srpna 2015 13:25:25, Albe Laurenz napsal(a):
> Zdenek Belehrádek wrote:
>
> > We
> > would like to know if there is simple way to EXPLAIN the trigger function,
> > so we could optimize it.
>
>
> I believe that the auto_explain module could help you:
> http://www.postgresql.org/docs/current/static/auto-explain.html
>
> If you turn on "auto_explain.log_nested_statements" and set
> "auto_explain.log_min_duration" low enough, the execution plans of
> all SQL statements calle from a function will be logged.
>
> Yours,
> Laurenz Albe

I did not know about this, it could be useful in future. Thanks.

Sadly, it does not solve our problem. When used on the INSERT INTO dummytable,
it produces:

2015-08-17 14:08:14 GMT LOG:  duration: 1.274 ms  plan:
        Query Text: INSERT INTO dummytable [...]
        Insert on dummytable  (cost=44.44..44.45 rows=1 width=0) (actual
time=2.956..2.956 rows=0 loops=1)
          InitPlan 1 (returns $0)
[...]
          ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual
time=0.013..0.013 rows=1 loops=1)

There is nothing in the log about calling trigger. I edited the trigger
function so it would use the slow select, and the output in the log was
exactly  the same (not counting different - longer - durations).

When I do EXPLAIN ANALYZE, at least I get some info about the trigger:

Insert on dummytable  (cost=44.44..44.45 rows=1 width=0) (actual
time=1.135..1.135 rows=0 loops=1)
   InitPlan 1 (returns $0)
[...]
   ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual time=0.018..0.018
rows=1 loops=1)
 Planning time: 0.111 ms
 Trigger trigger: time=1.113 calls=1
 Execution time: 1.244 ms


-- Zdeněk Bělehrádek

Dne Po 17. srpna 2015 13:25:25, Albe Laurenz napsal(a):
> Zdenek Belehrádek wrote:
>
> > We
> > would like to know if there is simple way to EXPLAIN the trigger function,
> > so we could optimize it.
>
>
> I believe that the auto_explain module could help you:
> http://www.postgresql.org/docs/current/static/auto-explain.html
>
> If you turn on "auto_explain.log_nested_statements" and set
> "auto_explain.log_min_duration" low enough, the execution plans of
> all SQL statements calle from a function will be logged.
>
> Yours,
> Laurenz Albe

Oh, sorry, I am an idiot. I totally missed the
auto_explain.log_nested_statements. With it set to true, I am getting the
trigger's EXPLAIN too.

Thank you very much!

--Zdeněk Bělehrádek.