[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