linux pgadmin备份数据库指令,PostgreSQL DBA(152) - pgAdmin（log_XXX parameter：when）

最新推荐文章于 2022-07-30 15:06:33 发布

老怪看盘

最新推荐文章于 2022-07-30 15:06:33 发布

阅读量374

点赞数

文章标签： linux pgadmin备份数据库指令

本节介绍了与日志相关的配置参数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: 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)

老怪看盘

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
linux pgadmin备份数据库指令,PostgreSQL DBA(152) - pgAdmin（log_XXX parameter：when）

本节介绍了与日志相关的配置参数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]:...
复制链接

扫一扫