Thread: [HACKERS] Performance issue after upgrading from 9.4 to 9.6

On Thu, Mar 9, 2017 at 7:47 AM, Naytro Naytro <naytro@googlemail.com> wrote:
> We are having some performance issues after we upgraded to newest
> version of PostgreSQL, before it everything was fast and smooth.
>
> Upgrade was done by pg_upgrade from 9.4 directly do 9.6.1. Now we
> upgraded to 9.6.2 with no improvement.
>
> Some information about our setup: Freebsd, Solaris (SmartOS), simple
> master-slave using streaming replication.
>
> Problem:
> Very high system CPU when master is streaming replication data, CPU
> goes up to 77%. Only one process is generating this load, it's a
> postgresql startup process. When I attached a truss to this process I
> saw a lot o read calls with almost the same number of errors (EAGAIN).
> read(6,0x7fffffffa0c7,1) ERR#35 'Resource temporarily unavailable'
>
> Descriptor 6 is a pipe
>
> Read call try to read one byte over and over, I looked up to source
> code and I think this file is responsible for this behavior
> src/backend/storage/ipc/latch.c. There was no such file in 9.4.

Our latch implementation did get overhauled pretty thoroughly in 9.6;
see primarily commit 98a64d0bd713cb89e61bef6432befc4b7b5da59e.  But I
can't guess what is going wrong here based on this information.  It
might help if you can pull some stack backtraces from the startup
process.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Hi,

On 2017-03-09 13:47:35 +0100, Naytro Naytro wrote:
> We are having some performance issues after we upgraded to newest
> version of PostgreSQL, before it everything was fast and smooth.
> 
> Upgrade was done by pg_upgrade from 9.4 directly do 9.6.1. Now we
> upgraded to 9.6.2 with no improvement.
> 
> Some information about our setup: Freebsd, Solaris (SmartOS), simple
> master-slave using streaming replication.

Which node is on which of those, and where is the high load?


> Problem:
> Very high system CPU when master is streaming replication data, CPU
> goes up to 77%. Only one process is generating this load, it's a
> postgresql startup process. When I attached a truss to this process I
> saw a lot o read calls with almost the same number of errors (EAGAIN).

Hm. Just to clarify: The load is on the *receiving* side, in the startup
process?  Because the load doesn't quite look that way...


> read(6,0x7fffffffa0c7,1) ERR#35 'Resource temporarily unavailable'
> 
> Descriptor 6 is a pipe

That's presumably a latches internal pipe.  Could you redo that
truss/strace with timestamps attached?  Does truss show signals
received? The above profile would e.g. make a lot more sense if not.  Is
the wal receiver sending signals?


> Read call try to read one byte over and over, I looked up to source
> code and I think this file is responsible for this behavior
> src/backend/storage/ipc/latch.c. There was no such file in 9.4.

It was "just" moved (and expanded), used to be at
src/backend/port/unix_latch.c.

There normally shouldn't be that much "latch traffic" in the startup
process, we'd expect to block from within WaitForWALToBecomeAvailable().

Hm.  Any chance you've configured a recovery_min_apply_delay?  Although
I'd expect more timestamp calls in that case.


Greetings,

Andres Freund