Re: Vacuum and state_change

> On Jun 9, 2017, at 11:23 AM, Adrian Klaver <adrian(dot)klaver(at)aklaver(dot)com> wrote:
>
> On 06/09/2017 09:13 AM, armand pirvu wrote:
>>> On Jun 9, 2017, at 11:01 AM, Adrian Klaver <adrian(dot)klaver(at)aklaver(dot)com <mailto:adrian(dot)klaver(at)aklaver(dot)com>> wrote:
>>>
>>> On 06/09/2017 08:45 AM, armand pirvu wrote:
>>>> Hi
>>>> Had a couple of processes blocking the vacuum so I terminated them using
>>>> select pg_terminate_backend(pid);
>>>> Running the following
>>>> select distinct pid, backend_start, query_start, state_change, state, query from pg_catalog.pg_stat_activity order by 1;
>>>> pid | backend_start | query_start | state_change | state | query
>>>> -------+-------------------------------+-------------------------------+-------------------------------+--------+--------------------------------------------------------------------------------------------------------------------------
>>>> 10677 | 2017-06-09 10:25:49.189848-05 | 2017-06-09 10:33:43.598805-05 | 2017-06-09 10:33:43.599091-05 | idle | SELECT 1
>>>> 11096 | 2017-06-09 10:27:03.686588-05 | 2017-06-09 10:33:56.28736-05 | 2017-06-09 10:33:56.287364-05 | active | select distinct pid, backend_start, query_start, state_change, state, query from pg_catalog.pg_stat_activity order by 1;
>>>> 13277 | 2017-06-09 07:48:49.506686-05 | 2017-06-09 07:48:52.887185-05 | 2017-06-09 07:48:52.887188-05 | active | autovacuum: VACUUM csischema.tf_purchased_badge
>>>> 13484 | 2017-06-09 10:31:54.127672-05 | 2017-06-09 10:33:47.137938-05 | 2017-06-09 10:33:47.138226-05 | idle | SELECT 1
>>>> 16886 | 2017-06-09 07:56:49.033893-05 | 2017-06-09 07:56:49.078369-05 | 2017-06-09 07:56:49.078371-05 | active | autovacuum: VACUUM csischema.tf_purchases_person
>>>> 25387 | 2017-06-09 05:32:08.079397-05 | 2017-06-09 05:32:08.385728-05 | 2017-06-09 05:32:08.385731-05 | active | autovacuum: VACUUM csischema.tf_demographic_response_person
>>>> 37465 | 2017-06-09 08:50:58.992002-05 | 2017-06-09 08:51:21.506829-05 | 2017-06-09 08:51:21.506831-05 | active | autovacuum: VACUUM csischema.tf_transaction_item_person
>>>> I did notice that state_change did not change one bit
>>>
>>> Did the state change?
>>>
>> No and that was what got me worried
>
> Are these large tables?
>
>

I would say yes

select count(*) from csischema.tf_purchased_badge;
9380749

select count(*) from csischema.tf_purchases_person;
19902172

select count(*) from csischema.tf_demographic_response_person;
80868561

select count(*) from csischema.tf_transaction_item_person;
3281084

Interesting enough two completed

relname | seq_scan | seq_tup_read | idx_scan | idx_tup_fetch | n_tup_ins | n_tup_upd | n_live_tup | n_dead_tup | n_mod_since_analyze | last_vacuum | last_autovacuum | autovacuum_count
----------------------------+----------+--------------+----------+---------------+-----------+-----------+------------+------------+---------------------+-------------+-------------------------------+------------------
tf_transaction_item_person | 160 | 0 | 476810 | 1946119 | 2526 | 473678 | 3226110 | 0 | 116097 | | 2017-06-09 11:15:24.701997-05 | 2
tf_purchased_badge | 358 | 1551142438 | 2108331 | 7020502 | 5498 | 1243746 | 9747336 | 107560 | 115888 | | 2017-06-09 15:09:16.624363-05 | 1

I did notice though that checkpoints seem a bit too often aka below 5 min from start to end

2017-06-09 14:18:38.552 CDT,,,888,,593a1810.378,271,,2017-06-08 22:37:52 CDT,,0,LOG,00000,"checkpoint starting: time",,,,,,,,,""
2017-06-09 14:21:12.210 CDT,,,888,,593a1810.378,272,,2017-06-08 22:37:52 CDT,,0,LOG,00000,"checkpoint complete: wrote 12070 buffers (9.2%); 0 transaction log file(s) added, 0 removed, 4 recycled; write=148.714 s, sync=4.834 s, total=153.657 s; sync files=17, longest=1.841 s, average=0.284 s; distance=89452 kB, estimate=89452 kB",,,,,,,,,""

2017-06-09 14:23:38.278 CDT,,,888,,593a1810.378,273,,2017-06-08 22:37:52 CDT,,0,LOG,00000,"checkpoint starting: time",,,,,,,,,""
2017-06-09 14:24:38.629 CDT,,,888,,593a1810.378,274,,2017-06-08 22:37:52 CDT,,0,LOG,00000,"checkpoint complete: wrote 593 buffers (0.5%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=59.825 s, sync=0.474 s, total=60.350 s; sync files=8, longest=0.355 s, average=0.059 s; distance=26952 kB, estimate=83202 kB",,,,,,,,,""

And also

SELECT
total_checkpoints,
seconds_since_start / total_checkpoints / 60 AS minutes_between_checkpoints
FROM
(SELECT
EXTRACT(EPOCH FROM (now() - pg_postmaster_start_time())) AS seconds_since_start,
(checkpoints_timed+checkpoints_req) AS total_checkpoints
FROM pg_stat_bgwriter
) AS sub;

total_checkpoints | minutes_between_checkpoints
-------------------+-----------------------------
285 | 3.33731205871345

These tables suffer quite some data changes IIRC but that comes via some temp tables which reside in a temp schema and some previous messages from the log suggest that it might have ran into ladder locking in early stages, aka tmp table locked from vacuum and any further processing waiting for it and causing some other waits on those largish tables

Considering the temp ones are only for load and yes some processing goes in there , I am thinking disabling auto vacuum for the temp tables . Or should I disable auto vacuum all together and run say as a bath job on a weekend night ?

> If you are on Postgres 9.6:
>
> https://www.postgresql.org/docs/9.6/static/progress-reporting.html
>

Aside that there are vacuum improvements and such, any other strong compelling reason to upgrade to 9.6 ?

>>>> Does that mean that something is not quite right with the vacuums ?
>>>
>>> Might want to take a look at:
>>>
>>> https://www.postgresql.org/docs/9.6/static/monitoring-stats.html#PG-STAT-ALL-TABLES-VIEW
>>>
>>>
>>>> Thank you
>>>> Armand
>>>
>>>
>>> --
>>> Adrian Klaver
>>> adrian(dot)klaver(at)aklaver(dot)com <mailto:adrian(dot)klaver(at)aklaver(dot)com>
>
>
> --
> Adrian Klaver
> adrian(dot)klaver(at)aklaver(dot)com