本篇内容介绍了“怎么使用PostgreSQL与日志相关的配置参数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很有用。
“怎么使用PostgreSQL与日志相关的配置参数log_XXX”的内容就介绍到这里了，感谢大家的阅读。如果想了解更多行业相关的知识可以关注亿速云网站，小编将为大家输出更多高质量的实用文章！
