Re: Queries intermittently slow

On 1/6/16, 10:19 AM, "Tom Lane" <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

>Scott Rankin <srankin(at)motus(dot)com> writes:
>> I’m trying to track down why some queries on my database system are intermittently much slower than usual. I have some queries 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, with a 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 logging and checkpoint logging, and this behavior happens whether or not a checkpoint is occurring. There are no lock waits happening 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’t have any writes being done against them. They have very few rows, and the query plan for them indicates that they are all sequential scans. When doing an EXPLAIN ANALYZE, the delay is not consistently on one table, it can vary between the 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 designate as confidential and proprietary. It is intended only for use of the individual or entity named above and should not be forwarded to any other persons or entities without the express consent of Motus, LLC, nor should it be used for any purpose other than in the course of any potential or actual business relationship with Motus, LLC. If the reader of 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 the preceding message contains advice relating to a Federal tax issue, unless expressly stated otherwise the advice is not intended or written to be used, and it cannot be used by the recipient or any other taxpayer, for the purpose of avoiding Federal tax penalties, and was not written to support the promotion or marketing of any transaction or matter discussed herein.