Re: autovacuum excesivo PostgreSQL 9.5

Hola Alvaro

No se si se me cruzaron las terminales!! reenvio todas las consultas y/o
pantallas para verificar y si el es caso mil disculpas:

El servidor, por mantenimiento de la virtualizacion, se le realizo un
reinicio anoche (hacia las 9 pm), pero apenas inicio nuevamente las tablas
en mención iniciaron autovacuum a pesar de estar en horas no laborales...

control data:

[postgres(at)MDB ~]# pg_controldata -D /PostgreSQL/9.5/data
pg_control version number: 942
Catalog version number: 201510051
Database system identifier: 6315449280875279671
Database cluster state: in production
pg_control last modified: Tue 04 Oct 2016 07:58:16 AM COT
Latest checkpoint location: 9/35E20BE8
Prior checkpoint location: 9/3460DF20
Latest checkpoint's REDO location: 9/35D87A50
Latest checkpoint's REDO WAL file: 000000010000000900000035
Latest checkpoint's TimeLineID: 1
Latest checkpoint's PrevTimeLineID: 1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID: 0/8406787
Latest checkpoint's NextOID: 184033
Latest checkpoint's NextMultiXactId: 12442
Latest checkpoint's NextMultiOffset: 25635
Latest checkpoint's oldestXID: 1741
Latest checkpoint's oldestXID's DB: 13236
Latest checkpoint's oldestActiveXID: 8406787
Latest checkpoint's oldestMultiXid: 1
Latest checkpoint's oldestMulti's DB: 13236
Latest checkpoint's oldestCommitTsXid:0
Latest checkpoint's newestCommitTsXid:0
Time of latest checkpoint: Tue 04 Oct 2016 07:58:02 AM COT
Fake LSN counter for unlogged rels: 0/1
Minimum recovery ending location: 0/0
Min recovery ending loc's timeline: 0
Backup start location: 0/0
Backup end location: 0/0
End-of-backup record required: no
wal_level setting: hot_standby
wal_log_hints setting: off
max_connections setting: 230
max_worker_processes setting: 8
max_prepared_xacts setting: 0
max_locks_per_xact setting: 64
track_commit_timestamp setting: off
Maximum data alignment: 8
Database block size: 8192
Blocks per segment of large relation: 131072
WAL block size: 8192
Bytes per WAL segment: 16777216
Maximum length of identifiers: 64
Maximum columns in an index: 32
Maximum size of a TOAST chunk: 1996
Size of a large-object chunk: 2048
Date/time type storage: 64-bit integers
Float4 argument passing: by value
Float8 argument passing: by value
Data page checksum version: 1

bd=# select * from pg_stat_user_tables where relname in ('marcador',
'usuario');
-[ RECORD 1 ]-------+------------------------------
relid | 44940
schemaname | sac
relname | usuario
seq_scan | 119
seq_tup_read | 404413
idx_scan | 97053
idx_tup_fetch | 83670
n_tup_ins | 0
n_tup_upd | 529
n_tup_del | 0
n_tup_hot_upd | 493
n_live_tup | 296
n_dead_tup | 53806
n_mod_since_analyze | 523
last_vacuum | 2016-10-04 00:12:05.059494-05
last_autovacuum | 2016-10-04 08:03:00.81192-05
last_analyze | 2016-10-04 00:12:25.596793-05
last_autoanalyze |
vacuum_count | 1
autovacuum_count | 376
analyze_count | 2
autoanalyze_count | 0
-[ RECORD 2 ]-------+------------------------------
relid | 44165
schemaname | sac
relname | marcador
seq_scan | 12
seq_tup_read | 21272907
idx_scan | 15787
idx_tup_fetch | 48832353
n_tup_ins | 6504
n_tup_upd | 6237
n_tup_del | 0
n_tup_hot_upd | 4866
n_live_tup | 1497958
n_dead_tup | 1099897
n_mod_since_analyze | 12741
last_vacuum | 2016-10-04 00:12:03.261379-05
last_autovacuum | 2016-10-04 07:58:16.192087-05
last_analyze | 2016-10-04 00:12:49.75513-05
last_autoanalyze |
vacuum_count | 1
autovacuum_count | 73
analyze_count | 2
autoanalyze_count | 0

--configuracion autovacuum

autovacuum;on
autovacuum_analyze_scale_factor;0.05
autovacuum_analyze_threshold;40
autovacuum_freeze_max_age;200000000
autovacuum_max_workers;5
autovacuum_multixact_freeze_max_age;400000000
autovacuum_naptime;1min
autovacuum_vacuum_cost_delay;10ms
autovacuum_vacuum_cost_limit;-1
autovacuum_vacuum_scale_factor;0.2
autovacuum_vacuum_threshold;90

VACUUM FULL analyze verbose sac.marcador;

INFO: vacuuming "bd.sac.marcador"
INFO: "marcador": found 0 removable, 2580480 nonremovable row versions in
104585 pages
DETAIL: 1082081 dead row versions cannot be removed yet.
CPU 0.95s/10.97u sec elapsed 26.32 sec.
INFO: analyzing "sac.marcador"
INFO: "marcador": scanned 104611 of 104611 pages, containing 1498399 live
rows and 1082098 dead rows; 120000 rows in sample, 1498399 estimated total
rows
Query returned successfully with no result in 39.8 secs.

--- log:

_2016-10-04 00:25:58 COT@@@@proc:7043 LOG: automatic vacuum of table
"bd.sac.marcador": index scans: 0
pages: 0 removed, 105114 remain, 0 skipped due to pins
tuples: 0 removed, 2592641 remain, 1093921 are dead but not yet
removable
buffer usage: 105258 hits, 122142 misses, 63624 dirtied
avg read rate: 1.247 MB/s, avg write rate: 0.649 MB/s
system usage: CPU 0.72s/7.44u sec elapsed 765.41 sec

_2016-10-04 00:32:49 COT@@@@proc:8347 LOG: automatic vacuum of table
"bd.sac.marcador": index scans: 0
pages: 0 removed, 105114 remain, 0 skipped due to pins
tuples: 0 removed, 2586008 remain, 1093921 are dead but not yet
removable
buffer usage: 94387 hits, 111210 misses, 3 dirtied
avg read rate: 2.376 MB/s, avg write rate: 0.000 MB/s
system usage: CPU 0.21s/0.42u sec elapsed 365.70 sec

_2016-10-04 00:39:40 COT@@@@proc:9038 LOG: automatic vacuum of table
"bd.sac.marcador": index scans: 0
pages: 0 removed, 105114 remain, 0 skipped due to pins
tuples: 0 removed, 2585320 remain, 1093921 are dead but not yet
removable
buffer usage: 94387 hits, 111210 misses, 2 dirtied
avg read rate: 2.370 MB/s, avg write rate: 0.000 MB/s
system usage: CPU 0.13s/0.49u sec elapsed 366.65 sec

--- la tabla usuario:

VACUUM FULL analyze verbose sac.usuario;
INFO: vacuuming "sac.usuario"
INFO: "usuario": found 0 removable, 52298 nonremovable row versions in
2201 pages
DETAIL: 52002 dead row versions cannot be removed yet.
CPU 0.01s/0.20u sec elapsed 0.34 sec.
INFO: analyzing "sac.usuario"
INFO: "usuario": scanned 2209 of 2209 pages, containing 296 live rows and
52002 dead rows; 296 rows in sample, 296 estimated total rows
Query returned successfully with no result in 2.2 secs.

--- log:

_2016-10-04 00:14:44 COT@@@@proc:7153 LOG: automatic vacuum of table
"bd.sac.usuario": index scans: 0
pages: 0 removed, 2262 remain, 0 skipped due to pins
tuples: 0 removed, 53578 remain, 53282 are dead but not yet
removable
buffer usage: 4669 hits, 1348 misses, 6 dirtied
avg read rate: 1.895 MB/s, avg write rate: 0.008 MB/s
system usage: CPU 0.00s/0.00u sec elapsed 5.55 sec

_2016-10-04 00:16:46 COT@@@@proc:7361 LOG: automatic vacuum of table "
bd.sac.usuario": index scans: 0
pages: 0 removed, 2262 remain, 0 skipped due to pins
tuples: 0 removed, 53578 remain, 53282 are dead but not yet
removable
buffer usage: 4692 hits, 1325 misses, 6 dirtied
avg read rate: 1.838 MB/s, avg write rate: 0.008 MB/s
system usage: CPU 0.00s/0.01u sec elapsed 5.63 sec

_2016-10-04 00:18:24 COT@@@@proc:7521 LOG: automatic vacuum of table "
bd.sac.usuario": index scans: 0
pages: 0 removed, 2262 remain, 0 skipped due to pins
tuples: 0 removed, 53578 remain, 53282 are dead but not yet
removable
buffer usage: 4692 hits, 1325 misses, 6 dirtied
avg read rate: 1.829 MB/s, avg write rate: 0.008 MB/s
system usage: CPU 0.00s/0.01u sec elapsed 5.65 sec

Lo particular es que esa campaña solo trabaja en horario hábil.. y el log
corresponde a la madrugada cuando no se esta haciendo nada....y asi se la
pasa tooodo el tiempo

Ademas también se evidencia sobre algunas tablas del sistema

bd=# select * from pg_stat_sys_tables where relname in ('pg_statistic');
-[ RECORD 1 ]-------+------------------------------
relid | 2619
schemaname | pg_catalog
relname | pg_statistic
seq_scan | 3
seq_tup_read | 8956
idx_scan | 112188
idx_tup_fetch | 73600
n_tup_ins | 0
n_tup_upd | 4537
n_tup_del | 0
n_tup_hot_upd | 22
n_live_tup | 4478
n_dead_tup | 82747
n_mod_since_analyze | 4537
last_vacuum | 2016-10-04 00:10:02.384032-05
last_autovacuum | 2016-10-04 08:03:44.508778-05
last_analyze |
last_autoanalyze |
vacuum_count | 1
autovacuum_count | 379
analyze_count | 0
autoanalyze_count | 0

_2016-10-04 00:11:03 COT@@@@proc:6829 LOG: automatic vacuum of table
"bd.pg_catalog.pg_statistic": index scans: 0
pages: 0 removed, 4292 remain, 0 skipped due to pins
tuples: 0 removed, 84631 remain, 80164 are dead but not yet
removable
buffer usage: 7275 hits, 1637 misses, 1 dirtied
avg read rate: 5.482 MB/s, avg write rate: 0.003 MB/s
system usage: CPU 0.00s/0.01u sec elapsed 2.33 sec

_2016-10-04 00:14:25 COT@@@@proc:7153 LOG: automatic vacuum of table
"bd.pg_catalog.pg_statistic": index scans: 0
pages: 0 removed, 4419 remain, 0 skipped due to pins
tuples: 0 removed, 87225 remain, 82747 are dead but not yet
removable
buffer usage: 9165 hits, 0 misses, 0 dirtied
avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
system usage: CPU 0.00s/0.01u sec elapsed 2.81 sec

pid backend_start xact_start query_start state_change waiting state
backend_xid backend_xmin query
1914 2016-10-03 23:23:19.505038-05
2016-10-04 08:04:48.7674-05 2016-10-04 08:04:48.768723-05 f idle

2265 2016-10-03 23:26:21.564493-05
2016-10-04 08:05:08.86149-05 2016-10-04 08:05:08.862897-05 f idle

47880 2016-10-04 07:06:14.579201-05
2016-10-04 08:04:02.589559-05 2016-10-04 08:04:02.589587-05 f idle

COMMIT
2278 2016-10-03 23:26:21.908269-05
2016-10-04 08:05:13.011841-05 2016-10-04 08:05:13.013463-05 f idle

44847 2016-10-04 06:36:14.581349-05
2016-10-04 07:57:58.172883-05 2016-10-04 07:57:58.172894-05 f idle

COMMIT
*53595* *2016-10-04 08:03:28.854093-05* *2016-10-04
08:04:12.434459-05* *2016-10-04
08:04:12.434459-05* *2016-10-04 08:04:12.43446-05* *f* *active*
*8409334* *autovacuum: VACUUM sac.marcador*
*53869* *2016-10-04 08:05:08.742561-05* *2016-10-04
08:05:08.767017-05* *2016-10-04
08:05:08.767017-05* *2016-10-04 08:05:08.767018-05* *f* *active*
*8409701* *autovacuum: VACUUM pg_catalog.pg_statistic*
44848 2016-10-04 06:36:14.585002-05
2016-10-04 08:05:16.139131-05 2016-10-04 08:05:16.139141-05 f idle

COMMIT
2335 2016-10-03 23:26:48.436263-05
2016-10-04 08:05:16.129982-05 2016-10-04 08:05:16.131393-05 f idle

2336 2016-10-03 23:26:48.753639-05
2016-10-04 08:05:10.965782-05 2016-10-04 08:05:10.967623-05 f idle

49345 2016-10-04 07:21:14.580598-05
2016-10-04 08:04:02.586993-05 2016-10-04 08:04:02.587004-05 f idle

COMMIT
34358 2016-10-04 04:50:19.478609-05
2016-10-04 08:05:07.911253-05 2016-10-04 08:05:07.912494-05 f idle

53078 2016-10-04 07:58:44.579811-05
2016-10-04 08:04:02.587614-05 2016-10-04 08:04:02.587625-05 f idle

COMMIT
43407 2016-10-04 06:21:28.721074-05
2016-10-04 08:01:51.027872-05 2016-10-04 08:01:51.027888-05 f idle

COMMIT
53295 2016-10-04 08:00:28.119403-05
2016-10-04 08:01:51.001261-05 2016-10-04 08:01:51.001271-05 f idle

COMMIT
46378 2016-10-04 06:51:28.722048-05
2016-10-04 08:03:51.379678-05 2016-10-04 08:03:51.379696-05 f idle

COMMIT
53455 2016-10-04 08:01:50.909667-05
2016-10-04 08:03:51.371146-05 2016-10-04 08:03:51.375271-05 f idle

COMMIT
50301 2016-10-04 07:30:36.691553-05
2016-10-04 08:01:51.027026-05 2016-10-04 08:01:51.028251-05 f idle

COMMIT
2579 2016-10-03 23:29:04.065025-05
2016-10-04 08:05:07.499953-05 2016-10-04 08:05:07.499991-05 f idle

COMMIT
19372 2016-10-04 02:20:00.02629-05
2016-10-04 08:05:00.057676-05 2016-10-04 08:05:00.057685-05 f idle

COMMIT
53456 2016-10-04 08:01:50.957187-05
2016-10-04 08:05:16.293226-05 2016-10-04 08:05:16.293235-05 f idle

COMMIT
53457 2016-10-04 08:01:50.995657-05
2016-10-04 08:04:59.700431-05 2016-10-04 08:04:59.700468-05 f idle

COMMIT
47043 2016-10-04 06:58:26.382192-05
2016-10-04 08:01:51.001292-05 2016-10-04 08:01:51.001318-05 f idle

COMMIT
50302 2016-10-04 07:30:36.731595-05
2016-10-04 08:03:51.378466-05 2016-10-04 08:03:51.378481-05 f idle

COMMIT
47045 2016-10-04 06:58:26.415354-05
2016-10-04 08:01:51.012204-05 2016-10-04 08:01:51.012217-05 f idle

COMMIT
53458 2016-10-04 08:01:50.998062-05
2016-10-04 08:03:51.415377-05 2016-10-04 08:03:51.415428-05 f idle

COMMIT
51243 2016-10-04 07:40:00.027611-05
2016-10-04 08:05:00.119537-05 2016-10-04 08:05:00.122584-05 f idle

COMMIT
53459 2016-10-04 08:01:51.002677-05
2016-10-04 08:05:14.253073-05 2016-10-04 08:05:14.253095-05 f idle

COMMIT
53497 2016-10-04 08:02:37.774635-05 2016-10-04 08:05:16.316145-05 2016-10-04
08:05:16.316145-05 2016-10-04 08:05:16.316147-05 f active
8409746 select pid,backend_start,xact_start,
query_start,state_change,waiting,state, backend_xid,backend_xmin,query from
pg_stat_activity where datname='bd'
53589 2016-10-04 08:03:11.156655-05
2016-10-04 08:04:45.177181-05 2016-10-04 08:04:45.188639-05 f idle

select * from pg_stat_sys_tables where relname in ('pg_statistic')

bd=# select * from pg_stat_sys_tables where relname in ('pg_statistic');
-[ RECORD 1 ]-------+------------------------------
relid | 2619
schemaname | pg_catalog
relname | pg_statistic
seq_scan | 3
seq_tup_read | 8956
idx_scan | 112188
idx_tup_fetch | 73600
n_tup_ins | 0
n_tup_upd | 4537
n_tup_del | 0
n_tup_hot_upd | 22
n_live_tup | 4478
n_dead_tup | 82747
n_mod_since_analyze | 4537
last_vacuum | 2016-10-04 00:10:02.384032-05
last_autovacuum | 2016-10-04 08:03:44.508778-05
last_analyze |
last_autoanalyze |
vacuum_count | 1
autovacuum_count | 379
analyze_count | 0
autoanalyze_count | 0

bd=# select * from pg_prepared_xacts;
(0 rows)

bd=# select * from pg_stat_replication;
-[ RECORD 1 ]----+------------------------------
pid | 1965
usesysid | 10
usename | postgres
application_name | walreceiver
client_addr | 192.168.72.XX
client_hostname |
client_port | 46730
backend_start | 2016-10-03 23:23:35.355306-05
backend_xmin |
state | streaming
sent_location | 9/365B2E88
write_location | 9/365B2E88
flush_location | 9/365B2E88
replay_location | 9/365B2C40
sync_priority | 0
sync_state | async
-[ RECORD 2 ]----+------------------------------
pid | 2054
usesysid | 10
usename | postgres
application_name | walreceiver
client_addr | 10.72.73.XX
client_hostname |
client_port | 50898
backend_start | 2016-10-03 23:24:07.788617-05
backend_xmin |
state | streaming
sent_location | 9/365B2E88
write_location | 9/365B2E88
flush_location | 9/365B2E88
replay_location | 9/365B2C40
sync_priority | 0
sync_state | async

bd=# select * from pg_replication_slots;

-[ RECORD 1 ]+---------------------
slot_name | replica_calleXX_slot
plugin |
slot_type | physical
datoid |
database |
active | t
active_pid | 1965
xmin | 8411241
catalog_xmin |
restart_lsn | 9/3670A150
-[ RECORD 2 ]+---------------------
slot_name | replica_local_slot
plugin |
slot_type | physical
datoid |
database |
active | t
active_pid | 2054
xmin | 5463120
catalog_xmin |
restart_lsn | 9/3670A150

2016-10-03 17:38 GMT-05:00 Alvaro Herrera <alvherre(at)2ndquadrant(dot)com>:

> Hellmuth Vargas escribió:
>
> > > Ahh, ¿no tendrás un standby con "feedback" activado que tiene una
> > > transacción preparada, o un slot inactivo? Pega acá
> > > select * from pg_stat_replication
> >
> >
> > bd=# select * from pg_stat_replication
> > bd-# ;
> > -[ RECORD 1 ]----+------------------------------
> > pid | 1892
> > usesysid | 10
> > usename | postgres
> > application_name | walreceiver
> > client_addr | 192.168.72.XX
> > client_hostname |
> > client_port | 46648
> > backend_start | 2016-10-02 11:46:57.003511-05
> > backend_xmin |
> > state | streaming
> > sent_location | 9/11E181C0
> > write_location | 9/11E181C0
> > flush_location | 9/11E181C0
> > replay_location | 9/11E18090
> > sync_priority | 0
> > sync_state | async
> > -[ RECORD 2 ]----+------------------------------
> > pid | 2043
> > usesysid | 10
> > usename | postgres
> > application_name | walreceiver
> > client_addr | 10.72.73.YY
> > client_hostname |
> > client_port | 55716
> > backend_start | 2016-10-02 11:48:07.38359-05
> > backend_xmin |
> > state | streaming
> > sent_location | 9/11E181C0
> > write_location | 9/11E181C0
> > flush_location | 9/11E181C0
> > replay_location | 9/11E18090
> > sync_priority | 0
> > sync_state | async
>
> ???
>
> Según controldata que pasaste antes,
> Latest checkpoint's REDO location: 1896/AB72AB00
> No tiene ningún sentido que sent_location acá sea 9/11E181C0. ¿Estamos
> hablando del mismo servidor?
>
> > > select * from pg_replication_slots
> > >
> > > bd=# select * from pg_replication_slots;
> > -[ RECORD 1 ]+---------------------
> > slot_name | replica_calleXX_slot
> > plugin |
> > slot_type | physical
> > datoid |
> > database |
> > active | t
> > active_pid | 1892
> > xmin | 8355084
> > catalog_xmin |
> > restart_lsn | 9/11FA3D18
> > -[ RECORD 2 ]+---------------------
> > slot_name | replica_local_slot
> > plugin |
> > slot_type | physical
> > datoid |
> > database |
> > active | t
> > active_pid | 2043
> > xmin | 5463120
> > catalog_xmin |
> > restart_lsn | 9/11FA3D18
>
> Ídem; además, el xmin es 8 millones que no está ni cerca del
> Latest checkpoint's NextXID: 0/2021183943
> (dos mil millones) que mostraste en controldata.
>
> Wtf?
>
> --
> Álvaro Herrera https://www.2ndQuadrant.com/
> PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
>

--
Cordialmente,

Ing. Hellmuth I. Vargas S.
Esp. Telemática y Negocios por Internet
Oracle Database 10g Administrator Certified Associate
EnterpriseDB Certified PostgreSQL 9.3 Associate