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 1oAOyz-0003Qc-Qp for pgsql-performance@arkaria.postgresql.org; Sun, 10 Jul 2022 04:55:50 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1oAOyw-0004Y8-Ux for pgsql-performance@arkaria.postgresql.org; Sun, 10 Jul 2022 04:55:46 +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 1oAOyw-0004Xy-Ig for pgsql-performance@lists.postgresql.org; Sun, 10 Jul 2022 04:55:46 +0000 Received: from mail-pj1-f52.google.com ([209.85.216.52]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1oAOys-0006kp-DU for pgsql-performance@lists.postgresql.org; Sun, 10 Jul 2022 04:55:45 +0000 Received: by mail-pj1-f52.google.com with SMTP id o3-20020a17090a744300b001ef8f7f3dddso2175995pjk.3 for ; Sat, 09 Jul 2022 21:55:41 -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:mime-version:subject:message-id:date:to; bh=ozqUIqG7niMD7KRn972WBFnBkzaQ4mH2mb+5cDQn/4g=; b=jlPu0a9srLmk9FgiSEeQEfHBntk+TItJ0U2H0w1QRLt3imGpJtVNTCDwe9cJ3/eFrG GMnHazsDCZIMukclrm06uB5MeT67kOW3bMjdtdziYSzU0F0VvDfg6ESQNwXF7apBuqB7 k/I0OU5cl1F0G1tYn30OQrdWfnCfOud0b0FVFHVzCUwaVETh9iVVFuHtr9NGe/0k0lIe 5QVzwJ4KAk14eVAtXZXqeDbICfUp8uy4MbEuaSvkMAZ2nu7hh23RZ4iG3tXnuDtIxjwR qfzpIc5lnntEYoF638bwV5COSTvI/pkgy+er3qkSA0kmBiVXotmKt2iOuRxfYEYJIogp OGCw== X-Gm-Message-State: AJIora/MsnoV8Ns5dBezOAfuOoE26Tbuq/gaJ2QNJ8IA0HAIMDHxxMRc 3rH4M47WAT2GE3a3u1bDD2hruJAB+i1pQQ== X-Google-Smtp-Source: AGRyM1tLa1jCruNvxS0HMsX7xkaxreKVi2Sp6CKGDtYCHae7DkwXYvrCVHtBNy45DRcw6K0T+Z775Q== X-Received: by 2002:a17:902:ce8f:b0:16b:fbc1:9529 with SMTP id f15-20020a170902ce8f00b0016bfbc19529mr11788405plg.159.1657428938423; Sat, 09 Jul 2022 21:55:38 -0700 (PDT) Received: from smtpclient.apple ([2406:5a00:227b:9501:342d:18ae:3540:5177]) by smtp.gmail.com with ESMTPSA id 84-20020a621757000000b0052531985e3esm2279293pfx.22.2022.07.09.21.55.36 for (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Sat, 09 Jul 2022 21:55:38 -0700 (PDT) From: Nathan Ward Content-Type: multipart/alternative; boundary="Apple-Mail=_1DD21991-D850-42B2-868F-CB8083F62886" Mime-Version: 1.0 (Mac OS X Mail 16.0 \(3696.100.31\)) Subject: Occasional performance issue after changing table partitions Message-Id: <24A451C3-1F45-48ED-B747-4BA17C249AF1@daork.net> Date: Sun, 10 Jul 2022 16:55:34 +1200 To: pgsql-performance@lists.postgresql.org 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=_1DD21991-D850-42B2-868F-CB8083F62886 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 Hi, I am running Postgres 13 on CentOS 7, installed from the = yum.postgresql.org repo. I have 3 servers in different sites, with asynchronous replication = managed by pgpool 4.0.11. Highest latency is 16ms RTT - but shouldn=E2=80=99= t matter as it=E2=80=99s async - but my application is running many = concurrent connections to keep throughput up when latency is high - as = the queries are typically very fast. Servers have 32GB RAM and 4 cores. max_connections =3D 256 max_locks_per_transaction =3D 256 max_stack_depth =3D 2MB max_wal_senders =3D 5 max_wal_size =3D 1GB min_wal_size =3D 80MB shared_buffers =3D 10GB I am storing internet usage data and attributes from RADIUS messages. Our ingest does not come directly from the RADIUS server - instead it = comes via rabbitmq which allows the database performance to drop without = impacting our RADIUS services. I am making pretty heavy use of partitions to manage this. The data = usage accounting is stored in a partition per hour, which runs through = daily aggregation - aggregating usage older than 3 to usage per day, = rather than usage per hour. At this point, we have a partition per day, = rather than per hour. I am doing this, because we want hourly usage for 3 days, and RADIUS = data comes in as a running total rather than a delta per some interval, = and we want to have the deltas available. For each incoming record, we = look at previous hours to find a previous total, and calculate a delta = from that - this means we are regularly (hundred of times per second) = looking at the last 2 hours. Partitioning per hour lets us manage that. I partition on an =E2=80=9Cinterval_start=E2=80=9D timestamp column. The aggregation process which runs each night at some time after = midnight does the following, in a transaction: 1) Create a new =E2=80=9Cfull day=E2=80=9D partition for 3 days ago. 2) Look at hourly data older than 3 days (so, across 24 partitions) and = calculate totals for that internet session on that day and insert in to = the =E2=80=9Cfull day=E2=80=9D table. 3) Detach the hourly partitions 4) Attach the full day partition 5) Drop the hourly partitions This process takes around 12s to run - aggregating around 16.8M rows in = to 700k rows. Each partition is around 70MB. Through this process, data continues to be ingested - but as the data = being aggregated is 3+ days old, and the ingest process is only looking = at current partitions (i.e. last couple hours), we don=E2=80=99t have = any conflicts here. Additionally (and I think less importantly so skip this if it=E2=80=99s = getting long winded) we store all RADIUS attributes from the RADIUS = messages as jsonb, doing deduplication - most RADIUS messages (apart = from the usage, session timers, etc.) are static, so we have a table of = those =E2=80=9Cstatic=E2=80=9D attributes in a jsonb column, and a table = of events matching timestamps to sets of RADIUS messages. These tables also make use of partitioning - we have hot, cold, and = frozen data so that only the hot and cold indexes are in memory most of = the time - the =E2=80=9Cfrozen=E2=80=9D data is very large (100s of GB) = so is only used for reporting. There are a couple of processes which run over this data periodically: 1) Move data from hot -> cold -> frozen as it ages 2) Aggregate =E2=80=9Cevents=E2=80=9D (i.e. RADIUS message timestamp to = attributes) together so that longer term we don=E2=80=99t have a row per = message, and rather only a row each time the attributes for a RADIUS = session changes. This means there is always dead rows in this table, but = they regularly get re-used. This appears to work very well, these processes run every 5 mins or so. = The event aggregation process drops around 180k rows. The issue I am having, is that when the daily data usage aggregation = runs, sometimes we have a big performance impact, with the following = characteristics which happen *after* the aggregation job runs in it = usual fast time of 12s or so: - The aggregation runs fast as per normal - Load on the server goes to 30-40 - recall we have quite high =E2=80=9Cma= x connections=E2=80=9D to keep throughput high when the client is far = (16ms) from the server - IOWait drops to ~0% (it=E2=80=99s usually at around 1-2%) but actual = disk IO rates seem approx normal - User and System CPU increase to a total of 100% - ~86% and ~14% = respectively - Processing time for RADIUS messages increases, and a big processing = backlog builds - Swap is not used - it is enabled, but very low swap IO - Memory usage does not change If I stop the ingest process briefly, then start it up again, the = problem goes away - the database server drops to 0% CPU, then after = starting the ingest process the backlog clears very rapidly and = performance is back to normal. This happens maybe once or twice a week - it=E2=80=99s not every day. = It=E2=80=99s not on specific days each week. There is a vague correlation with other aggregation jobs (i.e. event = aggregation mentioned above) running immediately after the daily data = usage aggregation. Only one of these jobs runs at once - so if another = scheduled job wants to run, it will run immediately after whatever is = already running. I am wondering if there=E2=80=99s some sort of problem where we drop all = these partitions, and postgres needs to do some work internally to free = the space up or something, but has a hard time doing so with all the = updates going on? I am not clear why this only happens some days - I am working on seeing = if I can firm up (or rule out) the correlation with other aggregation = jobs running immediately afterwards. Can anyone recommend some things to look at here? I=E2=80=99ve got quite = a bit of metrics collected every minute - per-table io (i.e. hit/read), = index sizes, table sizes, etc. - however everything there seems = =E2=80=9Cnormal=E2=80=9D for the slow ingest rate when the issue occurs, = so it=E2=80=99s hard to differentiate between cause and symptoms in = those metrics. I have bumped up effective_cache_size from default of 4GB to 16GB since = this last happened - but given IO doesn=E2=80=99t appear to be an issue, = I don=E2=80=99t think this will have too much effect. -- Nathan Ward --Apple-Mail=_1DD21991-D850-42B2-868F-CB8083F62886 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8 Hi,

I am = running Postgres 13 on CentOS 7, installed from the yum.postgresql.org repo.

I have 3 servers in different sites, = with asynchronous replication managed by pgpool 4.0.11. Highest latency = is 16ms RTT - but shouldn=E2=80=99t matter as it=E2=80=99s async - but = my application is running many concurrent connections to keep throughput = up when latency is high - as the queries are typically very = fast.

Servers have 32GB RAM and 4 cores.

max_connections =3D 256
max_locks_per_transaction =3D 256
max_stack_depth =3D 2MB
max_wal_senders = =3D 5
max_wal_size =3D 1GB
min_wal_size =3D 80MB
shared_buffers =3D = 10GB

I = am storing internet usage data and attributes from RADIUS = messages.
Our ingest does not come directly from = the RADIUS server - instead it comes via rabbitmq which allows the = database performance to drop without impacting our RADIUS = services.

I am = making pretty heavy use of partitions to manage this. The data usage = accounting is stored in a partition per hour, which runs through daily = aggregation - aggregating usage older than 3 to usage per day, rather = than usage per hour. At this point, we have a partition per day, rather = than per hour.
I am doing this, because we want = hourly usage for 3 days, and RADIUS data comes in as a running total = rather than a delta per some interval, and we want to have the deltas = available. For each incoming record, we look at previous hours to find a = previous total, and calculate a delta from that - this means we are = regularly (hundred of times per second) looking at the last 2 hours. = Partitioning per hour lets us manage that.
I = partition on an =E2=80=9Cinterval_start=E2=80=9D timestamp = column.

The = aggregation process which runs each night at some time after midnight = does the following, in a transaction:
1) Create a = new =E2=80=9Cfull day=E2=80=9D partition for 3 days ago.
2) Look at hourly data older than 3 days (so, across 24 = partitions) and calculate totals for that internet session on that day = and insert in to the =E2=80=9Cfull day=E2=80=9D table.
3) Detach the hourly partitions
4) = Attach the full day partition
5) Drop the hourly = partitions

This = process takes around 12s to run - aggregating around 16.8M rows in to = 700k rows.
Each partition is around 70MB.

Through this process, = data continues to be ingested - but as the data being aggregated is 3+ = days old, and the ingest process is only looking at current partitions = (i.e. last couple hours), we don=E2=80=99t have any conflicts = here.



Additionally (and I think less importantly so skip this if = it=E2=80=99s getting long winded) we store all RADIUS attributes from = the RADIUS messages as jsonb, doing deduplication - most RADIUS messages = (apart from the usage, session timers, etc.) are static, so we have a = table of those =E2=80=9Cstatic=E2=80=9D attributes in a jsonb column, = and a table of events matching timestamps to sets of RADIUS = messages.
These tables also make use of = partitioning - we have hot, cold, and frozen data so that only the hot = and cold indexes are in memory most of the time - the =E2=80=9Cfrozen=E2=80= =9D data is very large (100s of GB) so is only used for = reporting.
There are a couple of processes which = run over this data periodically:
1) Move data from = hot -> cold -> frozen as it ages
2) Aggregate = =E2=80=9Cevents=E2=80=9D (i.e. RADIUS message timestamp to attributes) = together so that longer term we don=E2=80=99t have a row per message, = and rather only a row each time the attributes for a RADIUS session = changes. This means there is always dead rows in this table, but they = regularly get re-used.
This appears to work very = well, these processes run every 5 mins or so. The event aggregation = process drops around 180k rows.



The issue I am having, is that when the = daily data usage aggregation runs, sometimes we have a big performance = impact, with the following characteristics which happen *after* the = aggregation job runs in it usual fast time of 12s or so:
- The aggregation runs fast as per normal
- Load on the server goes to 30-40 - recall we have quite = high =E2=80=9Cmax connections=E2=80=9D to keep throughput high when the = client is far (16ms) from the server
- IOWait drops = to ~0% (it=E2=80=99s usually at around 1-2%) but actual disk IO rates = seem approx normal
- User and System CPU increase = to a total of 100% - ~86% and ~14% respectively
- = Processing time for RADIUS messages increases, and a big processing = backlog builds
- Swap is not used - it is enabled, = but very low swap IO
- Memory usage does not = change

If = I stop the ingest process briefly, then start it up again, the problem = goes away - the database server drops to 0% CPU, then after starting the = ingest process the backlog clears very rapidly and performance is back = to normal.


This happens maybe once = or twice a week - it=E2=80=99s not every day. It=E2=80=99s not on = specific days each week.
There is a vague = correlation with other aggregation jobs (i.e. event aggregation = mentioned above) running immediately after the daily data usage = aggregation. Only one of these jobs runs at once - so if another = scheduled job wants to run, it will run immediately after whatever is = already running.


I am wondering if = there=E2=80=99s some sort of problem where we drop all these partitions, = and postgres needs to do some work internally to free the space up or = something, but has a hard time doing so with all the updates going = on?
I am not clear why this only happens some days = - I am working on seeing if I can firm up (or rule out) the correlation = with other aggregation jobs running immediately afterwards.


Can anyone recommend some things to look at here? I=E2=80=99ve = got quite a bit of metrics collected every minute - per-table io (i.e. = hit/read), index sizes, table sizes, etc. - however everything there = seems =E2=80=9Cnormal=E2=80=9D for the slow ingest rate when the issue = occurs, so it=E2=80=99s hard to differentiate between cause and symptoms = in those metrics.


I have bumped up = effective_cache_size from default of 4GB to 16GB since this last = happened - but given IO doesn=E2=80=99t appear to be an issue, I don=E2=80= =99t think this will have too much effect.

--
Nathan = Ward

= --Apple-Mail=_1DD21991-D850-42B2-868F-CB8083F62886--