PostgreSQL DBA(152) - pgAdmin（log_XXX parameter：when）

husthxd發表於2019-12-27

本節介紹了與日誌相關的配置引數log_XXX。

### 概覽
在新initdb的資料庫上查詢pg_settings，可查詢PostgreSQL中與log的引數包括：
```
[test@localhost ~]$ psql
Expanded display is used automatically.
psql (12.1)
Type "help" for help.

[local:/var/run/test]:5000 test@testdb=# select category,name,setting from pg_settings where name like 'log%' order by category;
               category               |            name             |            setting             
--------------------------------------+-----------------------------+--------------------------------
 Reporting and Logging / What to Log  | log_lock_waits              | off
 Reporting and Logging / What to Log  | log_checkpoints             | off
 Reporting and Logging / What to Log  | log_connections             | off
 Reporting and Logging / What to Log  | log_timezone                | PRC
 Reporting and Logging / What to Log  | log_temp_files              | -1
 Reporting and Logging / What to Log  | log_disconnections          | off
 Reporting and Logging / What to Log  | log_duration                | off
 Reporting and Logging / What to Log  | log_error_verbosity         | default
 Reporting and Logging / What to Log  | log_statement               | none
 Reporting and Logging / What to Log  | log_replication_commands    | off
 Reporting and Logging / What to Log  | log_autovacuum_min_duration | -1
 Reporting and Logging / What to Log  | log_hostname                | off
 Reporting and Logging / What to Log  | log_line_prefix             | %m [%p] 
 Reporting and Logging / When to Log  | log_min_duration_statement  | -1
 Reporting and Logging / When to Log  | log_min_error_statement     | error
 Reporting and Logging / When to Log  | log_min_messages            | warning
 Reporting and Logging / When to Log  | log_transaction_sample_rate | 0
 Reporting and Logging / Where to Log | log_destination             | stderr
 Reporting and Logging / Where to Log | log_filename                | postgresql-%Y-%m-%d_%H%M%S.log
 Reporting and Logging / Where to Log | logging_collector           | off
 Reporting and Logging / Where to Log | log_truncate_on_rotation    | off
 Reporting and Logging / Where to Log | log_rotation_size           | 10240
 Reporting and Logging / Where to Log | log_file_mode               | 0600
 Reporting and Logging / Where to Log | log_rotation_age            | 1440
 Reporting and Logging / Where to Log | log_directory               | log
 Statistics / Monitoring              | log_statement_stats         | off
 Statistics / Monitoring              | log_planner_stats           | off
 Statistics / Monitoring              | log_executor_stats          | off
 Statistics / Monitoring              | log_parser_stats            | off
(29 rows)

[local:/var/run/test]:5000 test@testdb=#

```
可以看到，日誌直接輸出在控制檯上，而log_打頭的引數有29個，下面從where、when、what這幾個維度來解析這些引數，本節是第二部分，介紹when to log。

### when to log
帶有時間屬性的引數包括log_timezone、log_duration、log_autovacuum_min_duration、log_min_duration_statement
**log_min_messages**
可選項從低到高包括：
debug5
debug4
debug3
debug2
debug1
info
notice
warning
error
log
fatal
panic
預設值為warning。
設定為panic，則只有panic級別的日誌，設定為debug5則包括所有級別的日誌。下面把該引數設定為debug5，重啟資料庫，檢查日誌輸出。
```
[test@localhost ~]$ grep 'log_min_' $PGDATA/postgresql.conf
log_min_messages = debug5   # values in order of decreasing detail:
#log_min_error_statement = error  # values in order of decreasing detail:
#log_min_duration_statement = -1  # -1 is disabled, 0 logs all statements
[test@localhost ~]$ 
[test@localhost ~]$ pg_ctl restart
waiting for server to shut down.... done
server stopped
waiting for server to start....2019-12-27 10:25:15.198 CST [4441] DEBUG:  postgres: PostmasterMain: initial environment dump:
2019-12-27 10:25:15.198 CST [4441] DEBUG:  -----------------------------------------
2019-12-27 10:25:15.198 CST [4441] DEBUG:   XDG_SESSION_ID=12
2019-12-27 10:25:15.198 CST [4441] DEBUG:   HOSTNAME=localhost.localdomain
2019-12-27 10:25:15.198 CST [4441] DEBUG:   TERM=xterm
2019-12-27 10:25:15.198 CST [4441] DEBUG:   SHELL=/bin/bash
2019-12-27 10:25:15.198 CST [4441] DEBUG:   HISTSIZE=1000
2019-12-27 10:25:15.198 CST [4441] DEBUG:   PG_GRANDPARENT_PID=2460
2019-12-27 10:25:15.198 CST [4441] DEBUG:   USER=test
2019-12-27 10:25:15.198 CST [4441] DEBUG:   LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=01;05;37;41:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.jpg=01;35:*.jpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.axv=01;35:*.anx=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=01;36:*.au=01;36:*.flac=01;36:*.mid=01;36:*.midi=01;36:*.mka=01;36:*.mp3=01;36:*.mpc=01;36:*.ogg=01;36:*.ra=01;36:*.wav=01;36:*.axa=01;36:*.oga=01;36:*.spx=01;36:*.xspf=01;36:
2019-12-27 10:25:15.198 CST [4441] DEBUG:   PGPORT=5000
2019-12-27 10:25:15.198 CST [4441] DEBUG:   PGDATABASE=testdb
2019-12-27 10:25:15.198 CST [4441] DEBUG:   LIBDIR=/appdb/pg12/pg12.1/share/postgresql/extension
2019-12-27 10:25:15.198 CST [4441] DEBUG:   PATH=/appdb/pg12/pg12.1/bin:/usr/local/bin:/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/home/test/.local/bin:/home/test/bin
2019-12-27 10:25:15.198 CST [4441] DEBUG:   MAIL=/var/spool/mail/test
2019-12-27 10:25:15.198 CST [4441] DEBUG:   _=/appdb/pg12/pg12.1/bin/pg_ctl
2019-12-27 10:25:15.198 CST [4441] DEBUG:   PWD=/home/test
2019-12-27 10:25:15.198 CST [4441] DEBUG:   LANG=en_US.UTF-8
2019-12-27 10:25:15.198 CST [4441] DEBUG:   PGHOST=/var/run/test
2019-12-27 10:25:15.198 CST [4441] DEBUG:   PGSYSCONFDIR=/appdb/pg12/pg12.1/etc/postgresql
2019-12-27 10:25:15.198 CST [4441] DEBUG:   HISTCONTROL=ignoredups
2019-12-27 10:25:15.198 CST [4441] DEBUG:   HOME=/home/test
2019-12-27 10:25:15.198 CST [4441] DEBUG:   SHLVL=1
2019-12-27 10:25:15.198 CST [4441] DEBUG:   LOGNAME=test
2019-12-27 10:25:15.198 CST [4441] DEBUG:   LESSOPEN=||/usr/bin/lesspipe.sh %s
2019-12-27 10:25:15.198 CST [4441] DEBUG:   PGDATA=/data/pgsql/tmpdb
2019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_COLLATE=en_US.UTF-8
2019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_CTYPE=en_US.UTF-8
2019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_MESSAGES=en_US.UTF-8
2019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_MONETARY=C
2019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_NUMERIC=C
2019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_TIME=C
2019-12-27 10:25:15.198 CST [4441] DEBUG:  -----------------------------------------
2019-12-27 10:25:15.202 CST [4441] DEBUG:  registering background worker "logical replication launcher"
2019-12-27 10:25:15.202 CST [4441] LOG:  starting PostgreSQL 12.1 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-16), 64-bit
2019-12-27 10:25:15.202 CST [4441] LOG:  listening on IPv6 address "::1", port 5000
2019-12-27 10:25:15.202 CST [4441] LOG:  listening on IPv4 address "127.0.0.1", port 5000
2019-12-27 10:25:15.206 CST [4441] LOG:  listening on Unix socket "/var/run/test/.s.PGSQL.5000"
2019-12-27 10:25:15.208 CST [4441] DEBUG:  invoking IpcMemoryCreate(size=149102592)
2019-12-27 10:25:15.208 CST [4441] DEBUG:  mmap(150994944) with MAP_HUGETLB failed, huge pages disabled: Cannot allocate memory
2019-12-27 10:25:15.218 CST [4441] DEBUG:  SlruScanDirectory invoking callback on pg_notify/0000
2019-12-27 10:25:15.218 CST [4441] DEBUG:  removing file "pg_notify/0000"
2019-12-27 10:25:15.218 CST [4441] DEBUG:  dynamic shared memory system will support 308 segments
2019-12-27 10:25:15.218 CST [4441] DEBUG:  created dynamic shared memory control segment 1237114017 (7408 bytes)
2019-12-27 10:25:15.219 CST [4441] DEBUG:  max_safe_fds = 983, usable_fds = 1000, already_open = 7
2019-12-27 10:25:15.219 CST [4441] LOG:  redirecting log output to logging collector process
2019-12-27 10:25:15.219 CST [4441] HINT:  Future log output will appear in directory "log".
 done
server started
[test@localhost ~]$

```
可以看到，在啟動階段輸出很多DEBUG日誌。
下面執行SQL：
```
[local:/var/run/test]:5000 test@testdb=# select * from tbl order by id limit 1;
 id | c1 
----+----
  1 | 1
(1 row)

[local:/var/run/test]:5000 test@testdb=#

```
日誌輸出：
```
...
2019-12-27 10:47:24.850 CST [5763] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
RELOPTINFO (tbl): rows=200002 width=6
  path list:
  SeqScan(tbl) rows=200002 cost=0.00..5540.02

cheapest parameterized paths:
  SeqScan(tbl) rows=200002 cost=0.00..5540.02

cheapest startup path:
  SeqScan(tbl) rows=200002 cost=0.00..5540.02

cheapest total path:
  SeqScan(tbl) rows=200002 cost=0.00..5540.02

2019-12-27 10:47:24.853 CST [5747] DEBUG:  registering background worker "parallel worker for PID 5763"
2019-12-27 10:47:24.853 CST [5747] DEBUG:  registering background worker "parallel worker for PID 5763"
2019-12-27 10:47:24.853 CST [5747] DEBUG:  starting background worker process "parallel worker for PID 5763"
2019-12-27 10:47:24.853 CST [5747] DEBUG:  starting background worker process "parallel worker for PID 5763"
2019-12-27 10:47:24.854 CST [5783] DEBUG:  InitPostgres
2019-12-27 10:47:24.854 CST [5783] DEBUG:  my backend ID is 4
2019-12-27 10:47:24.854 CST [5784] DEBUG:  InitPostgres
2019-12-27 10:47:24.854 CST [5784] DEBUG:  my backend ID is 5
2019-12-27 10:47:24.854 CST [5783] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.854 CST [5784] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.878 CST [5783] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.878 CST [5783] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.879 CST [5784] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.879 CST [5784] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.913 CST [5783] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.913 CST [5783] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.914 CST [5784] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.914 CST [5784] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.945 CST [5784] DEBUG:  CommitTransaction(1) name: unnamed; blockState: PARALLEL_INPROGRESS; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.945 CST [5784] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
2019-12-27 10:47:24.945 CST [5784] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make
2019-12-27 10:47:24.945 CST [5784] DEBUG:  proc_exit(0): 2 callbacks to make
2019-12-27 10:47:24.945 CST [5784] DEBUG:  exit(0)
2019-12-27 10:47:24.945 CST [5783] DEBUG:  CommitTransaction(1) name: unnamed; blockState: PARALLEL_INPROGRESS; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:47:24.945 CST [5784] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2019-12-27 10:47:24.945 CST [5784] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2019-12-27 10:47:24.945 CST [5784] DEBUG:  proc_exit(-1): 0 callbacks to make
2019-12-27 10:47:24.945 CST [5783] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
2019-12-27 10:47:24.945 CST [5783] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make
2019-12-27 10:47:24.945 CST [5783] DEBUG:  proc_exit(0): 2 callbacks to make
2019-12-27 10:47:24.945 CST [5783] DEBUG:  exit(0)
2019-12-27 10:47:24.945 CST [5783] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2019-12-27 10:47:24.945 CST [5783] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2019-12-27 10:47:24.945 CST [5783] DEBUG:  proc_exit(-1): 0 callbacks to make
2019-12-27 10:47:24.946 CST [5747] DEBUG:  reaping dead processes
2019-12-27 10:47:24.946 CST [5747] DEBUG:  unregistering background worker "parallel worker for PID 5763"
2019-12-27 10:47:24.946 CST [5747] DEBUG:  background worker "parallel worker" (PID 5784) exited with exit code 0
2019-12-27 10:47:24.947 CST [5747] DEBUG:  reaping dead processes
2019-12-27 10:47:24.947 CST [5747] DEBUG:  unregistering background worker "parallel worker for PID 5763"
2019-12-27 10:47:24.947 CST [5747] DEBUG:  background worker "parallel worker" (PID 5783) exited with exit code 0
2019-12-27 10:47:24.947 CST [5763] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0

```
執行insert&update
```
[local:/var/run/test]:5000 test@testdb=# insert into tbl(id) select generate_series(1,100000);
INSERT 0 100000
[local:/var/run/test]:5000 test@testdb=# update tbl set id = 4;
UPDATE 500002
[local:/var/run/test]:5000 test@testdb=#

```
日誌輸出
```
2019-12-27 10:49:08.917 CST [5763] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
RELOPTINFO (*SELECT*): rows=100000 width=4
  path list:
  SubqueryScan(*SELECT*) rows=100000 cost=0.00..1500.02

cheapest parameterized paths:
  SubqueryScan(*SELECT*) rows=100000 cost=0.00..1500.02

cheapest startup path:
  SubqueryScan(*SELECT*) rows=100000 cost=0.00..1500.02

cheapest total path:
  SubqueryScan(*SELECT*) rows=100000 cost=0.00..1500.02

2019-12-27 10:49:09.123 CST [5763] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 503/1/0 (used)
2019-12-27 10:49:20.592 CST [5751] DEBUG:  snapshot of 0+0 running transaction ids (lsn 0/A63FC00 oldest xid 504 latest complete 503 next xid 504)
2019-12-27 10:49:24.401 CST [5763] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
RELOPTINFO (tbl): rows=400002 width=44
  path list:
  SeqScan(tbl) rows=400002 cost=0.00..7540.02

cheapest parameterized paths:
  SeqScan(tbl) rows=400002 cost=0.00..7540.02

cheapest startup path:
  SeqScan(tbl) rows=400002 cost=0.00..7540.02

cheapest total path:
  SeqScan(tbl) rows=400002 cost=0.00..7540.02

2019-12-27 10:49:26.477 CST [5763] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 504/1/0 (used)

2019-12-27 10:49:37.140 CST [5751] DEBUG:  snapshot of 0+0 running transaction ids (lsn 0/EF68250 oldest xid 505 latest complete 504 next xid 505)

```
autovacuum的日誌輸出
```
2019-12-27 10:49:58.619 CST [5755] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:58.619 CST [5755] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:58.649 CST [5753] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:58.649 CST [5753] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:58.649 CST [5754] DEBUG:  received inquiry for database 0
2019-12-27 10:49:58.649 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-12-27 10:49:58.649 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-12-27 10:49:58.662 CST [5923] DEBUG:  InitPostgres
2019-12-27 10:49:58.662 CST [5923] DEBUG:  my backend ID is 4
2019-12-27 10:49:58.662 CST [5923] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:58.663 CST [5923] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:58.663 CST [5923] DEBUG:  autovacuum: processing database "testdb"
2019-12-27 10:49:58.663 CST [5754] DEBUG:  received inquiry for database 16384
2019-12-27 10:49:58.663 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-12-27 10:49:58.663 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_16384.stat"
2019-12-27 10:49:58.663 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-12-27 10:49:58.675 CST [5923] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:58.675 CST [5923] DEBUG:  tbl: vac: 500002 (threshold 80050), anl: 600002 (threshold 40050)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_statistic: vac: 6 (threshold 134), anl: 8 (threshold 92)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_type: vac: 0 (threshold 131), anl: 2 (threshold 91)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_authid: vac: 0 (threshold 52), anl: 0 (threshold 51)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_attribute: vac: 0 (threshold 633), anl: 8 (threshold 341)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_proc: vac: 0 (threshold 642), anl: 0 (threshold 346)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_class: vac: 0 (threshold 129), anl: 1 (threshold 90)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_index: vac: 0 (threshold 82), anl: 0 (threshold 66)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_operator: vac: 0 (threshold 204), anl: 0 (threshold 127)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_opclass: vac: 0 (threshold 76), anl: 0 (threshold 63)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_amop: vac: 0 (threshold 193), anl: 0 (threshold 122)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_amproc: vac: 0 (threshold 139), anl: 0 (threshold 95)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_rewrite: vac: 0 (threshold 75), anl: 0 (threshold 63)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_cast: vac: 0 (threshold 93), anl: 0 (threshold 72)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_namespace: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_depend: vac: 0 (threshold 1570), anl: 3 (threshold 810)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_tablespace: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_shdepend: vac: 0 (threshold 52), anl: 0 (threshold 51)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_ts_config: vac: 0 (threshold 54), anl: 0 (threshold 52)
2019-12-27 10:49:58.675 CST [5923] DEBUG:  pg_publication: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-12-27 10:49:58.676 CST [5754] DEBUG:  received inquiry for database 16384
2019-12-27 10:49:58.676 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-12-27 10:49:58.676 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_16384.stat"
2019-12-27 10:49:58.676 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-12-27 10:49:58.686 CST [5923] DEBUG:  tbl: vac: 500002 (threshold 80050), anl: 600002 (threshold 40050)
2019-12-27 10:49:58.686 CST [5923] DEBUG:  autovac_balance_cost(pid=5923 db=16384, rel=16385, dobalance=yes cost_limit=200, cost_limit_base=200, cost_delay=2)
2019-12-27 10:49:58.686 CST [5923] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:58.686 CST [5923] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:58.686 CST [5923] DEBUG:  vacuuming "public.tbl"
2019-12-27 10:49:59.087 CST [5923] DEBUG:  "tbl": removed 500002 row versions in 2216 pages
2019-12-27 10:49:59.087 CST [5923] DEBUG:  "tbl": found 500002 removable, 500002 nonremovable row versions in 4425 out of 4425 pages
2019-12-27 10:49:59.087 CST [5923] DETAIL:  0 dead row versions cannot be removed yet, oldest xmin: 505
  There were 168 unused item identifiers.
  Skipped 0 pages due to buffer pins, 0 frozen pages.
  0 pages are entirely empty.
  CPU: user: 0.22 s, system: 0.00 s, elapsed: 0.40 s.
2019-12-27 10:49:59.087 CST [5923] LOG:  automatic vacuum of table "testdb.public.tbl": index scans: 0
  pages: 0 removed, 4425 remain, 0 skipped due to pins, 0 skipped frozen
  tuples: 500002 removed, 500002 remain, 0 are dead but not yet removable, oldest xmin: 505
  buffer usage: 8877 hits, 0 misses, 1 dirtied
  avg read rate: 0.000 MB/s, avg write rate: 0.019 MB/s
  system usage: CPU: user: 0.22 s, system: 0.00 s, elapsed: 0.40 s
2019-12-27 10:49:59.087 CST [5923] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 (used)
2019-12-27 10:49:59.087 CST [5923] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:59.087 CST [5923] DEBUG:  analyzing "public.tbl"
2019-12-27 10:49:59.250 CST [5923] DEBUG:  "tbl": scanned 4425 of 4425 pages, containing 500002 live rows and 0 dead rows; 30000 rows in sample, 500002 estimated total rows
2019-12-27 10:49:59.258 CST [5923] LOG:  automatic analyze of table "testdb.public.tbl" system usage: CPU: user: 0.08 s, system: 0.01 s, elapsed: 0.17 s
2019-12-27 10:49:59.260 CST [5923] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 505/1/0 (used)
2019-12-27 10:49:59.265 CST [5923] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:59.265 CST [5923] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:49:59.265 CST [5923] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
2019-12-27 10:49:59.265 CST [5923] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make
2019-12-27 10:49:59.265 CST [5923] DEBUG:  proc_exit(0): 2 callbacks to make
2019-12-27 10:49:59.265 CST [5923] DEBUG:  exit(0)
2019-12-27 10:49:59.265 CST [5923] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2019-12-27 10:49:59.265 CST [5923] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2019-12-27 10:49:59.265 CST [5923] DEBUG:  proc_exit(-1): 0 callbacks to make
2019-12-27 10:49:59.267 CST [5747] DEBUG:  reaping dead processes
2019-12-27 10:49:59.267 CST [5747] DEBUG:  server process (PID 5923) exited with exit code 0
2019-12-27 10:50:07.762 CST [5751] DEBUG:  snapshot of 0+0 running transaction ids (lsn 0/F1DA880 oldest xid 506 latest complete 505 next xid 506)

```
我們把語句放在事務中執行：
```
[local:/var/run/test]:5000 test@testdb=# begin;
BEGIN
[local:/var/run/test]:5000 test@testdb=#* insert into tbl(id) select generate_series(1,100000);
INSERT 0 100000
[local:/var/run/test]:5000 test@testdb=#* update tbl set id = 4;
UPDATE 600002
[local:/var/run/test]:5000 test@testdb=#* update tbl set id = 5;
UPDATE 600002
[local:/var/run/test]:5000 test@testdb=#* end;
COMMIT
[local:/var/run/test]:5000 test@testdb=#

```
日誌輸出：
```
2019-12-27 10:53:36.847 CST [5763] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
RELOPTINFO (*SELECT*): rows=100000 width=4
  path list:
  SubqueryScan(*SELECT*) rows=100000 cost=0.00..1500.02

cheapest parameterized paths:
  SubqueryScan(*SELECT*) rows=100000 cost=0.00..1500.02

cheapest startup path:
  SubqueryScan(*SELECT*) rows=100000 cost=0.00..1500.02

cheapest total path:
  SubqueryScan(*SELECT*) rows=100000 cost=0.00..1500.02

2019-12-27 10:53:52.369 CST [5751] DEBUG:  snapshot of 1+0 running transaction ids (lsn 0/F8619B0 oldest xid 506 latest complete 505 next xid 507)
RELOPTINFO (tbl): rows=500002 width=44
  path list:
  SeqScan(tbl) rows=500002 cost=0.00..9425.02

cheapest parameterized paths:
  SeqScan(tbl) rows=500002 cost=0.00..9425.02

cheapest startup path:
  SeqScan(tbl) rows=500002 cost=0.00..9425.02

cheapest total path:
  SeqScan(tbl) rows=500002 cost=0.00..9425.02

2019-12-27 10:53:55.368 CST [5763] DEBUG:  creating and filling new WAL file
2019-12-27 10:53:55.414 CST [5763] DEBUG:  done creating and filling new WAL file
2019-12-27 10:53:55.901 CST [5763] DEBUG:  creating and filling new WAL file
2019-12-27 10:53:55.946 CST [5763] DEBUG:  done creating and filling new WAL file
2019-12-27 10:53:56.398 CST [5763] DEBUG:  creating and filling new WAL file
2019-12-27 10:53:56.436 CST [5763] DEBUG:  done creating and filling new WAL file
2019-12-27 10:53:56.891 CST [5763] DEBUG:  creating and filling new WAL file
2019-12-27 10:53:56.945 CST [5763] DEBUG:  done creating and filling new WAL file
2019-12-27 10:53:57.410 CST [5763] DEBUG:  creating and filling new WAL file
2019-12-27 10:53:57.501 CST [5763] DEBUG:  done creating and filling new WAL file
2019-12-27 10:53:58.128 CST [5763] DEBUG:  creating and filling new WAL file
2019-12-27 10:53:58.486 CST [5763] DEBUG:  done creating and filling new WAL file
2019-12-27 10:53:58.854 CST [5753] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:53:58.854 CST [5753] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:53:58.855 CST [5754] DEBUG:  received inquiry for database 0
2019-12-27 10:53:58.855 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-12-27 10:53:58.855 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-12-27 10:53:58.869 CST [6146] DEBUG:  InitPostgres
2019-12-27 10:53:58.869 CST [6146] DEBUG:  my backend ID is 4
2019-12-27 10:53:58.874 CST [6146] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:53:58.882 CST [6146] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:53:58.882 CST [6146] DEBUG:  autovacuum: processing database "testdb"
2019-12-27 10:53:58.883 CST [5754] DEBUG:  received inquiry for database 16384
2019-12-27 10:53:58.883 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-12-27 10:53:58.883 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_16384.stat"
2019-12-27 10:53:58.883 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-12-27 10:53:58.895 CST [6146] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:53:58.896 CST [6146] DEBUG:  tbl: vac: 0 (threshold 100050), anl: 0 (threshold 50050)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_statistic: vac: 8 (threshold 134), anl: 10 (threshold 92)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_type: vac: 0 (threshold 131), anl: 2 (threshold 91)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_authid: vac: 0 (threshold 52), anl: 0 (threshold 51)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_attribute: vac: 0 (threshold 633), anl: 8 (threshold 341)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_proc: vac: 0 (threshold 642), anl: 0 (threshold 346)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_class: vac: 0 (threshold 129), anl: 1 (threshold 90)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_index: vac: 0 (threshold 82), anl: 0 (threshold 66)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_operator: vac: 0 (threshold 204), anl: 0 (threshold 127)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_opclass: vac: 0 (threshold 76), anl: 0 (threshold 63)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_amop: vac: 0 (threshold 193), anl: 0 (threshold 122)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_amproc: vac: 0 (threshold 139), anl: 0 (threshold 95)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_rewrite: vac: 0 (threshold 75), anl: 0 (threshold 63)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_cast: vac: 0 (threshold 93), anl: 0 (threshold 72)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_namespace: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_depend: vac: 0 (threshold 1570), anl: 3 (threshold 810)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_tablespace: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_shdepend: vac: 0 (threshold 52), anl: 0 (threshold 51)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_ts_config: vac: 0 (threshold 54), anl: 0 (threshold 52)
2019-12-27 10:53:58.896 CST [6146] DEBUG:  pg_publication: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-12-27 10:53:58.897 CST [6146] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:53:58.897 CST [6146] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
2019-12-27 10:53:58.897 CST [6146] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make
2019-12-27 10:53:58.897 CST [6146] DEBUG:  proc_exit(0): 2 callbacks to make
2019-12-27 10:53:58.897 CST [6146] DEBUG:  exit(0)
2019-12-27 10:53:58.897 CST [6146] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2019-12-27 10:53:58.897 CST [6146] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2019-12-27 10:53:58.897 CST [6146] DEBUG:  proc_exit(-1): 0 callbacks to make
2019-12-27 10:53:58.903 CST [5747] DEBUG:  reaping dead processes
2019-12-27 10:53:58.903 CST [5747] DEBUG:  server process (PID 6146) exited with exit code 0
2019-12-27 10:54:09.502 CST [5751] DEBUG:  snapshot of 1+0 running transaction ids (lsn 0/15954428 oldest xid 506 latest complete 505 next xid 507)
2019-12-27 10:54:28.097 CST [5750] DEBUG:  snapshot of 1+0 running transaction ids (lsn 0/15954460 oldest xid 506 latest complete 505 next xid 507)
2019-12-27 10:54:28.098 CST [5750] DEBUG:  attempting to remove WAL segments older than log file 00000000000000000000000E
2019-12-27 10:54:28.098 CST [5750] DEBUG:  recycled write-ahead log file "000000010000000000000009"
2019-12-27 10:54:28.098 CST [5750] DEBUG:  recycled write-ahead log file "00000001000000000000000A"
2019-12-27 10:54:28.099 CST [5750] DEBUG:  recycled write-ahead log file "00000001000000000000000B"
2019-12-27 10:54:28.099 CST [5750] DEBUG:  recycled write-ahead log file "00000001000000000000000C"
2019-12-27 10:54:28.099 CST [5750] DEBUG:  removing write-ahead log file "00000001000000000000000D"
2019-12-27 10:54:28.103 CST [5750] DEBUG:  removing write-ahead log file "00000001000000000000000E"
2019-12-27 10:54:28.108 CST [5750] DEBUG:  SlruScanDirectory invoking callback on pg_subtrans/0000
2019-12-27 10:54:29.922 CST [5751] DEBUG:  snapshot of 1+0 running transaction ids (lsn 0/15954510 oldest xid 506 latest complete 505 next xid 507)
RELOPTINFO (tbl): rows=600115 width=44
  path list:
  SeqScan(tbl) rows=600115 cost=0.00..11312.15

cheapest parameterized paths:
  SeqScan(tbl) rows=600115 cost=0.00..11312.15

cheapest startup path:
  SeqScan(tbl) rows=600115 cost=0.00..11312.15

cheapest total path:
  SeqScan(tbl) rows=600115 cost=0.00..11312.15

2019-12-27 10:54:35.594 CST [5763] DEBUG:  creating and filling new WAL file
2019-12-27 10:54:35.638 CST [5763] DEBUG:  done creating and filling new WAL file
2019-12-27 10:54:46.496 CST [5751] DEBUG:  snapshot of 1+0 running transaction ids (lsn 0/1A760D38 oldest xid 506 latest complete 505 next xid 507)
2019-12-27 10:54:49.705 CST [5763] DEBUG:  CommitTransaction(1) name: unnamed; blockState: END; state: INPROGRESS, xid/subid/cid: 506/1/3
2019-12-27 10:54:58.913 CST [5753] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:54:58.913 CST [5753] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:54:58.913 CST [5754] DEBUG:  received inquiry for database 0
2019-12-27 10:54:58.913 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-12-27 10:54:58.914 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-12-27 10:54:58.926 CST [6200] DEBUG:  InitPostgres
2019-12-27 10:54:58.926 CST [6200] DEBUG:  my backend ID is 4
2019-12-27 10:54:58.930 CST [6200] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:54:58.938 CST [6200] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:54:58.938 CST [6200] DEBUG:  autovacuum: processing database "testdb"
2019-12-27 10:54:58.939 CST [5754] DEBUG:  received inquiry for database 16384
2019-12-27 10:54:58.939 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-12-27 10:54:58.939 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_16384.stat"
2019-12-27 10:54:58.939 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-12-27 10:54:58.950 CST [6200] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:54:58.951 CST [6200] DEBUG:  tbl: vac: 1200004 (threshold 100050), anl: 1300004 (threshold 50050)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_statistic: vac: 8 (threshold 134), anl: 10 (threshold 92)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_type: vac: 0 (threshold 131), anl: 2 (threshold 91)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_authid: vac: 0 (threshold 52), anl: 0 (threshold 51)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_attribute: vac: 0 (threshold 633), anl: 8 (threshold 341)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_proc: vac: 0 (threshold 642), anl: 0 (threshold 346)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_class: vac: 0 (threshold 129), anl: 1 (threshold 90)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_index: vac: 0 (threshold 82), anl: 0 (threshold 66)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_operator: vac: 0 (threshold 204), anl: 0 (threshold 127)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_opclass: vac: 0 (threshold 76), anl: 0 (threshold 63)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_amop: vac: 0 (threshold 193), anl: 0 (threshold 122)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_amproc: vac: 0 (threshold 139), anl: 0 (threshold 95)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_rewrite: vac: 0 (threshold 75), anl: 0 (threshold 63)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_cast: vac: 0 (threshold 93), anl: 0 (threshold 72)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_namespace: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_depend: vac: 0 (threshold 1570), anl: 3 (threshold 810)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_tablespace: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_shdepend: vac: 0 (threshold 52), anl: 0 (threshold 51)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_ts_config: vac: 0 (threshold 54), anl: 0 (threshold 52)
2019-12-27 10:54:58.951 CST [6200] DEBUG:  pg_publication: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-12-27 10:54:58.951 CST [5754] DEBUG:  received inquiry for database 16384
2019-12-27 10:54:58.951 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-12-27 10:54:58.951 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_16384.stat"
2019-12-27 10:54:58.951 CST [5754] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-12-27 10:54:58.962 CST [6200] DEBUG:  tbl: vac: 1200004 (threshold 100050), anl: 1300004 (threshold 50050)
2019-12-27 10:54:58.962 CST [6200] DEBUG:  autovac_balance_cost(pid=6200 db=16384, rel=16385, dobalance=yes cost_limit=200, cost_limit_base=200, cost_delay=2)
2019-12-27 10:54:58.962 CST [6200] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:54:58.962 CST [6200] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:54:58.962 CST [6200] DEBUG:  vacuuming "public.tbl"
2019-12-27 10:55:00.192 CST [6200] DEBUG:  "tbl": removed 1200004 row versions in 5311 pages
2019-12-27 10:55:00.192 CST [6200] DEBUG:  "tbl": found 1200004 removable, 600002 nonremovable row versions in 7965 out of 7965 pages
2019-12-27 10:55:00.192 CST [6200] DETAIL:  0 dead row versions cannot be removed yet, oldest xmin: 507
  There were 420 unused item identifiers.
  Skipped 0 pages due to buffer pins, 0 frozen pages.
  0 pages are entirely empty.
  CPU: user: 0.64 s, system: 0.02 s, elapsed: 1.23 s.
2019-12-27 10:55:00.192 CST [6200] LOG:  automatic vacuum of table "testdb.public.tbl": index scans: 0
  pages: 0 removed, 7965 remain, 0 skipped due to pins, 0 skipped frozen
  tuples: 1200004 removed, 600002 remain, 0 are dead but not yet removable, oldest xmin: 507
  buffer usage: 15957 hits, 0 misses, 890 dirtied
  avg read rate: 0.000 MB/s, avg write rate: 5.651 MB/s
  system usage: CPU: user: 0.64 s, system: 0.02 s, elapsed: 1.23 s
2019-12-27 10:55:00.192 CST [6200] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 (used)
2019-12-27 10:55:00.193 CST [6200] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:55:00.193 CST [6200] DEBUG:  analyzing "public.tbl"
2019-12-27 10:55:00.511 CST [6200] DEBUG:  "tbl": scanned 7965 of 7965 pages, containing 600002 live rows and 0 dead rows; 30000 rows in sample, 600002 estimated total rows
2019-12-27 10:55:00.525 CST [6200] LOG:  automatic analyze of table "testdb.public.tbl" system usage: CPU: user: 0.11 s, system: 0.06 s, elapsed: 0.33 s
2019-12-27 10:55:00.526 CST [6200] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 507/1/0 (used)
2019-12-27 10:55:00.526 CST [6200] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:55:00.526 CST [6200] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2019-12-27 10:55:00.526 CST [6200] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
2019-12-27 10:55:00.526 CST [6200] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make
2019-12-27 10:55:00.526 CST [6200] DEBUG:  proc_exit(0): 2 callbacks to make
2019-12-27 10:55:00.526 CST [6200] DEBUG:  exit(0)
2019-12-27 10:55:00.527 CST [6200] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2019-12-27 10:55:00.527 CST [6200] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2019-12-27 10:55:00.527 CST [6200] DEBUG:  proc_exit(-1): 0 callbacks to make
2019-12-27 10:55:00.531 CST [5747] DEBUG:  reaping dead processes
2019-12-27 10:55:00.531 CST [5747] DEBUG:  server process (PID 6200) exited with exit code 0
2019-12-27 10:55:06.901 CST [5751] DEBUG:  snapshot of 0+0 running transaction ids (lsn 0/1AD14BB0 oldest xid 508 latest complete 507 next xid 508)

```
對核心實現感興趣的，可以仔細研究下：）
其他級別的Level：
>INFO – as far as I can tell PostgreSQL itself uses it only in some cases with notify/listen
NOTICE – well, this are used for example when you create a table, with PRIMARY KEY, and it notifies you about index creation for the table
WARNING – all kinds of warnings, the most common one is about using escapes (\ character) in strings
ERROR – all cases which cause Pg to break transaction. Deadlocks, bad values, constraint violations and so on
LOG – used to log information about special event (checkpoint, connections)
FATAL – errors which cause Pg session that caused it to abort. For example – bad password given when authenticating
PANIC – errors which cause all Pg sessions to be aborted. You don't want this.

**log_min_error_statement**
可選項從低到高包括：
debug5
debug4
debug3
debug2
debug1
info
notice
warning
error
log
fatal
panic
預設值為error。
下面我們設定該值為debug5
```
[test@localhost tmpdb]$ pg_ctl restart
waiting for server to shut down.... done
server stopped
waiting for server to start....2019-12-27 11:51:01.267 CST [9410] LOG:  starting PostgreSQL 12.1 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-16), 64-bit
2019-12-27 11:51:01.268 CST [9410] LOG:  listening on IPv6 address "::1", port 5000
2019-12-27 11:51:01.268 CST [9410] LOG:  listening on IPv4 address "127.0.0.1", port 5000
2019-12-27 11:51:01.272 CST [9410] LOG:  listening on Unix socket "/var/run/test/.s.PGSQL.5000"
2019-12-27 11:51:01.286 CST [9410] LOG:  redirecting log output to logging collector process
2019-12-27 11:51:01.286 CST [9410] HINT:  Future log output will appear in directory "log".
 done
server started
[test@localhost tmpdb]$ grep 'log_min_error' postgresql.conf 
log_min_error_statement = debug5  # values in order of decreasing detail:
[test@localhost tmpdb]$

```
執行常規的SQL和出錯的SQL
```
###SQL
[local:/var/run/test]:5000 test@testdb=# select * from ttt;
ERROR:  relation "ttt" does not exist
LINE 1: select * from ttt;
                      ^
[local:/var/run/test]:5000 test@testdb=# select 1/0;
ERROR:  division by zero
[local:/var/run/test]:5000 test@testdb=#

###日誌輸出
2019-12-27 11:52:19.052 CST [9430] ERROR:  relation "ttt" does not exist at character 15
2019-12-27 11:52:19.052 CST [9430] STATEMENT:  select * from ttt;
2019-12-27 11:52:34.043 CST [9430] ERROR:  division by zero
2019-12-27 11:52:34.043 CST [9430] STATEMENT:  select 1/0;
```
調整為panic，執行SQL
```
[test@localhost tmpdb]$ pg_ctl restart
waiting for server to shut down.... done
server stopped
...
[test@localhost tmpdb]$ grep 'log_min_error' postgresql.conf 
log_min_error_statement = panic   # values in order of decreasing detail:
[test@localhost tmpdb]$ 
###
[local:/var/run/test]:5000 test@testdb=# select * from ttt;
ERROR:  relation "ttt" does not exist
LINE 1: select * from ttt;
                      ^
[local:/var/run/test]:5000 test@testdb=# select 1/0;
ERROR:  division by zero
[local:/var/run/test]:5000 test@testdb=#

###
2019-12-27 12:03:49.939 CST [10151] ERROR:  relation "ttt" does not exist at character 15
2019-12-27 12:03:54.470 CST [10151] ERROR:  division by zero

```
日誌輸出只有錯誤資訊，沒有SQL語句。

**log_min_duration_statement**
整型，單位為ms毫秒。SQL執行時長超過此設定的，將記錄在日誌中。需要注意的是，並不是超過該時長馬上記錄，而是在SQL執行結束後才會記錄。
```
[test@localhost tmpdb]$ grep log_min_duration_statement postgresql.conf 
log_min_duration_statement = 100  # -1 is disabled, 0 logs all statements
[test@localhost tmpdb]$ pg_ctl restart
waiting for server to shut down.... done
server stopped
waiting for server to start....2019-12-27 16:01:11.343 CST [23662] LOG:  starting PostgreSQL 12.1 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-16), 64-bit
2019-12-27 16:01:11.347 CST [23662] LOG:  listening on IPv6 address "::1", port 5000
2019-12-27 16:01:11.347 CST [23662] LOG:  listening on IPv4 address "127.0.0.1", port 5000
2019-12-27 16:01:11.358 CST [23662] LOG:  listening on Unix socket "/var/run/test/.s.PGSQL.5000"
2019-12-27 16:01:11.382 CST [23662] LOG:  redirecting log output to logging collector process
2019-12-27 16:01:11.382 CST [23662] HINT:  Future log output will appear in directory "log".
 done
server started
[test@localhost tmpdb]$

```
執行SQL：
```
[local:/var/run/test]:5000 test@testdb=# select pg_sleep(0.01);
 pg_sleep 
----------
 
(1 row)

[local:/var/run/test]:5000 test@testdb=# select pg_sleep(1);
 pg_sleep 
----------
 
(1 row)

[local:/var/run/test]:5000 test@testdb=#

```
日誌輸出（SQL執行完才會記錄在日誌中）
```
...
2019-12-27 16:02:02.066 CST [23733] LOG:  duration: 1001.115 ms  statement: select pg_sleep(1);

```

**log_transaction_sample_rate**
該引數在PG 12中引入，解釋如下：
>Log all statements from a sample of transactions
This is useful to obtain a view of the different transaction types in an
application, regardless of the durations of the statements each runs.

對按此引數設定的比例對事務進行取樣，對APP很有用。

**參考資料**
[Understanding postgresql.conf : log](https://www.depesz.com/2011/05/06/understanding-postgresql-conf-log/)
[Waiting for PostgreSQL 12 – Log all statements from a sample of transactions](https://www.depesz.com/2019/04/18/waiting-for-postgresql-12-log-all-statements-from-a-sample-of-transactions/#more-3525)

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/6906/viewspace-2670966/，如需轉載，請註明出處，否則將追究法律責任。

相關文章

PostgreSQL DBA(151) - pgAdmin（log_XXX parameter：where）
2019-12-26
SQL
PostgreSQL DBA(153) - pgAdmin（log_XXX parameter：what）
2019-12-30
SQL
PostgreSQL DBA(86) - Table Parameter(fillfactor)
2019-08-27
SQL
PostgreSQL DBA(164) - pgAdmin(Drop column)
2020-02-13
SQL
PostgreSQL DBA(160) - pgAdmin(prepare transaction)
2020-02-10
SQL
PostgreSQL DBA(170) - pgAdmin(Queries For Index Maintenance)
2020-04-07
SQLIndexAINaN
PostgreSQL DBA(173) - pgAdmin(Network latency)
2020-05-18
SQL
PostgreSQL DBA(156) - pgAdmin（Rollback setting）
2020-01-09
SQL
PostgreSQL DBA(147) - pgAdmin（Scripts for freeze）
2019-12-17
SQL
PostgreSQL DBA(132) - pgAdmin(unix_socket_directories)
2019-11-18
SQL
PostgreSQL DBA(120) - pgAdmin(HA with Patroni)
2019-11-04
SQL
PostgreSQL DBA(165) - pgAdmin(Create Function選項)
2020-02-25
SQLFunction
PostgreSQL DBA(168) - pgAdmin(config：checkpoint)
2020-03-05
SQL
PostgreSQL DBA(166) - pgAdmin(Parallelism, what next？)
2020-02-27
SQLParallel
PostgreSQL DBA(161) - pgAdmin(synchronous_commit)
2020-02-11
SQLMIT
PostgreSQL DBA(128) - pgAdmin(Load balance with HAProxy)
2019-11-14
SQL
PostgreSQL DBA(101) - pgAdmin(statement timeout)
2019-10-08
SQL
PostgreSQL DBA(102) - pgAdmin(Row Level Security)
2019-10-09
SQL
PostgreSQL DBA(104) - pgAdmin(Don't do this：Rule)
2019-10-11
SQL
PostgreSQL DBA(106) - pgAdmin(Don't do this：NOT IN)
2019-10-14
SQL
PostgreSQL DBA(143) - pgAdmin（Monitoring PostgreSQL VACUUM processes#2）
2019-12-11
SQL
PostgreSQL DBA(145) - pgAdmin（AUTOVACUUM：引數解析#3）
2019-12-12
SQL
PostgreSQL DBA(144) - pgAdmin（AUTOVACUUM：引數解析#2）
2019-12-12
SQL
PostgreSQL DBA(103) - pgAdmin(Don't do this：Encoding)
2019-10-10
SQLEncoding
PostgreSQL DBA(167) - pgAdmin(config：work_mem)
2020-03-02
SQL
PostgreSQL DBA(154) - pgAdmin（bool轉換為smallint）
2019-12-31
SQL
PostgreSQL DBA(157) - pgAdmin（OOM & max_locks_per_transaction ）
2020-01-10
SQLOOM
PostgreSQL DBA(148) - pgAdmin（Show script for psql command）
2019-12-17
SQL
PostgreSQL DBA(107) - pgAdmin(Don't do this：NOT IN vs NOT EXISTS)
2019-10-15
SQL
PostgreSQL DBA(121) - pgAdmin(HA：PAF vs repmgr vs Patroni)
2019-11-05
SQL
PostgreSQL DBA(159) - pgAdmin(Allow vacuum command to process indexes in paralle
2020-01-20
SQLIndex
PostgreSQL DBA(146) - pgAdmin（pg_dumpall vs pg_dump）
2019-12-16
SQL
PostgreSQL DBA(105) - pgAdmin(Don't do this：psql&inheritance)
2019-10-12
SQL
PostgreSQL DBA(117) - pgAdmin(Don't do this： Don't use serial)
2019-10-29
SQL
PostgreSQL DBA(119) - pgAdmin(LIMIT：Index Scan vs Bitmap Index Scan)
2019-11-01
SQLMITIndex
PostgreSQL DBA(113) - pgAdmin(Don't do this：Don't use char(n))
2019-10-23
SQL
PostgreSQL DBA(109) - pgAdmin(Don't do this：Don't use BETWEEN)
2019-10-17
SQL
PostgreSQL DBA(108) - pgAdmin(Don't do this：Don't use upper names)
2019-10-16
SQL