Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1jO00u-0006qe-Un for pgsql-admin@arkaria.postgresql.org; Mon, 13 Apr 2020 14:24:41 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1jO00t-0004c0-Qe for pgsql-admin@arkaria.postgresql.org; Mon, 13 Apr 2020 14:24:39 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1jO00t-0004bt-GB for pgsql-admin@lists.postgresql.org; Mon, 13 Apr 2020 14:24:39 +0000 Received: from mail-ot1-x343.google.com ([2607:f8b0:4864:20::343]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1jO00r-0006IJ-Kk for pgsql-admin@lists.postgresql.org; Mon, 13 Apr 2020 14:24:39 +0000 Received: by mail-ot1-x343.google.com with SMTP id 103so9243409otv.0 for ; Mon, 13 Apr 2020 07:24:37 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=subject:to:references:from:message-id:date:user-agent:mime-version :in-reply-to:content-language; bh=ZpVH0TDqAh1z1VL4aK8ty5muJwa2l6fQ5p/7c+MqdnA=; b=qFDVYKY2rcvBv1iqw+DXlpIVV8IcAOhT2Cl8wF8xX2nVFG8TJ0BEYK/3fFGCtJzGiN Tp7UPwyOwvA70q79t1nJ9S2IHiKeEtK2OqZ2N1zFVqt4Xtr1qcX3k5Hv2AJAy/y5nyR6 Wt+SsIMJHfZDz0WiEh02c6maWg3Sv4WKnBMZgWhVzUmE4HpKnvTlNtAFPqzhBuxqwWeX 6uUlcjhTLVeMvY4ZuGoUBrCrPx7v4zTnnUUK8jn8S62i37uSdEdtTMKKU33lEe/FIwjG Cj2VpQ2f69l/VuRu1lb8RqUmObJrD3TCuWebR5dmIC5It1VDmyk+EgV5Ourp+AFUa6LQ FNlw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:subject:to:references:from:message-id:date :user-agent:mime-version:in-reply-to:content-language; bh=ZpVH0TDqAh1z1VL4aK8ty5muJwa2l6fQ5p/7c+MqdnA=; b=FdJzwTeJGzJJZEONNfYnGA5DOl2kcvkUdCpWKFkTj8WOUTTYmEj4O/6ANp3AUrx99q w05wrZxqDBPLmjrllZDlB3JL268OKrZWi4S/xWRfamLmjQQQBQ72VvpsPzGl8ykx1DMl 9rwjKrnNkq04i2YTVpCKtHFqKGT3YgQdc/2qTgASxKqzHEsliLdzLlQBaBk6FlZwCg6h mU11MVSRQtQuXTpptfobWFf6GobQeiV3AyOVN8qPWjiNCkTANrYz/oBV20jX9moCokuQ 1bPKHMbavHkma3HEQjD2kaUX796SpRk1SKnMqx9Db9AZvofYgGt1MyUDOrHM0xNle5Bj 10wg== X-Gm-Message-State: AGi0PubGiky5RtiN6orWvhA5I6J1vD/fbsKoYeYO7+oWWrWZxpjYLqUC vxeOxLrybsWvQfx3f798EthOtmyw X-Google-Smtp-Source: APiQypI/VqlqooiguNY7Gf1gcIpHJboQI/kcB01x60Nc9oD0v8qRxhX47nNHA7XLp5gfLwXtqAwkbA== X-Received: by 2002:a05:6830:1:: with SMTP id c1mr14299562otp.200.1586787875625; Mon, 13 Apr 2020 07:24:35 -0700 (PDT) Received: from [192.168.1.10] (ip70-186-126-197.no.no.cox.net. [70.186.126.197]) by smtp.googlemail.com with ESMTPSA id n23sm5315279ooe.44.2020.04.13.07.24.34 for (version=TLS1_3 cipher=TLS_AES_128_GCM_SHA256 bits=128/128); Mon, 13 Apr 2020 07:24:35 -0700 (PDT) Subject: Re: Help needed on optimizing query To: pgsql-admin@lists.postgresql.org References: From: Ron Message-ID: Date: Mon, 13 Apr 2020 09:24:34 -0500 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Thunderbird/68.4.1 MIME-Version: 1.0 In-Reply-To: Content-Type: multipart/alternative; boundary="------------F0009029C28F239EA74652AF" Content-Language: en-US List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk This is a multi-part message in MIME format. --------------F0009029C28F239EA74652AF Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 8bit Does the Azure VM have the same IOPS rating as the Expedient DC? (That would immediately explain the slowdown, as would the fact that Azure has been heavily strained by new services spun up during the COVID-19 crisis.) On 4/13/20 9:07 AM, Mark Steben wrote: > Good morning, > We run postgres 9.4.21.  Last week we moved our database from an expedient > datacenter to an azure vm. > I submit this query for your consideration: > >  SELECT DISTINCT ON (permissions.id ) >         permissions.section, >         permissions.subject, >         permissions.action >        FROM >          permissions >          LEFT JOIN permissions_roles ON permissions.id > = permissions_roles.permission_id >          LEFT JOIN roles_users ON permissions_roles.role_id = > roles_users.role_id AND roles_users.user_id = 13949 >          LEFT JOIN accounts_users_permissions ON permissions.id > = accounts_users_permissions.permission_id >          LEFT JOIN accounts_users ON > accounts_users_permissions.accounts_user_id = accounts_users.id > >              AND accounts_users.user_id = 13949 >              AND accounts_users.account_id = 0 >          LEFT JOIN access_keys_permissions ON permissions.id > = access_keys_permissions.permission_id >          LEFT JOIN access_keys_users ON > access_keys_permissions.access_key_id = access_keys_users.access_key_id > AND access_keys_users.user_id = 13949 >        WHERE >         accounts_users.deleted_at IS NULL AND >          13949 IS NOT NULL AND >          ( > roles_users.id IS NOT NULL OR > access_keys_users.id IS NOT NULL OR > accounts_users.id IS NOT NULL >           ) > > Here is the explain analyze: > >  Unique  (cost=1.84..3153.19 rows=322 width=29) (actual > time=1.289..996.395 rows=76 loops=1) >    ->  Merge Left Join  (cost=1.84..2856.84 rows=118541 width=29) (actual > time=1.288..985.494 rows=183907 loops=1) >          Merge Cond: (permissions.id = > permissions_roles.permission_id) >          Filter: ((roles_users.id IS NOT NULL) OR > (access_keys_users.id IS NOT NULL) OR > (accounts_users.id IS NOT NULL)) >          Rows Removed by Filter: 5613165 >          -> *Merge Left Join  (cost=1.27..418.98 rows=7353 width=37) > (actual time=0.044..45.830 rows=185714 loops=1)* >                Merge Cond: (permissions.id = > access_keys_permissions.permission_id) >                ->  Nested Loop Left Join  (cost=0.72..214.69 rows=1422 > width=33) (actual time=0.020..2.614 rows=3223 loops=1) >                      Join Filter: > (accounts_users_permissions.accounts_user_id = accounts_users.id > ) >                      Filter: (accounts_users.deleted_at IS NULL) >                      ->  Merge Left Join  (cost=0.43..162.80 rows=3172 > width=33) (actual time=0.013..1.844 rows=3223 loops=1) >                            Merge Cond: (permissions.id > = accounts_users_permissions.permission_id) >                            ->  Index Scan using permissions_pkey on > permissions  (cost=0.15..14.01 rows=322 width=29) (actual > time=0.007..0.099 rows=322 loops=1) >                            ->  Index Scan using > accounts_users_permissions_permission_id on accounts_users_permissions >  (cost=0.28..108.33 rows=3172 width=8) (actual time=0.004..1.140 rows=3172 > loops=1) >                      ->  Materialize  (cost=0.29..4.31 rows=1 width=12) > (actual time=0.000..0.000 rows=0 loops=3223) >                            ->  Index Scan using > index_stores_users_on_store_id_and_user_id on accounts_users >  (cost=0.29..4.31 rows=1 width=12) (actual time=0.003..0.003 rows=0 loops=1) >                                  Index Cond: ((account_id = 0) AND > (user_id = 13949)) >                -> *Materialize  (cost=0.55..94.61 rows=1665 width=8) > (actual time=0.022..9.459 rows=182891 loops=1)* >                      ->  Nested Loop Left Join  (cost=0.55..90.44 > rows=1665 width=8) (actual time=0.020..0.818 rows=1665 loops=1) >                            Join Filter: > (access_keys_permissions.access_key_id = access_keys_users.access_key_id) >                            ->  Index Scan using > index_access_keys_permissions_on_permission_id on access_keys_permissions >  (cost=0.28..61.18 rows=1665 width=8) (actual time=0.011..0.455 rows=1665 > loops=1) >                            ->  Materialize  (cost=0.28..4.29 rows=1 > width=8) (actual time=0.000..0.000 rows=0 loops=1665) >                                  ->  Index Scan using > index_access_keys_users_on_user_id on access_keys_users  (cost=0.28..4.29 > rows=1 width=8) (actual time=0.006..0.006 rows=0 loops=1) >                                        Index Cond: (user_id = 13949) >          -> *Materialize  (cost=0.57..654.71 rows=5190 width=8) (actual > time=0.738..269.930 rows=5797068 loops=1)* >                ->  Nested Loop Left Join  (cost=0.57..641.73 rows=5190 > width=8) (actual time=0.736..6.183 rows=5190 loops=1) >                      Join Filter: (permissions_roles.role_id = > roles_users.role_id) >                      Rows Removed by Join Filter: 20636 >                      ->  Index Scan using permissions_roles_permission_id > on permissions_roles  (cost=0.28..150.89 rows=5190 width=8) (actual > time=0.005..1.669 rows=5190 loops=1) >                      ->  Materialize  (cost=0.29..335.15 rows=2 width=8) > (actual time=0.000..0.000 rows=4 loops=5190) >                            ->  Index Scan using > index_roles_users_on_role_id_and_user_id on roles_users >  (cost=0.29..335.14 rows=2 width=8) (actual time=0.179..0.724 rows=4 loops=1) >                                  Index Cond: (user_id = 13949) >  Planning time: 1.782 ms >  Execution time: 996.545 ms > (34 rows) > > (I hope the boldened lines show up as boldened in your email reception to > make this easier.) > > This query runs thousands of times a day, specifically many hundreds of > times between 3 am and 6 am causing hi stress load and consequently > dropped connections. > > My specific question to you is: I notice in the boldened lines the > discrepancy between the 'estimated row count' and 'actual row count' Most > blatant is one Materialize where estimated rowcount as calculated in the > explain is 5190 and actual rowcount is 5,797.068.  How do I fix this so > that the estimated is closer to the actual.  I run a vacuum and an analyze > on all tables nightly. > > I have attached a file containing table/index descriptions and our > postgresql file for your reference. > Thank you for your help!  This is quite urgent. > (One note - this morning to try to fix this we rebooted and increased the > shared_buffers from 8 GB to 14 GB. >  Our hope is that we find the real solution for this optimization and >  revert back to 8 GB.) > > > > > > -- > *Mark Steben* >  Database Administrator > @utoRevenue | Autobase > > CRM division of Dominion Dealer Solutions > 95D Ashley Ave. > West Springfield, MA 01089 > t: 413.327-3045 > f: 413.383-9567 > > www.fb.com/DominionDealerSolutions > www.twitter.com/DominionDealer > www.drivedominion.com > > > > > -- Angular momentum makes the world go 'round. --------------F0009029C28F239EA74652AF Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: 8bit Does the Azure VM have the same IOPS rating as the Expedient DC? (That would immediately explain the slowdown, as would the fact that Azure has been heavily strained by new services spun up during the COVID-19 crisis.)

On 4/13/20 9:07 AM, Mark Steben wrote:
Good morning,
We run postgres 9.4.21.  Last week we moved our database from an expedient datacenter to an azure vm.  
I submit this query for your consideration:

 SELECT DISTINCT ON (permissions.id)
        permissions.section,
        permissions.subject,
        permissions.action
       FROM
         permissions
         LEFT JOIN permissions_roles ON permissions.id = permissions_roles.permission_id
         LEFT JOIN roles_users ON permissions_roles.role_id = roles_users.role_id AND roles_users.user_id = 13949
         LEFT JOIN accounts_users_permissions ON permissions.id = accounts_users_permissions.permission_id
         LEFT JOIN accounts_users ON accounts_users_permissions.accounts_user_id = accounts_users.id
             AND accounts_users.user_id = 13949
             AND accounts_users.account_id = 0
         LEFT JOIN access_keys_permissions ON permissions.id = access_keys_permissions.permission_id
         LEFT JOIN access_keys_users ON access_keys_permissions.access_key_id = access_keys_users.access_key_id AND access_keys_users.user_id = 13949
       WHERE
        accounts_users.deleted_at IS NULL AND
         13949 IS NOT NULL AND
         (
           roles_users.id IS NOT NULL OR
           access_keys_users.id IS NOT NULL OR
           accounts_users.id IS NOT NULL
          )

Here is the explain analyze:

 Unique  (cost=1.84..3153.19 rows=322 width=29) (actual time=1.289..996.395 rows=76 loops=1)
   ->  Merge Left Join  (cost=1.84..2856.84 rows=118541 width=29) (actual time=1.288..985.494 rows=183907 loops=1)
         Merge Cond: (permissions.id = permissions_roles.permission_id)
         Filter: ((roles_users.id IS NOT NULL) OR (access_keys_users.id IS NOT NULL) OR (accounts_users.id IS NOT NULL))
         Rows Removed by Filter: 5613165
         ->  Merge Left Join  (cost=1.27..418.98 rows=7353 width=37) (actual time=0.044..45.830 rows=185714 loops=1)
               Merge Cond: (permissions.id = access_keys_permissions.permission_id)
               ->  Nested Loop Left Join  (cost=0.72..214.69 rows=1422 width=33) (actual time=0.020..2.614 rows=3223 loops=1)
                     Join Filter: (accounts_users_permissions.accounts_user_id = accounts_users.id)
                     Filter: (accounts_users.deleted_at IS NULL)
                     ->  Merge Left Join  (cost=0.43..162.80 rows=3172 width=33) (actual time=0.013..1.844 rows=3223 loops=1)
                           Merge Cond: (permissions.id = accounts_users_permissions.permission_id)
                           ->  Index Scan using permissions_pkey on permissions  (cost=0.15..14.01 rows=322 width=29) (actual time=0.007..0.099 rows=322 loops=1)
                           ->  Index Scan using accounts_users_permissions_permission_id on accounts_users_permissions  (cost=0.28..108.33 rows=3172 width=8) (actual time=0.004..1.140 rows=3172 loops=1)
                     ->  Materialize  (cost=0.29..4.31 rows=1 width=12) (actual time=0.000..0.000 rows=0 loops=3223)
                           ->  Index Scan using index_stores_users_on_store_id_and_user_id on accounts_users  (cost=0.29..4.31 rows=1 width=12) (actual time=0.003..0.003 rows=0 loops=1)
                                 Index Cond: ((account_id = 0) AND (user_id = 13949))
               ->  Materialize  (cost=0.55..94.61 rows=1665 width=8) (actual time=0.022..9.459 rows=182891 loops=1)
                     ->  Nested Loop Left Join  (cost=0.55..90.44 rows=1665 width=8) (actual time=0.020..0.818 rows=1665 loops=1)
                           Join Filter: (access_keys_permissions.access_key_id = access_keys_users.access_key_id)
                           ->  Index Scan using index_access_keys_permissions_on_permission_id on access_keys_permissions  (cost=0.28..61.18 rows=1665 width=8) (actual time=0.011..0.455 rows=1665 loops=1)
                           ->  Materialize  (cost=0.28..4.29 rows=1 width=8) (actual time=0.000..0.000 rows=0 loops=1665)
                                 ->  Index Scan using index_access_keys_users_on_user_id on access_keys_users  (cost=0.28..4.29 rows=1 width=8) (actual time=0.006..0.006 rows=0 loops=1)
                                       Index Cond: (user_id = 13949)
         ->  Materialize  (cost=0.57..654.71 rows=5190 width=8) (actual time=0.738..269.930 rows=5797068 loops=1)
               ->  Nested Loop Left Join  (cost=0.57..641.73 rows=5190 width=8) (actual time=0.736..6.183 rows=5190 loops=1)
                     Join Filter: (permissions_roles.role_id = roles_users.role_id)
                     Rows Removed by Join Filter: 20636
                     ->  Index Scan using permissions_roles_permission_id on permissions_roles  (cost=0.28..150.89 rows=5190 width=8) (actual time=0.005..1.669 rows=5190 loops=1)
                     ->  Materialize  (cost=0.29..335.15 rows=2 width=8) (actual time=0.000..0.000 rows=4 loops=5190)
                           ->  Index Scan using index_roles_users_on_role_id_and_user_id on roles_users  (cost=0.29..335.14 rows=2 width=8) (actual time=0.179..0.724 rows=4 loops=1)
                                 Index Cond: (user_id = 13949)
 Planning time: 1.782 ms
 Execution time: 996.545 ms
(34 rows)

(I hope the boldened lines show up as boldened in your email reception to make this easier.)

This query runs thousands of times a day, specifically many hundreds of times between 3 am and 6 am causing hi stress load and consequently dropped connections.

My specific question to you is: I notice in the boldened lines the discrepancy between the 'estimated row count' and 'actual row count' Most blatant is one Materialize where estimated rowcount as calculated in the explain is 5190 and actual rowcount is 5,797.068.  How do I fix this so that the estimated is closer to the actual.  I run a vacuum and an analyze on all tables nightly.

I have attached a file containing table/index descriptions and our postgresql file for your reference.
Thank you for your help!  This is quite urgent.
(One note - this morning to try to fix this we rebooted and increased the shared_buffers from 8 GB to 14 GB.
 Our hope is that we find the real solution for this optimization and
 revert back to 8 GB.)





--
Mark Steben
 Database Administrator
@utoRevenue | Autobase 
  CRM division of Dominion Dealer Solutions 
95D Ashley Ave.
West Springfield, MA 01089
t: 413.327-3045
f: 413.383-9567

www.fb.com/DominionDealerSolutions
www.twitter.com/DominionDealer
 www.drivedominion.com






--
Angular momentum makes the world go 'round.
--------------F0009029C28F239EA74652AF--