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 1oBHaT-0008IF-JR for pgsql-performance@arkaria.postgresql.org; Tue, 12 Jul 2022 15:14:10 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1oBHaQ-0004nS-OJ for pgsql-performance@arkaria.postgresql.org; Tue, 12 Jul 2022 15:14:06 +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 1oBHaO-0004je-OF for pgsql-performance@lists.postgresql.org; Tue, 12 Jul 2022 15:14:06 +0000 Received: from mail-pl1-f173.google.com ([209.85.214.173]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1oBHaF-0002Dz-Cf for pgsql-performance@lists.postgresql.org; Tue, 12 Jul 2022 15:13:59 +0000 Received: by mail-pl1-f173.google.com with SMTP id j12so7489701plj.8 for ; Tue, 12 Jul 2022 08:13:54 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:from:message-id:mime-version:subject:date :in-reply-to:cc:to:references; bh=1iDmrc4xSBPGvFnNX+IRn8jgzICvfsIdYnIPvry5GEY=; b=2GKS3uFF/7erXLJltdXMoS8PesnLRJG2oeAhFvX8J2toSWDnQLe1xnJciP3CSby9Op tFm9ScL9OEhzl/xvlmJlb50sRUQHdK6WA2jhAp9Iym1j5MEHu7IvZMw/+YZ3OvjBdV3b NIvYUbuiqii8qRdzMA4EU6EL895K/+cVp2gc7mWYGJBYxWnS6198CaEQwkghjvNqZaQr C/AiorlK7BpkBLaUJDMCl8q0TzyoZuMCZXVnD6xVtp1dHlRXe4BMvK4DXsPaQo0TPa2o Mh+Thtv+D5fXJBbVnjnFiYTXAeoKtm1SVgrLnhhpHEHX4p0ZzH/noFFlsx8fiPBBndYG lMzQ== X-Gm-Message-State: AJIora9hSTwM8wWksoazADTJGTTPTnXV9cVCxiYk/z/4zw4t0Yzm1ttv t4SNIt3PF0snLduEcvwOLGr25iLo2OGDTQ== X-Google-Smtp-Source: AGRyM1viWET5Rv6SCnoDc850bACVhxOQ9lODR9RW2yfs1/VIOMcgNvlsTYEqlcaQ+8XWIq/cu+pHxA== X-Received: by 2002:a17:902:ef85:b0:16c:56e4:8631 with SMTP id iz5-20020a170902ef8500b0016c56e48631mr5943113plb.174.1657638832059; Tue, 12 Jul 2022 08:13:52 -0700 (PDT) Received: from smtpclient.apple ([203.94.33.135]) by smtp.gmail.com with ESMTPSA id o65-20020a625a44000000b0052ac99c2c1csm4891994pfb.83.2022.07.12.08.13.49 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Tue, 12 Jul 2022 08:13:50 -0700 (PDT) From: Nathan Ward Message-Id: <84101021-8B67-45AD-83F2-A3C8F0AA4BEE@daork.net> Content-Type: multipart/alternative; boundary="Apple-Mail=_31158C78-5891-415F-96B2-685A612564AB" Mime-Version: 1.0 (Mac OS X Mail 16.0 \(3696.100.31\)) Subject: Re: Occasional performance issue after changing table partitions Date: Wed, 13 Jul 2022 03:13:46 +1200 In-Reply-To: Cc: pgsql-performance@lists.postgresql.org To: Justin Pryzby References: <24A451C3-1F45-48ED-B747-4BA17C249AF1@daork.net> <20220710140519.GN13040@telsasoft.com> <4954694D-9E02-4209-815B-07903F57779A@daork.net> <20220711040527.GQ13040@telsasoft.com> X-Mailer: Apple Mail (2.3696.100.31) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --Apple-Mail=_31158C78-5891-415F-96B2-685A612564AB Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 Hi, I haven=E2=80=99t caught the issue yet with this debug etc. in place, = but auto_explain (and some pg_stat_statements poking about) has helped = me find something interesting that might(?) be related. My data ingest is in 2 functions, depending on the type of data: - RADIUS data with usage info - RADIUS data without usage info The functions are the largely same, except the one with usage info has = to go and work with a table with lots of partitions (444, right at the = moment). The function that works with the usage info is *significantly* slower. One thing I have specifically noticed is that the run time for the total = function doesn=E2=80=99t add up to the run time of each of the of the = nested statements. Not even close. It=E2=80=99s around 16ms on average = (both in pg_stat_statements and in the auto_explain), but the nested = statements add up to around 1-2ms or so - which I think means the = planner is the culprit here. I have been stepping through the various statements which are different = between the two functions, and note that when I do math on a timestamp = in a SELECT statement (i.e. _event_timestamp - INTERVAL =E2=80=981 = hour=E2=80=99), the planner takes 50ms or so - note that the result of = the timestamp is used to search the partition key. If I declare a function which does the math in advance, stores it in a = variable and then runs the SELECT, the planner takes less than 1ms. Does this mean it=E2=80=99s calculating the timestamp for each = partition, or something like that? I have updated the function in my production database to do this math in = advance, and the mean time is down to around 6ms, from 16ms. This is still longer than the actual statement execution times in the = auto_explain output - which add up to around 1-2ms - but it=E2=80=99s = better! I=E2=80=99ve also turned on pg_stat_statements.track_planning and will = see what that looks like after some time. I see Postgres 14 release notes has information about performance = improvements in the planner for updates on tables with "many = partitions=E2=80=9D. Is 444 partitions =E2=80=9Cmany=E2=80=9D? My updates are all impacting a single partition only. > On 11/07/2022, at 6:20 PM, Nathan Ward = wrote: >=20 >>=20 >> On 11/07/2022, at 4:05 PM, Justin Pryzby = wrote: >>=20 >> On Mon, Jul 11, 2022 at 03:21:38PM +1200, Nathan Ward wrote: >>>> Note that postgres doesn't automatically analyze parent tables, so = you should >>>> maybe do that whenever the data changes enough for it to matter. >>>=20 >>> Hmm. This raises some stuff I=E2=80=99m not familiar with - does = analysing a parent table do anything? >>=20 >> Yes >>=20 >> You could check if you have stats now (maybe due to a global ANALYZE = or >> analyzedb) and how the query plans change if you analyze. >> The transaction may be overly conservative. >>=20 >> SELECT COUNT(1) FROM pg_stats WHERE tablename=3DPARENT; >> SELECT last_analyze, last_autoanalyze, relname FROM = pg_stat_all_tables WHERE relname=3DPARENT; >> begin; >> SET default_statistics_target=3D10; >> ANALYZE; >> explain SELECT [...]; >> rollback; >=20 > I have a development database which gets a mirror of about 50% of the = data coming in, and ran a global ANALYZE earlier on - and note that the = disk IO is actually a lot higher since which is interesting and not = desirable obviously, so I have some more fiddling to do.. > The behaviour during the ANALYZE was very similar to what happens on = my production database when things go funny though, so, this feels like = it=E2=80=99s getting me close. >=20 > The above is going to be a bit tricky to do I think - the ingest = process runs a stored procedure, and behaviour varies quite a bit if I = stick in synthetic values. >=20 > I think probably my approach for now will be to turn on auto explain = with some sampling, and see what happens. >=20 >=20 > Side note, in the auto_explain docs, there is a note in a callout box = saying that log_analyze has a high impact even if the query isn=E2=80=99t = logged - if I use sampling, is this still the case - i.e. all queries = are impacted - or is it only the sampled queries? >=20 >>> I got the impression that analysing the parent was just shorthand = for analysing all of the attached partitions. >>=20 >> Could you let us know if the documentation left that impression ? >>=20 >> See here (this was updated recently). >>=20 >> https://www.postgresql.org/docs/13/sql-analyze.html#id-1.9.3.46.8 >>=20 >> For partitioned tables, ANALYZE gathers statistics by sampling rows = from all partitions; in addition, it will recurse into each partition = and update its statistics. Each leaf partition is analyzed only once, = even with multi-level partitioning. No statistics are collected for only = the parent table (without data from its partitions), because with = partitioning it's guaranteed to be empty. >>=20 >> By contrast, if the table being analyzed has inheritance children, = ANALYZE gathers two sets of statistics: one on the rows of the parent = table only, and a second including rows of both the parent table and all = of its children. This second set of statistics is needed when planning = queries that process the inheritance tree as a whole. The child tables = themselves are not individually analyzed in this case. >>=20 >> The autovacuum daemon does not process partitioned tables, nor does = it process inheritance parents if only the children are ever modified. = It is usually necessary to periodically run a manual ANALYZE to keep the = statistics of the table hierarchy up to date. >=20 >=20 > It was this part: > =E2=80=9C=E2=80=9D=E2=80=9D > No statistics are collected for *only* the parent table (without data = from its partitions), because with partitioning it's guaranteed to be = empty. > =E2=80=9C=E2=80=9D=E2=80=9D >=20 > Emphasis around =E2=80=9Conly=E2=80=9D is mine - I think my brain = skipped that word, but, it=E2=80=99s obviously critical. >=20 > I also note this: > =E2=80=9C=E2=80=9D=E2=80=9D > It is usually necessary to periodically run a manual ANALYZE to keep = the statistics of the table hierarchy up to date. > =E2=80=9C=E2=80=9D=E2=80=9D > This seems really important and is something I was entirely unaware of = - maybe this should be in one of those callout boxes. >=20 >=20 >>> Perhaps because I attach a table with data, the parent sometimes = decides it needs to run analyse on a bunch of things? >>=20 >> No, that doesn't happen. >=20 > Ack. >=20 >>> Or, maybe it uses the most recently attached partition, with bad = statistics, to plan queries that only touch other partitions? >>=20 >> This is closer to what I was talking about. >>=20 >> To be clear, you are using relkind=3Dp partitions (added in v10), and = not >> inheritance parents, right ? >=20 > Yes, relkind=3Dp. >=20 > -- > Nathan Ward --Apple-Mail=_31158C78-5891-415F-96B2-685A612564AB Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8
Hi,

I = haven=E2=80=99t caught the issue yet with this debug etc. in place, but = auto_explain (and some pg_stat_statements poking about) has helped me = find something interesting that might(?) be related.

My data ingest is in 2 functions, depending on = the type of data:
- RADIUS data with usage info
- = RADIUS data without usage info

The = functions are the largely same, except the one with usage info has to go = and work with a table with lots of partitions (444, right at the = moment).

The function that works with the = usage info is *significantly* slower.
One thing I have = specifically noticed is that the run time for the total function = doesn=E2=80=99t add up to the run time of each of the of the nested = statements. Not even close. It=E2=80=99s around 16ms on average (both in = pg_stat_statements and in the auto_explain), but the nested statements = add up to around 1-2ms or so - which I think means the planner is the = culprit here.

I have been stepping = through the various statements which are different between the two = functions, and note that when I do math on a timestamp in a SELECT = statement (i.e. _event_timestamp - INTERVAL =E2=80=981 hour=E2=80=99), = the planner takes 50ms or so - note that the result of the timestamp is = used to search the partition key.
If I declare a function which = does the math in advance, stores it in a variable and then runs the = SELECT, the planner takes less than 1ms.

Does = this mean it=E2=80=99s calculating the timestamp for each partition, or = something like that?


I have updated the function in my production database = to do this math in advance, and the mean time is down to around 6ms, = from 16ms.
This is still longer than the actual statement = execution times in the auto_explain output - which add up to around = 1-2ms - but it=E2=80=99s better!


I=E2=80=99ve also turned on = pg_stat_statements.track_planning and will see what that looks like = after some time.


I = see Postgres 14 release notes has information about performance = improvements in the planner for updates on tables with "many = partitions=E2=80=9D. Is 444 partitions =E2=80=9Cmany=E2=80=9D?
My = updates are all impacting a single partition only.

On 11/07/2022, at 6:20 PM, Nathan Ward <lists+postgresql@daork.net> wrote:


On 11/07/2022, at 4:05 PM, Justin = Pryzby <pryzby@telsasoft.com> wrote:

On Mon, Jul 11, 2022 at 03:21:38PM +1200, Nathan Ward = wrote:
Note that postgres doesn't automatically = analyze parent tables, so you should
maybe do that = whenever the data changes enough for it to matter.

Hmm. This raises some stuff I=E2=80= =99m not familiar with - does analysing a parent table do anything?

Yes

You could check if you have stats now (maybe due to a global = ANALYZE or
analyzedb) and how the query plans change if = you analyze.
The transaction may be overly = conservative.

SELECT COUNT(1) FROM pg_stats = WHERE tablename=3DPARENT;
SELECT last_analyze, = last_autoanalyze, relname FROM pg_stat_all_tables WHERE = relname=3DPARENT;
begin;
SET = default_statistics_target=3D10;
ANALYZE;
explain SELECT [...];
rollback;

I have a development database which gets a mirror of about = 50% of the data coming in, and ran a global ANALYZE earlier on - and = note that the disk IO is actually a lot higher since which is = interesting and not desirable obviously, so I have some more fiddling to = do..
The behaviour = during the ANALYZE was very similar to what happens on my production = database when things go funny though, so, this feels like it=E2=80=99s = getting me close.

The above is going to be a bit tricky to do I think - the = ingest process runs a stored procedure, and behaviour varies quite a bit = if I stick in synthetic values.

I think probably my approach for now will be to turn on auto = explain with some sampling, and see what happens.


Side note, in the auto_explain = docs, there is a note in a callout box saying that log_analyze has a = high impact even if the query isn=E2=80=99t logged - if I use sampling, = is this still the case - i.e. all queries are impacted - or is it only = the sampled queries?

I = got the impression that analysing the parent was just shorthand for = analysing all of the attached partitions.

Could you let us know if the documentation left that = impression ?

See here (this was updated = recently).

https://www.postgresql.org/docs/13/sql-analyze.html#id-1.9.3.46= .8

For partitioned tables, ANALYZE = gathers statistics by sampling rows from all partitions; in addition, it = will recurse into each partition and update its statistics. Each leaf = partition is analyzed only once, even with multi-level partitioning. No = statistics are collected for only the parent table (without data from = its partitions), because with partitioning it's guaranteed to be = empty.

By contrast, if the table being = analyzed has inheritance children, ANALYZE gathers two sets of = statistics: one on the rows of the parent table only, and a second = including rows of both the parent table and all of its children. This = second set of statistics is needed when planning queries that process = the inheritance tree as a whole. The child tables themselves are not = individually analyzed in this case.

The = autovacuum daemon does not process partitioned tables, nor does it = process inheritance parents if only the children are ever modified. It = is usually necessary to periodically run a manual ANALYZE to keep the = statistics of the table hierarchy up to date.


It was this part:
=E2=80=9C=E2=80=9D=E2=80=9D
No statistics are collected for *only* the parent table = (without data from its partitions), because with partitioning it's = guaranteed to be empty.
=E2=80=9C=E2=80=9D=E2=80=9D

Emphasis around =E2=80=9Conly=E2=80=9D is mine - I think my = brain skipped that word, but, it=E2=80=99s obviously critical.

I also note this:
=E2=80=9C=E2=80=9D=E2=80=9D=
It is usually = necessary to periodically run a manual ANALYZE to keep the statistics of = the table hierarchy up to date.
=E2=80=9C=E2=80=9D=E2=80=9D
This seems really important and is something I was entirely = unaware of - maybe this should be in one of those callout = boxes.


Perhaps because I attach = a table with data, the parent sometimes decides it needs to run analyse = on a bunch of things?

No, that = doesn't happen.

Ack.

Or, maybe it uses the most recently attached partition, with = bad statistics, to plan queries that only touch other partitions?

This is closer to what I was = talking about.

To be clear, you are using = relkind=3Dp partitions (added in v10), and not
inheritance = parents, right ?

Yes, relkind=3Dp.

--
Nathan = Ward

= --Apple-Mail=_31158C78-5891-415F-96B2-685A612564AB--