Here is the strace as requested for pg11
Thanks
Il giorno mar 5 mar 2019 alle ore 17:47 Thomas Munro <thomas.mu...@gmail.com>
ha scritto:
> On Wed, Mar 6, 2019 at 4:22 AM Nicola Contu <nicola.co...@gmail.com>
> 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
