This is instead the strace of another server running the same version compiled but that is even slower.
Il giorno mer 6 mar 2019 alle ore 11:14 Nicola Contu <nicola.contu@xxxxxxxxx> ha scritto:
Here is the strace as requested for pg11ThanksIl 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
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 2019-03-06 11:04:56 GMT [127.0.0.1(46276)] [14799]: [2-1] db=cmdv3preprod,user=cmdpreprodapp FATAL: terminating connection due to administrator command 32.50 143.010306 7 21044095 lseek 26.21 115.354045 14 8144577 read 6.18 27.185578 16 1669889 10 sendto 5.29 23.300584 57 407528 fdatasync 4.93 21.709522 9 2313529 824174 recvfrom 3.31 14.547568 19 765897 write 2.73 12.007486 14 867088 14494 epoll_wait 2.18 9.597460 15 659871 84097 futex 1.85 8.147759 14 567414 close 1.77 7.767832 18 437656 11319 open 1.53 6.749496 161 42009 wait4 1.39 6.110869 226 26994 setsid 1.31 5.760971 15 396402 brk 1.16 5.083198 29 175022 munmap 0.90 3.954892 18 224829 epoll_ctl 0.89 3.928084 17 227227 1 mmap 0.77 3.376280 11 298018 rt_sigaction 0.63 2.778183 16 178446 kill 0.63 2.763563 17 159928 rt_sigprocmask 0.52 2.306854 12 190988 fstat 0.42 1.850528 128 14468 sync_file_range 0.35 1.534351 52 29591 18762 select 0.35 1.532532 16 96298 epoll_create1 0.32 1.415160 2331 607 fsync 0.29 1.263220 21 61605 35503 stat 0.28 1.227967 125 9827 28 fallocate 0.27 1.195613 8 153557 38629 rt_sigreturn 0.26 1.123353 112 10013 173 unlink 0.24 1.060130 20 52112 mprotect 0.11 0.487515 18 26994 clone 0.10 0.458161 11 41080 fadvise64 0.10 0.440217 16 26991 1 access 0.09 0.406644 4 109169 fcntl 0.04 0.188007 173 1088 rename 0.04 0.181400 18 9829 ftruncate 0.03 0.119387 4 26995 pipe 0.01 0.036748 1 26995 set_robust_list 0.01 0.023510 24 1000 dup 0.00 0.019099 13 1425 setitimer 0.00 0.017918 18 981 setsockopt 0.00 0.015479 26 595 accept 0.00 0.010666 18 602 getsockname 0.00 0.010172 50 202 getdents 0.00 0.004645 28 165 openat 0.00 0.003369 73 46 link 0.00 0.002171 43 50 mremap 0.00 0.000213 71 3 2 mkdir 0.00 0.000189 32 6 getcwd 0.00 0.000179 30 6 bind 0.00 0.000153 10 15 getrusage 0.00 0.000152 30 5 chdir 0.00 0.000133 12 11 socket 0.00 0.000119 24 5 lstat 0.00 0.000102 13 8 2 connect 0.00 0.000083 83 1 rmdir 0.00 0.000070 23 3 geteuid 0.00 0.000068 23 3 listen 0.00 0.000056 28 2 umask 0.00 0.000046 15 3 getrlimit 0.00 0.000042 42 1 execve 0.00 0.000037 37 1 chmod 0.00 0.000030 30 1 arch_prctl 0.00 0.000025 25 1 getuid 0.00 0.000024 24 1 shmget 0.00 0.000022 22 1 shmat 0.00 0.000022 22 1 statfs 0.00 0.000021 21 1 getsockopt 0.00 0.000018 9 2 getppid 0.00 0.000012 12 1 set_tid_address 0.00 0.000008 8 1 shmdt 0.00 0.000000 0 6 recvmsg ------ ----------- ----------- --------- --------- ---------------- 100.00 440.070316 39499781 1027195 total
