千家信息网

怎么使用PostgreSQL与日志相关的配置参数log_XXX

发表于:2026-11-02 作者:千家信息网编辑
千家信息网最后更新 2026年11月02日,本篇内容介绍了"怎么使用PostgreSQL与日志相关的配置参数log_XXX"的有关知识,在实际案例的操作过程中,不少人都会遇到这样的困境,接下来就让小编带领大家学习一下如何处理这些情况吧!希望大家
千家信息网最后更新 2026年11月02日怎么使用PostgreSQL与日志相关的配置参数log_XXX

本篇内容介绍了"怎么使用PostgreSQL与日志相关的配置参数log_XXX"的有关知识,在实际案例的操作过程中,不少人都会遇到这样的困境,接下来就让小编带领大家学习一下如何处理这些情况吧!希望大家仔细阅读,能够学有所成!

概览

在新initdb的数据库上查询pg_settings,可查询PostgreSQL中与log的参数包括:

[test@localhost ~]$ psqlExpanded 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.conflog_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 restartwaiting for server to shut down.... doneserver stoppedwaiting 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=122019-12-27 10:25:15.198 CST [4441] DEBUG:   HOSTNAME=localhost.localdomain2019-12-27 10:25:15.198 CST [4441] DEBUG:   TERM=xterm2019-12-27 10:25:15.198 CST [4441] DEBUG:   SHELL=/bin/bash2019-12-27 10:25:15.198 CST [4441] DEBUG:   HISTSIZE=10002019-12-27 10:25:15.198 CST [4441] DEBUG:   PG_GRANDPARENT_PID=24602019-12-27 10:25:15.198 CST [4441] DEBUG:   USER=test2019-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=50002019-12-27 10:25:15.198 CST [4441] DEBUG:   PGDATABASE=testdb2019-12-27 10:25:15.198 CST [4441] DEBUG:   LIBDIR=/appdb/pg12/pg12.1/share/postgresql/extension2019-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/bin2019-12-27 10:25:15.198 CST [4441] DEBUG:   MAIL=/var/spool/mail/test2019-12-27 10:25:15.198 CST [4441] DEBUG:   _=/appdb/pg12/pg12.1/bin/pg_ctl2019-12-27 10:25:15.198 CST [4441] DEBUG:   PWD=/home/test2019-12-27 10:25:15.198 CST [4441] DEBUG:   LANG=en_US.UTF-82019-12-27 10:25:15.198 CST [4441] DEBUG:   PGHOST=/var/run/test2019-12-27 10:25:15.198 CST [4441] DEBUG:   PGSYSCONFDIR=/appdb/pg12/pg12.1/etc/postgresql2019-12-27 10:25:15.198 CST [4441] DEBUG:   HISTCONTROL=ignoredups2019-12-27 10:25:15.198 CST [4441] DEBUG:   HOME=/home/test2019-12-27 10:25:15.198 CST [4441] DEBUG:   SHLVL=12019-12-27 10:25:15.198 CST [4441] DEBUG:   LOGNAME=test2019-12-27 10:25:15.198 CST [4441] DEBUG:   LESSOPEN=||/usr/bin/lesspipe.sh %s2019-12-27 10:25:15.198 CST [4441] DEBUG:   PGDATA=/data/pgsql/tmpdb2019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_COLLATE=en_US.UTF-82019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_CTYPE=en_US.UTF-82019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_MESSAGES=en_US.UTF-82019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_MONETARY=C2019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_NUMERIC=C2019-12-27 10:25:15.198 CST [4441] DEBUG:   LC_TIME=C2019-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-bit2019-12-27 10:25:15.202 CST [4441] LOG:  listening on IPv6 address "::1", port 50002019-12-27 10:25:15.202 CST [4441] LOG:  listening on IPv4 address "127.0.0.1", port 50002019-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 memory2019-12-27 10:25:15.218 CST [4441] DEBUG:  SlruScanDirectory invoking callback on pg_notify/00002019-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 segments2019-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 = 72019-12-27 10:25:15.219 CST [4441] LOG:  redirecting log output to logging collector process2019-12-27 10:25:15.219 CST [4441] HINT:  Future log output will appear in directory "log". doneserver 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/0RELOPTINFO (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.022019-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:  InitPostgres2019-12-27 10:47:24.854 CST [5783] DEBUG:  my backend ID is 42019-12-27 10:47:24.854 CST [5784] DEBUG:  InitPostgres2019-12-27 10:47:24.854 CST [5784] DEBUG:  my backend ID is 52019-12-27 10:47:24.854 CST [5783] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:47:24.854 CST [5784] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:47:24.878 CST [5783] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:47:24.878 CST [5783] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:47:24.879 CST [5784] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:47:24.879 CST [5784] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:47:24.913 CST [5783] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:47:24.913 CST [5783] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:47:24.914 CST [5784] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:47:24.914 CST [5784] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:47:24.945 CST [5784] DEBUG:  CommitTransaction(1) name: unnamed; blockState: PARALLEL_INPROGRESS; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:47:24.945 CST [5784] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make2019-12-27 10:47:24.945 CST [5784] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make2019-12-27 10:47:24.945 CST [5784] DEBUG:  proc_exit(0): 2 callbacks to make2019-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/02019-12-27 10:47:24.945 CST [5784] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make2019-12-27 10:47:24.945 CST [5784] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make2019-12-27 10:47:24.945 CST [5784] DEBUG:  proc_exit(-1): 0 callbacks to make2019-12-27 10:47:24.945 CST [5783] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make2019-12-27 10:47:24.945 CST [5783] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make2019-12-27 10:47:24.945 CST [5783] DEBUG:  proc_exit(0): 2 callbacks to make2019-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 make2019-12-27 10:47:24.945 CST [5783] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make2019-12-27 10:47:24.945 CST [5783] DEBUG:  proc_exit(-1): 0 callbacks to make2019-12-27 10:47:24.946 CST [5747] DEBUG:  reaping dead processes2019-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 02019-12-27 10:47:24.947 CST [5747] DEBUG:  reaping dead processes2019-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 02019-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/0RELOPTINFO (*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.022019-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/0RELOPTINFO (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.022019-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/02019-12-27 10:49:58.619 CST [5755] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:49:58.649 CST [5753] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:49:58.649 CST [5753] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:49:58.649 CST [5754] DEBUG:  received inquiry for database 02019-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:  InitPostgres2019-12-27 10:49:58.662 CST [5923] DEBUG:  my backend ID is 42019-12-27 10:49:58.662 CST [5923] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:49:58.663 CST [5923] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-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 163842019-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/02019-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 163842019-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/02019-12-27 10:49:58.686 CST [5923] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-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 pages2019-12-27 10:49:59.087 CST [5923] DEBUG:  "tbl": found 500002 removable, 500002 nonremovable row versions in 4425 out of 4425 pages2019-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 s2019-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/02019-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 rows2019-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 s2019-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/02019-12-27 10:49:59.265 CST [5923] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:49:59.265 CST [5923] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make2019-12-27 10:49:59.265 CST [5923] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make2019-12-27 10:49:59.265 CST [5923] DEBUG:  proc_exit(0): 2 callbacks to make2019-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 make2019-12-27 10:49:59.265 CST [5923] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make2019-12-27 10:49:59.265 CST [5923] DEBUG:  proc_exit(-1): 0 callbacks to make2019-12-27 10:49:59.267 CST [5747] DEBUG:  reaping dead processes2019-12-27 10:49:59.267 CST [5747] DEBUG:  server process (PID 5923) exited with exit code 02019-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/0RELOPTINFO (*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.022019-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.022019-12-27 10:53:55.368 CST [5763] DEBUG:  creating and filling new WAL file2019-12-27 10:53:55.414 CST [5763] DEBUG:  done creating and filling new WAL file2019-12-27 10:53:55.901 CST [5763] DEBUG:  creating and filling new WAL file2019-12-27 10:53:55.946 CST [5763] DEBUG:  done creating and filling new WAL file2019-12-27 10:53:56.398 CST [5763] DEBUG:  creating and filling new WAL file2019-12-27 10:53:56.436 CST [5763] DEBUG:  done creating and filling new WAL file2019-12-27 10:53:56.891 CST [5763] DEBUG:  creating and filling new WAL file2019-12-27 10:53:56.945 CST [5763] DEBUG:  done creating and filling new WAL file2019-12-27 10:53:57.410 CST [5763] DEBUG:  creating and filling new WAL file2019-12-27 10:53:57.501 CST [5763] DEBUG:  done creating and filling new WAL file2019-12-27 10:53:58.128 CST [5763] DEBUG:  creating and filling new WAL file2019-12-27 10:53:58.486 CST [5763] DEBUG:  done creating and filling new WAL file2019-12-27 10:53:58.854 CST [5753] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:53:58.854 CST [5753] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:53:58.855 CST [5754] DEBUG:  received inquiry for database 02019-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:  InitPostgres2019-12-27 10:53:58.869 CST [6146] DEBUG:  my backend ID is 42019-12-27 10:53:58.874 CST [6146] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:53:58.882 CST [6146] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-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 163842019-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/02019-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/02019-12-27 10:53:58.897 CST [6146] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make2019-12-27 10:53:58.897 CST [6146] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make2019-12-27 10:53:58.897 CST [6146] DEBUG:  proc_exit(0): 2 callbacks to make2019-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 make2019-12-27 10:53:58.897 CST [6146] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make2019-12-27 10:53:58.897 CST [6146] DEBUG:  proc_exit(-1): 0 callbacks to make2019-12-27 10:53:58.903 CST [5747] DEBUG:  reaping dead processes2019-12-27 10:53:58.903 CST [5747] DEBUG:  server process (PID 6146) exited with exit code 02019-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 00000000000000000000000E2019-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/00002019-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.152019-12-27 10:54:35.594 CST [5763] DEBUG:  creating and filling new WAL file2019-12-27 10:54:35.638 CST [5763] DEBUG:  done creating and filling new WAL file2019-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/32019-12-27 10:54:58.913 CST [5753] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:54:58.913 CST [5753] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:54:58.913 CST [5754] DEBUG:  received inquiry for database 02019-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:  InitPostgres2019-12-27 10:54:58.926 CST [6200] DEBUG:  my backend ID is 42019-12-27 10:54:58.930 CST [6200] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:54:58.938 CST [6200] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-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 163842019-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/02019-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 163842019-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/02019-12-27 10:54:58.962 CST [6200] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/02019-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 pages2019-12-27 10:55:00.192 CST [6200] DEBUG:  "tbl": found 1200004 removable, 600002 nonremovable row versions in 7965 out of 7965 pages2019-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 s2019-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/02019-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 rows2019-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 s2019-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/02019-12-27 10:55:00.526 CST [6200] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/02019-12-27 10:55:00.526 CST [6200] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make2019-12-27 10:55:00.526 CST [6200] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make2019-12-27 10:55:00.526 CST [6200] DEBUG:  proc_exit(0): 2 callbacks to make2019-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 make2019-12-27 10:55:00.527 CST [6200] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make2019-12-27 10:55:00.527 CST [6200] DEBUG:  proc_exit(-1): 0 callbacks to make2019-12-27 10:55:00.531 CST [5747] DEBUG:  reaping dead processes2019-12-27 10:55:00.531 CST [5747] DEBUG:  server process (PID 6200) exited with exit code 02019-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 restartwaiting for server to shut down.... doneserver stoppedwaiting 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-bit2019-12-27 11:51:01.268 CST [9410] LOG:  listening on IPv6 address "::1", port 50002019-12-27 11:51:01.268 CST [9410] LOG:  listening on IPv4 address "127.0.0.1", port 50002019-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 process2019-12-27 11:51:01.286 CST [9410] HINT:  Future log output will appear in directory "log". doneserver 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 existLINE 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 152019-12-27 11:52:19.052 CST [9430] STATEMENT:  select * from ttt;2019-12-27 11:52:34.043 CST [9430] ERROR:  division by zero2019-12-27 11:52:34.043 CST [9430] STATEMENT:  select 1/0;

调整为panic,执行SQL

[test@localhost tmpdb]$ pg_ctl restartwaiting for server to shut down.... doneserver 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 existLINE 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 152019-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 restartwaiting for server to shut down.... doneserver stoppedwaiting 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-bit2019-12-27 16:01:11.347 CST [23662] LOG:  listening on IPv6 address "::1", port 50002019-12-27 16:01:11.347 CST [23662] LOG:  listening on IPv4 address "127.0.0.1", port 50002019-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 process2019-12-27 16:01:11.382 CST [23662] HINT:  Future log output will appear in directory "log". doneserver 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"的内容就介绍到这里了,感谢大家的阅读。如果想了解更多行业相关的知识可以关注网站,小编将为大家输出更多高质量的实用文章!

日志 输出 参数 级别 配置 事务 内容 只有 数据 数据库 时长 更多 知识 语句 查询 实用 学有所成 接下来 信息 兴趣 数据库的安全要保护哪些东西 数据库安全各自的含义是什么 生产安全数据库录入 数据库的安全性及管理 数据库安全策略包含哪些 海淀数据库安全审计系统 建立农村房屋安全信息数据库 易用的数据库客户端支持安全管理 连接数据库失败ssl安全错误 数据库的锁怎样保障安全 互联网高科技 科技互联网项目 厦门中拓互联网络科技有限公司 互联网科技战争 互联网科技的 互联网科技与金融科技 友谊互联网络科技 国外互联网科技网站 互联网汽车科技小镇 广州慧亚互联网科技怎么样 欧洲十大科技互联网公司 互联网科技圈年度人物 每天都有哪些好的互联网科技 梅州GM互联网络科技有限公司 吉林省码上互联网科技电话 艺电能源互联网科技有限公司招聘 北京品多多互联网科技有限公司 银川新华互联网科技学校招聘 高科技和互联网的现代国家 前海云享互联网科技 百单网互联网科技有限公司 卓越科技互联网 招聘 互联网科技与大数据专业 浙南科技城互联网大厦建设工程 朱啸虎曾投资哪些互联网科技企业 伊宁互联网科技做什么的 萌小萌互联网科技河南有限公司 科技信息时代互联网发展 互联网科技创新创业项目 长沙易易互联网科技有限公司
0