Thread: Need help identifying a periodic performance issue.

On Tue, Nov 16, 2021 at 04:43:25AM +0000, Robert Creager wrote:
> We’re executing the following copy to fill a table with approximately 5k records, then repeating for a total of 250k
records. Normally, this copy executes < 1 second, with the entire set taking a couple of minutes. The problem is not
reproducibleon command, but usually within a couple of hours of starting some test runs.
 
> 
> COPY ds3.blob (byte_offset, checksum, checksum_type, id, length, object_id) FROM STDIN WITH DELIMITER AS ‘|’
> 
> But, occasionally we get into a huge performance bottleneck for about 2 hours, where these copy operations are taking
140seconds or so
 
> 
> Nov 15 22:25:49 sm4u-34 postgres[5799]: [381-1] db=tapesystem,user=Administrator,app=PostgreSQL JDBC
Driver,client=127.0.0.1LOG:  duration: 145326.293 ms  statement: COPY ds3.blob (byte_offset, checksum, checksum_type,
id,length, object_id) FROM STDIN WITH DELIMITER AS '|'
 

> I’m logging statements with pgbadger monitoring the logs. There are no apparent auto-vacuum’s running, nor any
vacuums,nor anything at all really. Other select queries around that time frame are executing normally.
 

What about checkpoints ?

Would you show the "^checkpoint starting" and "^checkpoint complete" logs
surrounding a slow COPY ?

> We’re coming from PostgreSQL 9.6 on FreeBSD 11 where we did not see this problem, but have a major release upgrade
happening. I’m checking to see if this machine was updated or was a fresh install.
 
>  PostgreSQL 13.2 on amd64-portbld-freebsd13.0, compiled by FreeBSD clang version 11.0.1
(git@github.com<mailto:git@github.com>:llvm/llvm-project.gitllvmorg-11.0.1-0-g43ff75f2c3fe), 64-bit
 
> 
> Changes made to the settings in the postgresql.conf file
>  checkpoint_timeout              | 30min                           | configuration file
>  log_checkpoints                 | on                              | configuration file
>  log_lock_waits                  | on                              | configuration file
...
>  shared_buffers                  | 21679MB                         | configuration file

> Operating system and version:
> FreeBSD sm4u-34 13.0-STABLE FreeBSD 13.0-STABLE #0: Mon Sep 13 10:11:57 MDT 2021

> These are the system calls made over 30 seconds from Postgres during a slowdown.
...
>   fsync                                                            27

-- 
Justin

On Tue, Nov 16, 2021 at 5:43 PM Robert Creager <robertc@spectralogic.com> wrote:
> One CPU is pegged, the data has been sent over STDIN, so Postgres is not waiting for more, there are no other queries
runningusing this select:
 

So PostgreSQL is eating 100% CPU, with no value shown in
wait_event_type, and small numbers of system calls are counted.  In
that case, is there an interesting user stack that jumps out with a
profiler during the slowdown (or the kernel version, stack())?

sudo dtrace -n 'profile-99 /arg0/ { @[ustack()] = count(); } tick-10s
{ exit(0); }'

On Wed, Nov 17, 2021 at 11:40 AM Robert Creager
<robertc@spectralogic.com> wrote:
> Presuming this is the type of output you are expecting:
>
> CPU     ID                    FUNCTION:NAME
>   0  58709                        :tick-10s
>
>
>               postgres`AtEOXact_LargeObject+0x11
>               postgres`CommitTransaction+0x127
>               postgres`CommitTransactionCommand+0xf2
>               postgres`PostgresMain+0x1fef
>               postgres`process_startup_packet_die
>               postgres`0x73055b
>               postgres`PostmasterMain+0xf36
>               postgres`0x697837
>               postgres`_start+0x100
>               `0x80095f008
>                 1

It's the right output format, but isn't /pid == '$PID'/ only going to
match one single process called "postgres"?   Maybe /execname ==
"postgres"/ to catch them all?  Hopefully it'll be obvious what's
going on from an outlier stack with a high sample count.  Can also be
useful to convert the output to flamegraph format if CPU time is
distributed over many distinct stacks.

On Wed, Nov 17, 2021 at 11:51 AM Thomas Munro <thomas.munro@gmail.com> wrote:
> It's the right output format, but isn't /pid == '$PID'/ only going to
> match one single process called "postgres"?   Maybe /execname ==
> "postgres"/ to catch them all?

Oh, duh, it's the top CPU one.  Makes sense.  Never mind :-)