Thread: Postgresql 10.3 , query never completes if LIMIT clause is specifiedand paralle processing is on

On 03/21/2018 05:09 PM, Alessandro Aste wrote:
> Hi there, we are using postgresql 10.3 and we're facing an issue with a
> query. The query (full query below)  completes only  when: 
> 
> 1 - LIMIT 10 is removed
> or
> 2 -  show max_parallel_workers_per_gather  is set to 0, so parallel
> processing is disabled.
> 
> With  max_parallel_workers_per_gather   set to the default value (8) I'm
> not even able to get the query plan.
> 
> Notes: 
> 
>   * We're experiencing the issue in any server of ours but I've
>     reproduced the issue in a fresh restored database with full
>     vacuum/reindex of the tables.
>   * We didn't touch any parameter concering the parallel processing,
>     we're running the defaults: 
> 
> 
> cmdstaging=# show max_parallel_workers_per_gather ;
>  max_parallel_workers_per_gather
> ---------------------------------
>  8
> (1 row)
> 
> cmdstaging=# show max_worker_processes ;
>  max_worker_processes
> ----------------------
>  8
> (1 row)
> 
> cmdstaging=# show max_parallel_workers;
>  max_parallel_workers
> ----------------------
>  8
> (1 row)
> 
> 
> 
> 
> The query completes only omitting the LIMIT clause or when I disable
> parallel processing: 
> 
>  id   | vendor_id | gaa |   pop_name    | pop_status | pop_location |
> pop_provider_id | pop_provider |     pop_street      | pop_city | pop
> _postal_code | pop_state | pop_country | pop_country_id
>
--------+-----------+-----+---------------+------------+--------------+-----------------+--------------+---------------------+----------+----
> -------------+-----------+-------------+----------------
>  684807 |     12346 |     | GTT/POP/LON1T | Active     | LON1T        | 
>          12288 | Telehouse UK | 14 Coriander Avenue | London   | E14
>  2AA         |           | GB          |            219
> (1 row)
> 
> Time: 4374.759 ms (00:04.375)
> cmdstaging=# show max_parallel_workers_per_gather ;
>  max_parallel_workers_per_gather
> ---------------------------------
>  0
> (1 row)
> 
> Time: 0.097 ms
> 
> 
> Otherwise it just keep running for forever. 
> 

When you say "running forever" is it actually using CPU, or does it get
stuck on something?

> 
> This is the full query: 
> 
> 
> SELECT * FROM (
> SELECT
> seg.circuit_id AS id,
> vendor_gtt_pop.vendor_id,
> CASE WHEN vendor_gtt_pop.push_to_gaa = 1 THEN 'Y' END as gaa,
> pop.gii_circuitid AS pop_name,
> cst.label AS pop_status,
> seg.a_company_name AS pop_location,
> seg.vendor_id AS pop_provider_id,
> seg.vendor_name AS pop_provider,
> cs.address1 AS pop_street,
> cs.city AS pop_city,
> cs.postal_code AS pop_postal_code,
> cs.state AS pop_state,
> csc.code AS pop_country,
> cs.country_id AS pop_country_id
> FROM (
> SELECT c.gii_circuitid, max(so.id <http://so.id>) AS service_order_id
> FROM service_order so
> join circuit c on c.product_id=so.product_id
> join master_service_order mso on mso.id <http://mso.id>=so.master_service_order_id
> WHERE NOT (so.ordertype_id = 2 AND so.status <> 999) AND
> NOT (so.ordertype_id = 3 AND so.status <> 999) AND
> c.status >= 20 AND
> c.status not in (160,999) AND
> mso.client_id=11615 AND
> c.service_description=28 AND
> c.status!=160
> GROUP BY c.gii_circuitid
> ) pop
> JOIN service_order so ON so.id <http://so.id> = pop.service_order_id
> left JOIN client_site cs on cs.id <http://cs.id>=so.a_site_id
> left JOIN country csc on csc.id <http://csc.id>=cs.country_id
> JOIN circuit c ON so.product_id=c.product_id
> JOIN circuit_status cst ON cst.id <http://cst.id>=c.status
> JOIN (
> SELECT c.id <http://c.id> AS circuit_id, sg.id <http://sg.id> AS segment_id, c.pop_support_vendor_id AS vendor_id,
> v.name <http://v.name> AS vendor_name, sg.a_company_name
> FROM segment sg
> JOIN circuit_layout cl ON cl.segment_id = sg.id <http://sg.id> AND cl.ordinal = 1
> JOIN circuit c ON c.id <http://c.id> = cl.circuit_id
> JOIN vendor v ON v.id <http://v.id> = c.pop_support_vendor_id
> ) seg ON seg.circuit_id = c.id <http://c.id>
> JOIN vendor_gtt_pop on vendor_gtt_pop.gtt_pop_id = seg.circuit_id
> ) foo where vendor_id = 12346 AND (1=1) ORDER BY pop_name ASC,id LIMIT 10
> 
> 
> 
> Execution plan with  max_parallel_workers_per_gather =0 , 
> max_parallel_workers_per_gather =8 and no LIMIT clause : 
> 
> 
We really need to see the execution plan that causes issues, i.e.
max_parallel_workers_per_gather=8 with LIMIT clause. Plain explain
(without analyze), at least.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 03/21/2018 08:44 PM, Alessandro Aste wrote:
> Thanks for your reply Tomas.  The query just got stuck for forever.  I
> observed no CPU spikes, it is currently running and I see 89 of the CPU
> idle. I'm using a relative powerfull machine (120 GB ram, 56 CPU).  
> 

That doesn't really answer the question, I'm afraid. I suppose "89 of
CPU" means that 89% idle in total, but 11% with 56 CPUs still means
about 6 cores 100% busy. But maybe you meant something else?

Is there something else running on the machine? If you look at "top" are
the processes (the one you're connected to and the parallel workers)
doing something on the CPU?

> 
> Plain analyze as requested. : 
> 

I don't see anything obviously broken with the query plan, and it's
difficult to compare with the other plans because they are quite different.

But there's one part of the plan interesting:

 Limit  (cost=253523.56..253523.57 rows=1 width=176)
   ->  Sort  (cost=253523.56..253523.57 rows=1 width=176)
         Sort Key: c_2.gii_circuitid, c_1.id
         ->  Nested Loop  (cost=33190.89..253523.55 rows=1 width=176)
               Join Filter: (c_1.id = c.id)
               ->  Nested Loop  (cost=31724.87..31736.29 rows=1 ...)
                     ...
               ->  Gather  (cost=1466.02..221787.23 rows=3 width=75)
                     Workers Planned: 5
                     ->  Hash Join  (cost=466.02..220786.93 rows=1 ...)
                         ...

That is, there's a Gather on the inner side of a Nested Loop. I wonder
if that might cause issues in case of under-estimate (in which case we'd
be restarting the Gather many times) ...


BTW one of the plans you sent earlier is incomplete, because it ends
like this:

    ->  Nested Loop  (cost=42469.41..42480.82 rows=1 width=85) (...)
        Join Filter: (c.status = cst.id)
    Time: 3016.688 ms (00:03.017)

That is, it's missing the part below the join.


That being said, I'm not sure what's the issue here. Can you prepare a
self-contained test case that we might use to reproduce the issue? For
example by dumping the relevant part of the tables?


regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 03/22/2018 11:33 AM, Alessandro Aste wrote:
> Tomas, thank you. This machine  is abare metal server running only a
> staging postgresql 10.3  instance. Nobody is using it beside me. 
> 
> I'm attaching 4 files.  
> 
> every_30_seconds_top_stats_during_query.txt    - this is a caputure of
> the top command every 30 seconds(more or less) for 10+ minutes while I'm
> running the query. Let me know if this helps to answere your question.
> EXPLAIN_WITH_LIMIT_AND_max_parallel_workers_per_gather_SET_TO_0.txt   - 
> query plan  with full query and  max_parallel_workers_per_gather  force
> to 0. Full output.
> EXPLAIN_WITH_LIMIT_AND_DEFAULT_PARALLEL_PROCESSING_SETTINGS.txt  - 
>  query plan with full query and  default parellel processing settings. 
> Full output.
> EXPLAIN_WITHOUT_LIMIT_AND_DEFAULT_PARALLEL_PROCESSING_SETTINGS.tx  -
> query plan of the query omitting the LIMIT clause and default parellel
> processing settings. Full output.
> 

OK. Looking at the top output, I see this:

       PID USER       VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
    104880 postgres  30.8g 1.9g 1.9g R 92.0  1.5  15:15.60 postmaster
    111732 postgres  30.8g 476m 473m R 88.2  0.4   0:00.47 postmaster
    111730 postgres  30.8g 473m 470m R 86.4  0.4   0:00.46 postmaster
    111731 postgres  30.8g 476m 473m R 86.4  0.4   0:00.46 postmaster
    111733 postgres  30.8g 476m 473m R 86.4  0.4   0:00.46 postmaster
    111734 postgres  30.8g 476m 473m R 86.4  0.4   0:00.46 postmaster
    111728 root      15824 1912  828 R  3.8  0.0   0:00.04 top

That means it certainly is not stuck, it's simply doing a lot of work on
CPU. The question is why and what it's doing ...

Can you collect some CPU profiles using perf? There's a howto here:

    https://wiki.postgresql.org/wiki/Profiling_with_perf

But in short - install perf, install debuginfo packages for postgres,
and then do

    perf record -a -g -s sleep 60

while running the query. Once the profile data is collected, do

    perf report > report.txt

and share the report.txt with us (well, if it's very large you may need
to only cut the first 1000 lines or so).

That should tell us in which functions most of the time is spent. That
will give us some hints, hopefully.

> 
> For what concerns the  self-contained test case - I'll do my best to
> prepare it.
> 

Yeah, that would be helpful.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 03/22/2018 11:29 PM, Alessandro Aste wrote:
> Thanks Tomas. We're currently building postgres from source. In order to
> enable symbols, you want me to re-configure postres with  --enable-debug
> then run perf?
> 

Yes.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hi,

the perf profiles look really weird - clearly, there's a lot of lock
contention, because the top item is this

    13.49%    13.40%  postmaster   postgres  [.]   LWLockAcquire
                 |

                 ---LWLockAcquire



That's a sign of lock contention - not sure which one, though. And then
there's heap_hot_search_buffer

    12.65%     7.92%  postmaster   postgres [.] heap_hot_search_buffer
                 |

                 ---heap_hot_search_buffer


So either there's a table with many HOT-updated rows (repeatedly), or we
search the HOT chains very frequently for some reason. Considering it
only affects the non-LIMIT case, I'd guess the latter.

There also seems to be quite a few page faults, for some reason.

Trying to reproduce this without the actual data is rather futile. We
need some sort of reproducer (sample data to test the query on).

regards

On 03/28/2018 10:30 AM, Alessandro Aste wrote:
> Hello,  any news ?
> 
> Thank you,
> 
> Alessandro.
> 
> On Fri, Mar 23, 2018 at 8:22 PM, Alessandro Aste
> <alessandro.aste@gmail.com <mailto:alessandro.aste@gmail.com>> wrote:
> 
>     PS , in the meanwhile I discovered a 2nd workaround(beside disabling
>     parallel processing) . I added offset  0 to the subquery , and,
>     according to the documentation, “OFFSET 0 is the same as omitting
>     the OFFSET clause”
>     - https://www.postgresql.org/docs/current/static/queries-limit.html
>     <https://www.postgresql.org/docs/current/static/queries-limit.html>
> 
>     cmd3dev=# show max_parallel_workers_per_gather ;
> 
>     *max_parallel_workers_per_gather*
> 
>     *---------------------------------*
> 
>     *8*
> 
>     (1 row)
> 
>      
> 
>     cmd3dev=# \timing
> 
>     Timing is on.
> 
>     cmd3dev=#  SELECT * FROM (SELECT seg.circuit_id AS id,
>     vendor_gtt_pop.vendor_id, CASE WHEN vendor_gtt_pop.push_to_gaa = 1
>     THEN 'Y' END as gaa, pop.gii_circuitid AS pop_name, cst.label AS
>     pop_status, seg.a_company_name AS pop_location, seg.vendor_id AS
>     pop_provider_id, seg.vendor_name AS pop_provider, cs.address1 AS
>     pop_street, cs.city AS pop_city, cs.postal_code AS pop_postal_code,
>     cs.state AS pop_state, csc.code AS pop_country, cs.country_id AS
>     pop_country_id FROM ( SELECT c.gii_circuitid, max(so.id
>     <http://so.id>) AS service_order_id FROM service_order so join
>     circuit c on c.product_id=so.product_id join master_service_order
>     mso on mso.id <http://mso.id>=so.master_service_order_id WHERE NOT
>     (so.ordertype_id = 2 AND so.status <> 999) AND NOT (so.ordertype_id
>     = 3 AND so.status <> 999) AND c.status >= 20 AND c.status not in
>     (160,999) AND mso.client_id=11615 AND c.service_description=28 AND
>     c.status!=160 GROUP BY c.gii_circuitid ) pop JOIN service_order so
>     ON so.id <http://so.id> = pop.service_order_id left JOIN client_site
>     cs on cs.id <http://cs.id>=so.a_site_id left JOIN country csc on
>     csc.id <http://csc.id>=cs.country_id JOIN circuit c ON
>     so.product_id=c.product_id JOIN circuit_status cst ON cst.id
>     <http://cst.id>=c.status JOIN ( SELECT c.id <http://c.id> AS
>     circuit_id, sg.id <http://sg.id> AS segment_id,
>     c.pop_support_vendor_id AS vendor_id, v.name <http://v.name> AS
>     vendor_name, sg.a_company_name FROM segment sg JOIN circuit_layout
>     cl ON cl.segment_id = sg.id <http://sg.id> AND cl.ordinal = 1 JOIN
>     circuit c ON c.id <http://c.id> = cl.circuit_id JOIN vendor v ON
>     v.id <http://v.id> = c.pop_support_vendor_id ) seg ON seg.circuit_id
>     = c.id <http://c.id> JOIN vendor_gtt_pop on
>     vendor_gtt_pop.gtt_pop_id = seg.circuit_id offset 0) foo where
>     vendor_id = 12346 AND (1=1) ORDER BY pop_name ASC,id desc LIMIT 10;
> 
>        id   | vendor_id | gaa |   pop_name    | pop_status |
>     pop_location | pop_provider_id | pop_provider |     pop_street     
>     | pop_city | pop
> 
>     _postal_code | pop_state | pop_country | pop_country_id
> 
>
--------+-----------+-----+---------------+------------+--------------+-----------------+--------------+---------------------+----------+----
> 
>     -------------+-----------+-------------+----------------
> 
>     684807 |     12346 | Y   | GTT/POP/LON1T | Active     | LON1T       
>     |           12288 | Telehouse UK | 14 Coriander Avenue | London   | E14
> 
>     2AA         |           | GB          |            219
> 
>     (1 row)
> 
>      
> 
>     *Time: 2245.073 ms (00:02.245)*
> 
> 
> 
> 
>     On Fri, Mar 23, 2018 at 9:31 AM, Alessandro Aste
>     <alessandro.aste@gmail.com <mailto:alessandro.aste@gmail.com>> wrote:
> 
>         Tomas, I'm attaching a 4MB file with the perf report. Let me
>         know if it gets blocked, I'll shrink it to the first 1000 lines. 
> 
>         Thank you,
> 
>         Alessandro.
> 
>         On Thu, Mar 22, 2018 at 11:42 PM, Tomas Vondra
>         <tomas.vondra@2ndquadrant.com
>         <mailto:tomas.vondra@2ndquadrant.com>> wrote:
> 
>             On 03/22/2018 11:29 PM, Alessandro Aste wrote:
>             > Thanks Tomas. We're currently building postgres from source. In order to
>             > enable symbols, you want me to re-configure postres with  --enable-debug
>             > then run perf?
>             >
> 
>             Yes.
> 
>             regards
> 
>             --
>             Tomas Vondra                  http://www.2ndQuadrant.com
>             PostgreSQL Development, 24x7 Support, Remote DBA, Training &
>             Services
> 
> 
> 
> 

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services