Thread: FK triggers misused?
I have performance problem with the following simple update query:
UPDATE posts
SET num_views = num_views + 1
WHERE post_id IN (2526,5254,2572,4671,25);
The table "posts" is a large table with a number of foreign keys (FK).
It seems that the FK triggers for the table are evaluated even though
none of the FK columns are altered. In fact, these FK triggers seems to
constitute a considerable part of the total execution time. See the
below EXPLAIN ANALYZE.
Why are these FK triggers evaluated at all and why do they take so much
time?
------
=> EXPLAIN ANALYZE update posts set num_views = num_views + 1 where
post_id in (2526,5254,2572,4671,25);
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------
Bitmap Heap Scan on posts (cost=10.02..29.81 rows=5 width=1230)
(actual time=0.146..0.253 rows=5 loops=1)
Recheck Cond: ((post_id = 2526) OR (post_id = 5254) OR (post_id =
2572) OR (post_id = 4671) OR (post_id = 25))
-> BitmapOr (cost=10.02..10.02 rows=5 width=0) (actual
time=0.105..0.105 rows=0 loops=1)
-> Bitmap Index Scan on posts_pkey (cost=0.00..2.00 rows=1
width=0) (actual time=0.053..0.053 rows=2 loops=1)
Index Cond: (post_id = 2526)
-> Bitmap Index Scan on posts_pkey (cost=0.00..2.00 rows=1
width=0) (actual time=0.012..0.012 rows=2 loops=1)
Index Cond: (post_id = 5254)
-> Bitmap Index Scan on posts_pkey (cost=0.00..2.00 rows=1
width=0) (actual time=0.008..0.008 rows=2 loops=1)
Index Cond: (post_id = 2572)
-> Bitmap Index Scan on posts_pkey (cost=0.00..2.00 rows=1
width=0) (actual time=0.010..0.010 rows=2 loops=1)
Index Cond: (post_id = 4671)
-> Bitmap Index Scan on posts_pkey (cost=0.00..2.00 rows=1
width=0) (actual time=0.011..0.011 rows=2 loops=1)
Index Cond: (post_id = 25)
Trigger for constraint posts_question_id_fkey: time=50.031 calls=5
Trigger for constraint posts_author_id_fkey: time=22.330 calls=5
Trigger for constraint posts_language_id_fkey: time=1.282 calls=5
Trigger posts_tsvectorupdate: time=61.659 calls=5
Total runtime: 174.230 ms
(18 rows)
cluster <skrald@amossen.dk> writes:
> It seems that the FK triggers for the table are evaluated even though
> none of the FK columns are altered.
Hm, they're not supposed to be, at least not in reasonably modern
PG releases (and one that breaks out trigger runtime in EXPLAIN ANALYZE
should be modern enough IIRC). Exactly which PG release are you
running? Can you provide a self-contained test case?
regards, tom lane
On 2007-04-15, Tom Lane <tgl@sss.pgh.pa.us> wrote: > cluster <skrald@amossen.dk> writes: >> It seems that the FK triggers for the table are evaluated even though >> none of the FK columns are altered. > > Hm, they're not supposed to be, at least not in reasonably modern > PG releases (and one that breaks out trigger runtime in EXPLAIN ANALYZE > should be modern enough IIRC). Exactly which PG release are you > running? Can you provide a self-contained test case? Looking at current CVS code the RI check seems to be skipped on update of the _referred to_ table if the old and new values match, but not on update of the _referring_ table. -- Andrew, Supernews http://www.supernews.com - individual and corporate NNTP services
Andrew - Supernews <andrew+nonews@supernews.com> writes:
> Looking at current CVS code the RI check seems to be skipped on update of
> the _referred to_ table if the old and new values match, but not on update
> of the _referring_ table.
No, both sides are supposed to be tested, see lines 3350-3395 in
src/backend/commands/trigger.c. Or do you see something broken there?
It works for me in a quick test.
regards, tom lane
On 2007-04-15, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Andrew - Supernews <andrew+nonews@supernews.com> writes: >> Looking at current CVS code the RI check seems to be skipped on update of >> the _referred to_ table if the old and new values match, but not on update >> of the _referring_ table. > > No, both sides are supposed to be tested, see lines 3350-3395 in > src/backend/commands/trigger.c. Or do you see something broken there? > It works for me in a quick test. Hm, you're right; I was looking at the logic in the triggers themselves (in ri_triggers.c). So the next question is, what pg version is the original poster using? because 8.1.x doesn't report trigger execution times, and 8.2.x would use a single bitmap index scan with an = ANY condition, not a BitmapOr. -- Andrew, Supernews http://www.supernews.com - individual and corporate NNTP services
> So the next question is, what pg version is the original poster using? > because 8.1.x doesn't report trigger execution times, and 8.2.x would use > a single bitmap index scan with an = ANY condition, not a BitmapOr. I have tried 8.1.0 and 8.1.3 for this query.
cluster <skrald@amossen.dk> writes:
>> So the next question is, what pg version is the original poster using?
>> because 8.1.x doesn't report trigger execution times, and 8.2.x would use
>> a single bitmap index scan with an = ANY condition, not a BitmapOr.
> I have tried 8.1.0 and 8.1.3 for this query.
Checking the code, 8.1.x does report trigger times, so AndrewSN is
mistaken on that point.
However, it's also the case that 8.1 does have the suppress-the-trigger
logic for FKs, and it works fine for me in a simple test. I'm using
8.1 branch tip, but there are no relevant changes since 8.1.0 as far
as I can see in the CVS logs.
What is that non-FK trigger shown in your results?
> Trigger posts_tsvectorupdate: time=61.659 calls=5
Could it possibly be firing an extra update on the table?
regards, tom lane
Idly thumbing through the code, I came across something that might
possibly explain your results. Do the rows being updated contain
NULLs in the foreign-key columns? I see that ri_KeysEqual() treats
two null values as not equal, which might be overzealous respect for
SQL null semantics in this context.
regards, tom lane
> Do the rows being updated contain > NULLs in the foreign-key columns? No, all FK columns are non-NULL. It is very strange.
I have investigated a bit now and found the following:
When I perform the update the *first* time, the triggers are actually
not evaluated. But from the second update they are.
Also notice that the number of rows changes. Shouldn't that number of
rows always be 2 as question_id is primary key?
Example:
=> explain analyze update questions set cancelled_time = now() where
question_id in (10,11);
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------
Bitmap Heap Scan on questions (cost=4.01..12.04 rows=2 width=112)
(actual time=0.193..0.205 rows=2 loops=1)
Recheck Cond: ((question_id = 10) OR (question_id = 11))
-> BitmapOr (cost=4.01..4.01 rows=2 width=0) (actual
time=0.046..0.046 rows=0 loops=1)
-> Bitmap Index Scan on questions_pkey (cost=0.00..2.00
rows=1 width=0) (actual time=0.037..0.037 rows=1 loops=1)
Index Cond: (question_id = 10)
-> Bitmap Index Scan on questions_pkey (cost=0.00..2.00
rows=1 width=0) (actual time=0.005..0.005 rows=1 loops=1)
Index Cond: (question_id = 11)
Trigger for constraint questions_repost_of_fkey: time=0.023 calls=2
Total runtime: 0.734 ms
(9 rows)
=> explain analyze update questions set cancelled_time = now() where
question_id in (10,11);
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------
Bitmap Heap Scan on questions (cost=4.01..12.04 rows=2 width=112)
(actual time=0.085..0.097 rows=2 loops=1)
Recheck Cond: ((question_id = 10) OR (question_id = 11))
-> BitmapOr (cost=4.01..4.01 rows=2 width=0) (actual
time=0.047..0.047 rows=0 loops=1)
-> Bitmap Index Scan on questions_pkey (cost=0.00..2.00
rows=1 width=0) (actual time=0.036..0.036 rows=2 loops=1)
Index Cond: (question_id = 10)
-> Bitmap Index Scan on questions_pkey (cost=0.00..2.00
rows=1 width=0) (actual time=0.007..0.007 rows=2 loops=1)
Index Cond: (question_id = 11)
Trigger for constraint questions_repost_of_fkey: time=0.025 calls=2
Trigger for constraint questions_author_id_fkey: time=0.167 calls=2
Trigger for constraint questions_category_id_fkey: time=0.196 calls=2
Trigger for constraint questions_lock_user_id_fkey: time=0.116 calls=2
Total runtime: 1.023 ms
(12 rows)
On Sat, 21 Apr 2007, cluster wrote: > I have investigated a bit now and found the following: > > When I perform the update the *first* time, the triggers are actually > not evaluated. But from the second update they are. Are these in one transaction? If so, then right now after the first update, the remaining updates will trigger checks if the row modified was modified in this transaction. The comment in trigger.c lists the basic circumstance, although it mentions it in terms of insert and a deferred FK, I would guess that if there's ever a possibility of two modifications (including multiple updates or on an immediate constraint) before the constraint check occurred the same condition could happen.