Re: [PERFORM] Performance issue after upgrading from 9.4 to 9.6

[Merlin Moncure]

On Mon, Mar 6, 2017 at 7:20 AM, Piotr Gasidło  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).
>
> root@d8:~ # truss -c -p 38091
> ^Csyscall seconds   calls  errors
> semop   0.001611782 198   0
> write   0.74404   2   0
> read2.281535100   17266   12375
> openat  0.000683532  48   0
> lseek   0.177612479   20443   0
> close   0.000395549  48   0
>   - --- ---
> 2.461912846   38005   12375
>
> read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
> lseek(444,0x0,SEEK_END) = 32571392 (0x1f1)
> read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
> lseek(444,0x0,SEEK_END) = 32571392 (0x1f1)
> read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
> lseek(7,0x0,SEEK_END) = 164487168 (0x9cde000)
> lseek(778,0x0,SEEK_END) = 57344 (0xe000)
> read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
> lseek(894,0x0,SEEK_END) = 139296768 (0x84d8000)
> lseek(894,0x4b7e000,SEEK_SET) = 79159296 (0x4b7e000)
> read(894," ~\0\08\a\M--m\0\0\^A\0\M^T\"...,8192) = 8192 (0x2000)
> lseek(3,0xfa6000,SEEK_SET) = 16408576 (0xfa6000)
> read(3,"\M^S\M-P\^E\0\^A\0\0\0\0`\M-z"...,8192) = 8192 (0x2000)
> read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
> lseek(894,0x0,SEEK_END) = 139296768 (0x84d8000)
> lseek(894,0x0,SEEK_END) = 139296768 (0x84d8000)
> lseek(894,0x449c000,SEEK_SET) = 71942144 (0x449c000)
> read(894,"\^_~\0\0\M-H\M-H\M-B\M-b\0\0\^E"...,8192) = 8192 (0x2000)
> lseek(818,0x0,SEEK_END) = 57344 (0xe000)
> read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
> lseek(442,0x0,SEEK_END) = 10174464 (0x9b4000)
> lseek(442,0x4c4000,SEEK_SET) = 4997120 (0x4c4000)
> read(442,"\^_~\0\0\M-P\M-+\M-1\M-b\0\0\0\0"...,8192) = 8192 (0x2000)
> read(6,0x7fffa0c7,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.

Is a git bisect out of the question?

merlin


-- 
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

[PERFORM] Performance issue after upgrading from 9.4 to 9.6

[Piotr Gasidło]

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).

root@d8:~ # truss -c -p 38091
^Csyscall seconds   calls  errors
semop   0.001611782 198   0
write   0.74404   2   0
read2.281535100   17266   12375
openat  0.000683532  48   0
lseek   0.177612479   20443   0
close   0.000395549  48   0
  - --- ---
2.461912846   38005   12375

read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
lseek(444,0x0,SEEK_END) = 32571392 (0x1f1)
read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
lseek(444,0x0,SEEK_END) = 32571392 (0x1f1)
read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
lseek(7,0x0,SEEK_END) = 164487168 (0x9cde000)
lseek(778,0x0,SEEK_END) = 57344 (0xe000)
read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
lseek(894,0x0,SEEK_END) = 139296768 (0x84d8000)
lseek(894,0x4b7e000,SEEK_SET) = 79159296 (0x4b7e000)
read(894," ~\0\08\a\M--m\0\0\^A\0\M^T\"...,8192) = 8192 (0x2000)
lseek(3,0xfa6000,SEEK_SET) = 16408576 (0xfa6000)
read(3,"\M^S\M-P\^E\0\^A\0\0\0\0`\M-z"...,8192) = 8192 (0x2000)
read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
lseek(894,0x0,SEEK_END) = 139296768 (0x84d8000)
lseek(894,0x0,SEEK_END) = 139296768 (0x84d8000)
lseek(894,0x449c000,SEEK_SET) = 71942144 (0x449c000)
read(894,"\^_~\0\0\M-H\M-H\M-B\M-b\0\0\^E"...,8192) = 8192 (0x2000)
lseek(818,0x0,SEEK_END) = 57344 (0xe000)
read(6,0x7fffa0c7,1) ERR#35 'Resource temporarily unavailable'
lseek(442,0x0,SEEK_END) = 10174464 (0x9b4000)
lseek(442,0x4c4000,SEEK_SET) = 4997120 (0x4c4000)
read(442,"\^_~\0\0\M-P\M-+\M-1\M-b\0\0\0\0"...,8192) = 8192 (0x2000)
read(6,0x7fffa0c7,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.


-- 
Piotr Gasidło


-- 
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance