Re: Slow nested loop execution on larger server

The naked query runs a very long time, and stuck in a slow semop() syscalls from my strace output, the explain plans are probably more to do with our statistic problems that we are clubbing through slowly but surely. The main concern was way the slow semop() calls consistently, a restart of the server seemed to have stopped the issue for now.

- John

-----Original Message-----
From: pgsql-performance-owner(at)postgresql(dot)org [mailto:pgsql-performance-owner(at)postgresql(dot)org] On Behalf Of Scott Marlowe
Sent: Friday, December 16, 2011 3:16 PM
To: Greg Smith
Cc: pgsql-performance(at)postgresql(dot)org
Subject: Re: [PERFORM] Slow nested loop execution on larger server

On Fri, Dec 16, 2011 at 11:27 AM, Greg Smith <greg(at)2ndquadrant(dot)com> wrote:
> Forwarding this on from someone who may pop up on the list too.  This
> is a new server that's running a query slowly.  The rate at which new
> semops happen may be related.  OS is standard RHEL 5.5, kernel 2.6.18-194.32.1.el5.
>  One possibly interesting part is that this is leading edge hardware:  
> four 8-core processes with HyperThreading, for 64 threads total:
>
> processor       : 63
> model name      : Intel(R) Xeon(R) CPU           X7550  @ 2.00GHz
> physical id     : 3 siblings        : 16 cpu cores       : 8
>
> My only vague memory of issues around systems like this that comes to
> mind here is Scott Marlowe talking about some kernel tweaks he had to
> do on his
> 48 core AMD boxes to get them work right.  That seems like a sketchy
> association, and I don't seem to have the details handy.
>
> I do have the full query text and associated plans, but it's mostly noise.
>  Here's the fun part:
>
> ->  Nested Loop  (cost=581.52..3930.81 rows=2 width=51) (actual
> time=25.681..17562.198 rows=21574 loops=1)
>      ->  Merge Join  (cost=581.52..783.07 rows=2 width=37) (actual
> time=25.650..98.268 rows=21574 loops=1)
>            Merge Cond: (rim.instrumentid = ri.instrumentid)
>            ->  Index Scan using reportinstruments_part_125_pkey on
> reportinstruments_part_125 rim  (cost=0.00..199.83 rows=110 width=8)
> (actual
> time=0.033..27.180 rows=20555 loops=1)
>                  Index Cond: (reportid = 105668)
>            ->  Sort  (cost=581.52..582.31 rows=316 width=33) (actual
> time=25.608..34.931 rows=21574 loops=1)
>                  Sort Key: ri.instrumentid
>                  Sort Method: quicksort  Memory: 2454kB
>                  ->  Index Scan using riskbreakdown_part_51_pkey on
> riskbreakdown_part_51 ri  (cost=0.00..568.40 rows=316 width=33)
> (actual
> time=0.019..11.599 rows=21574 loops=1)
>                        Index Cond: (reportid = 105668)
>      ->  Index Scan using energymarketlist_pkey on energymarketlist ip
>  (cost=0.00..1573.86 rows=1 width=18) (actual time=0.408..0.808 rows=1
> loops=21574)
>            Index Cond: ((reportid = 105668) AND (instrumentid =
> ri.instrumentid))
> ...
> Total runtime: 21250.377 ms
>
> The stats are terrible and the estimates off by many orders of magnitude.
>  But that's not the point.  It expected 2 rows and 21574 came out; fine.
>  Why is it taking this server 17 seconds to process 21K rows of tiny
> width through a Nested Loop?  Is it bouncing to a new CPU every time
> the thing processes a row or something?  I'm finding it hard to
> imagine how this could be a PostgreSQL problem; seems more like a
> kernel bug aggrevated on this system.  I wonder if we could produce a
> standalone test case with a similar plan from what the bad query looks
> like, and ask the person with this strange system to try it.  See if
> it's possible to make it misbehave in the same way with something simpler others can try, too.

What's the difference in speed of running the query naked and with explain analyze? It's not uncommon to run into a situation where the instrumentation of explain analyze costs significantly more than anything in the query, and for some loops this gets especially bad.
If the naked query runs in say 1 second, and the explain analyze runs in 17 seconds, then the explain analyze time keeping is costing you 16/17ths of the time to do the accounting. If that's the case then the real query is about 16 times faster than the explain analyzed one, and the rows are being processed at about 25k/second.

--
Sent via pgsql-performance mailing list (pgsql-performance(at)postgresql(dot)org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
This email is confidential and subject to important disclaimers and
conditions including on offers for the purchase or sale of
securities, accuracy and completeness of information, viruses,
confidentiality, legal privilege, and legal entity disclaimers,
available at http://www.jpmorgan.com/pages/disclosures/email.