Re: Queries intermittently slow - Mailing list pgsql-performance

On 1/6/16, 10:19 AM, "Tom Lane" <tgl@sss.pgh.pa.us> wrote:


>Scott Rankin <srankin@motus.com> writes:
>> I’m trying to track down why some queries on my database system are intermittently much slower than usual.  I have
somequeries that run, on average, 2-3ms, and they run at a rate of about 10-20 queries/second.  However, every 3-5
seconds,one of the queries will be 500-100ms.  This is making the average query time turn out to be closer to 20ms,
witha very large standard deviation.
 
>
>> This happens to a number of otherwise very fast queries, and I’m trying to trace the reason.  I’ve turned on lock
loggingand checkpoint logging, and this behavior happens whether or not a checkpoint is occurring.  There are no lock
waitshappening in the system either.
 
>
>I doubt you've proved that --- log_lock_waits will only report on waits
>longer than deadlock_timeout, which you don't appear to have changed from
>its default of 1 sec.  If you're trying to capture events that last a few
>hundred msec, you're going to need to reduce deadlock_timeout to maybe
>100ms.
>
>It would help to know more about what the queries are, too.  The cause
>might be something like GIN index pending-list cleanup but we can't tell
>on the basis of this much info.
>
>regards, tom lane

Hi Tom,

Thanks for the update. The query in question is a pretty simple one - it joins 3 tables, all of which are static - they
don’thave any writes being done against them.  They have very few rows, and the query plan for them indicates that they
areall sequential scans.  When doing an EXPLAIN ANALYZE, the delay is not consistently on one table, it can vary
betweenthe three tables involved in the query.
 

Here is the query plan for a fast run:

"Nested Loop  (cost=0.00..4.20 rows=1 width=185) (actual time=0.069..0.069 rows=0 loops=1)"
"  Join Filter: (be.branding_id = b.branding_id)"
"  Rows Removed by Join Filter: 1"
"  ->  Nested Loop  (cost=0.00..3.19 rows=1 width=189) (actual time=0.040..0.057 rows=1 loops=1)"
"        Join Filter: (s.setting_id = be.setting_id)"
"        Rows Removed by Join Filter: 41"
"        ->  Seq Scan on branding_extension be  (cost=0.00..1.00 rows=1 width=8) (actual time=0.008..0.008 rows=1
loops=1)"
"        ->  Seq Scan on setting s  (cost=0.00..2.04 rows=42 width=185) (actual time=0.004..0.018 rows=42 loops=1)"
"  ->  Seq Scan on branding b  (cost=0.00..1.01 rows=1 width=4) (actual time=0.006..0.008 rows=1 loops=1)"
"        Filter: ((name)::text = 'crs'::text)"
"        Rows Removed by Filter: 1"
"Total runtime: 0.150 ms"

And for a slow one:


"Nested Loop  (cost=0.00..4.20 rows=1 width=185) (actual time=383.862..383.862 rows=0 loops=1)"
"  Join Filter: (be.branding_id = b.branding_id)"
"  Rows Removed by Join Filter: 1"
"  ->  Nested Loop  (cost=0.00..3.19 rows=1 width=189) (actual time=383.815..383.849 rows=1 loops=1)"
"        Join Filter: (s.setting_id = be.setting_id)"
"        Rows Removed by Join Filter: 41"
"        ->  Seq Scan on branding_extension be  (cost=0.00..1.00 rows=1 width=8) (actual time=383.776..383.776 rows=1
loops=1)"
"        ->  Seq Scan on setting s  (cost=0.00..2.04 rows=42 width=185) (actual time=0.005..0.037 rows=42 loops=1)"
"  ->  Seq Scan on branding b  (cost=0.00..1.01 rows=1 width=4) (actual time=0.007..0.009 rows=1 loops=1)"
"        Filter: ((name)::text = 'crs'::text)"
"        Rows Removed by Filter: 1"
"Total runtime: 383.920 ms"

I will look at changing the deadlock_timeout, but that might have to wait for the weekend since this is a production
system.


Thanks,
Scott
This email message contains information that Motus, LLC considers confidential and/or proprietary, or may later
designateas confidential and proprietary. It is intended only for use of the individual or entity named above and
shouldnot be forwarded to any other persons or entities without the express consent of Motus, LLC, nor should it be
usedfor any purpose other than in the course of any potential or actual business relationship with Motus, LLC. If the
readerof this message is not the intended recipient, or the employee or agent responsible to deliver it to the intended
recipient,you are hereby notified that any dissemination, distribution, or copying of this communication is strictly
prohibited.If you have received this communication in error, please notify sender immediately and destroy the original
message.

Internal Revenue Service regulations require that certain types of written advice include a disclaimer. To the extent
thepreceding message contains advice relating to a Federal tax issue, unless expressly stated otherwise the advice is
notintended or written to be used, and it cannot be used by the recipient or any other taxpayer, for the purpose of
avoidingFederal tax penalties, and was not written to support the promotion or marketing of any transaction or matter
discussedherein.