Here is the strace as requested for pg11
Thanks
Il giorno mar 5 mar 2019 alle ore 17:47 Thomas Munro <thomas.munro@xxxxxxxxx> ha scritto:
On Wed, Mar 6, 2019 at 4:22 AM Nicola Contu <nicola.contu@xxxxxxxxx> wrote:
>
> Not sure what you are requesting exactly but here is the strace for the start of the pg_ctl
I meant that you could run the server itself in the foreground under
strace, like so:
$ strace -f -c /usr/local/pgsql11.2/bin/postgres -D /db/pgsql11/data/
Then perform your testing, and finally stop it with pg_ctl from
another window (or hit ^C in this window) and strace should spit out a
table of system calls with some counters. We might be able to see why
v11 is spending so much more time executing system calls than v10 for
your workload, or at least which systems calls they are, assuming you
run the same transactions against both versions.
--
Thomas Munro
https://enterprisedb.com
[postgres@STAGING-CMD1 ~]$ strace -f -c /usr/local/pgsql11.2/bin/postgres -D /db/pgsql11/data/ 2019-03-06 10:07:47 GMT [] [163892]: [1-1] db=,user= LOG: listening on IPv4 address "0.0.0.0", port 5432 2019-03-06 10:07:47 GMT [] [163892]: [2-1] db=,user= LOG: listening on IPv6 address "::", port 5432 2019-03-06 10:07:47 GMT [] [163892]: [3-1] db=,user= LOG: listening on Unix socket "/tmp/.s.PGSQL.5432" strace: Process 163894 attached 2019-03-06 10:07:48 GMT [] [163894]: [1-1] db=,user= LOG: database system was shut down at 2019-03-06 10:06:22 GMT strace: Process 163895 attached strace: Process 163896 attached strace: Process 163897 attached strace: Process 163898 attached strace: Process 163899 attached strace: Process 163900 attached 2019-03-06 10:07:48 GMT [] [163892]: [4-1] db=,user= LOG: database system is ready to accept connections strace: Process 163908 attached strace: Process 163915 attached strace: Process 163928 attached strace: Process 163931 attached strace: Process 163943 attached strace: Process 163960 attached strace: Process 163976 attached 2019-03-06 10:09:08 GMT [] [163895]: [1-1] db=,user= LOG: checkpoint starting: xlog strace: Process 163989 attached strace: Process 164002 attached 2019-03-06 10:09:42 GMT [] [163895]: [2-1] db=,user= LOG: checkpoint complete: wrote 201350 buffers (15.4%); 0 WAL file(s) added, 0 removed, 0 recycled; write=33.879 s, sync=0.208 s, total=34.093 s; sync files=30, longest=0.142 s, average=0.006 s; distance=1228942 kB, estimate=1228942 kB strace: Process 164015 attached 2019-03-06 10:09:58 GMT [] [163895]: [3-1] db=,user= LOG: checkpoint starting: xlog strace: Process 164035 attached strace: Process 164050 attached 2019-03-06 10:10:26 GMT [] [163895]: [4-1] db=,user= LOG: checkpoint complete: wrote 126477 buffers (9.6%); 0 WAL file(s) added, 0 removed, 0 recycled; write=27.650 s, sync=0.015 s, total=27.668 s; sync files=30, longest=0.004 s, average=0.000 s; distance=1226813 kB, estimate=1228729 kB strace: Process 164066 attached 2019-03-06 10:10:43 GMT [] [163895]: [5-1] db=,user= LOG: checkpoint starting: xlog strace: Process 164079 attached strace: Process 164102 attached 2019-03-06 10:11:08 GMT [] [163895]: [6-1] db=,user= LOG: checkpoint complete: wrote 125741 buffers (9.6%); 1 WAL file(s) added, 0 removed, 0 recycled; write=24.804 s, sync=0.077 s, total=24.947 s; sync files=30, longest=0.015 s, average=0.002 s; distance=1229772 kB, estimate=1229772 kB strace: Process 164223 attached 2019-03-06 10:11:22 GMT [] [163895]: [7-1] db=,user= LOG: checkpoint starting: xlog strace: Process 164347 attached 2019-03-06 10:11:46 GMT [] [163895]: [8-1] db=,user= LOG: checkpoint complete: wrote 133784 buffers (10.2%); 1 WAL file(s) added, 0 removed, 0 recycled; write=23.399 s, sync=0.141 s, total=23.595 s; sync files=29, longest=0.027 s, average=0.004 s; distance=1227832 kB, estimate=1229578 kB strace: Process 164460 attached 2019-03-06 10:11:52 GMT [[local]] [163931]: [1-1] db=cmdstaging,user=postgres LOG: duration: 209593.079 ms statement: update service_order set customer_pon = now(); strace: Process 164575 attached strace: Process 164694 attached 2019-03-06 10:12:28 GMT [] [163928]: [1-1] db=,user= LOG: automatic vacuum of table "cmdstaging.public.service_order": index scans: 1 pages: 0 removed, 171162 remain, 413 skipped due to pins, 0 skipped frozen tuples: 123264 removed, 1300328 remain, 0 are dead but not yet removable, oldest xmin: 1172166 buffer usage: 890073 hits, 250961 misses, 270986 dirtied avg read rate: 7.826 MB/s, avg write rate: 8.451 MB/s system usage: CPU: user: 12.96 s, system: 10.24 s, elapsed: 250.52 s ^Cstrace: Process 163892 detached 2019-03-06 10:12:29 GMT [] [163892]: [5-1] db=,user= LOG: received fast shutdown request strace: Process 163895 detached strace: Process 163896 detached strace: Process 163897 detached strace: Process 163898 detached strace: Process 163899 detached strace: Process 163900 detached strace: Process 163928 detached strace: Process 163931 detached % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 2019-03-06 10:12:29 GMT [] [163892]: [6-1] db=,user= LOG: aborting any active transactions 2019-03-06 10:12:29 GMT [] [163928]: [2-1] db=,user= FATAL: terminating autovacuum process due to administrator command 2019-03-06 10:12:29 GMT [[local]] [163931]: [2-1] db=cmdstaging,user=postgres FATAL: terminating connection due to administrator command 71.60 12.371671 8 1573947 write 5.81 1.004669 2 481816 read 5.64 0.974727 13 76782 sync_file_range 5.19 0.896717 655 1370 fsync 4.64 0.801652 1 657031 lseek 4.55 0.785944 181 4354 fdatasync 0.96 0.166075 6151 27 setsid 2019-03-06 10:12:29 GMT [] [163892]: [7-1] db=,user= LOG: background worker "logical replication launcher" (PID 163900) exited with exit code 1 2019-03-06 10:12:29 GMT [] [163895]: [9-1] db=,user= LOG: shutting down 2019-03-06 10:12:29 GMT [] [163895]: [10-1] db=,user= LOG: checkpoint starting: shutdown immediate 0.29 0.050526 0 112795 109999 open 0.23 0.039631 4 9508 38 select 0.20 0.033862 4 8098 close 0.16 0.027331 15 1845 sendto 0.16 0.027178 3 10487 epoll_ctl 0.15 0.026539 6 4421 85 epoll_wait 0.08 0.014493 2 6198 1170 futex 0.08 0.013544 3 4345 epoll_create1 0.07 0.012289 3 3641 1797 recvfrom 0.03 0.005584 18 303 link 0.03 0.005098 48 107 rename 0.03 0.004366 12 369 munmap 0.02 0.003996 6 635 320 unlink 0.02 0.002652 41 64 getdents 0.01 0.002203 2 1000 dup 0.01 0.002073 6 360 345 stat 0.01 0.001373 3 440 mmap 0.01 0.001047 2 478 brk 0.00 0.000769 3 307 rt_sigaction 0.00 0.000750 2 344 fstat 0.00 0.000514 2 216 rt_sigprocmask 0.00 0.000342 3 103 kill 0.00 0.000310 8 38 wait4 0.00 0.000288 2 124 123 rt_sigreturn 0.00 0.000184 6 31 1 openat 0.00 0.000122 5 25 1 access 0.00 0.000085 5 18 mprotect 0.00 0.000076 10 8 2 connect 0.00 0.000074 3 27 clone 0.00 0.000072 7 11 socket 0.00 0.000064 1 115 fcntl 0.00 0.000039 1 28 pipe 0.00 0.000036 6 6 bind 0.00 0.000033 6 6 recvmsg 0.00 0.000032 4 9 getsockname 0.00 0.000018 4 5 setitimer 0.00 0.000018 3 6 getcwd 0.00 0.000014 7 2 accept 0.00 0.000013 4 3 listen 0.00 0.000013 3 5 chdir 0.00 0.000010 3 3 setsockopt 0.00 0.000010 0 58 getrusage 0.00 0.000009 9 1 statfs 0.00 0.000009 0 28 set_robust_list 0.00 0.000007 7 1 chmod 0.00 0.000006 3 2 lstat 0.00 0.000006 6 1 shmget 0.00 0.000006 6 1 shmdt 0.00 0.000006 2 3 getrlimit 0.00 0.000006 6 1 fallocate 0.00 0.000004 4 1 shmat 0.00 0.000004 4 1 getsockopt 0.00 0.000004 4 1 ftruncate 0.00 0.000004 1 3 geteuid 0.00 0.000003 2 2 umask 0.00 0.000003 2 2 getppid 0.00 0.000002 2 1 getuid 0.00 0.000002 2 1 arch_prctl 0.00 0.000002 2 1 set_tid_address 0.00 0.000000 0 1 execve ------ ----------- ----------- --------- --------- ---------------- 100.00 17.279209 2961971 113881 total
