Discussion:
Autovacuum issues with truncate and create index ...
(too old to reply)
Kevin Grittner
2012-12-30 18:35:59 UTC
Permalink
Just so we know how to interpret that, how many minutes, hours,
or days did you wait to see whether it would ever end?
I have waiting for 15 minutes in this state. I can not wait more
time without losing some data for our client.
Thanks. I wasn't suggesting you increase the duration; I just
wanted perspective on whether it could be the result of unusually
long run times rather than blocking, and how severe that increase
was known ot be.
If it doesn't cause too much pain to let it get into this state
for a few minutes, it might help diagnose the issue if you could
start `vmstat 1` before you let it get into this state, and
capture `ps aux | postgres`, pg_stat_activity, and pg_locks at
intervals while it is in this state. Looking at all of the above
might suggest a cause. If we can find the cause, we can almost
certainly fix it.
[information captured as requested]
Thank you very much, With that much information we should be much
better able to get a sense of the nature of the problem. It will
take a while to sift through it and properly analyze it. But even
on a first pass I think there is a lot of valuable information that
jumps out:

(1) There is no sign of unusual pressure on OS memory; OS cache
usage remains stable from before the incident to the end of the
monitored period.

(2) Disk wait time climbed early in the incident and remained high
to the end.

(3) Disk read volume *before* the incident shows a peak of about
the same as during the incident, with somewhat lower disk wait
time. (Do we know what was causing that? It ended before the other
results were captured.)

(4) Not a single incident of blocking was captured in any of the
lists of pg_stat_activity or pg_locks.

(5) The TRUNCATE statements completed and moved on to CREATE INDEX,
which continued to accrue CPU time during the episode.

(6) Of the three autovacuum worker processes, two were running just
an ANALYZE on every sample, and were moving on from table to table.

(7) One autovacuum process was running VACUUM ANALYZE against a
single table for the entire duration of the incident. It was slowly
accumulating CPU time during the incident.

On the face of it, it appears that with your normal production
settings your storage system is right at the edge of what it can
handle, and making autovacuum more aggressive to try to keep the
statistics on the second type of table more up-to-date is pushing
the load past its capacity. You might be able to change the
autovacuum thresholds and scale factors without changing
autovacuum_vacuum_cost_delay and autovacuum_vacuum_cost_limit (or
making smaller changes to them). You could probably throw hardware
at it to fix the problem. Even with settings which work fine when
everything is up-to-date you may experience some impact on
production when you frist turn it on and autovacuum is attempting
to "catch up".

I'm not actually clear, when I look back, at what the problem is
that you are trying to solve -- you say that a particular type of
query is running for 2 to 3 minutes, and note that statistics on a
particular type of table are only being re-sampled once every 5 to
6 days. It's not clear that more frequent statistical sampling of
the tables would change the plans. Perhaps you should post one such
query to the performance list, with supporting data, and see
whether someone can suggest a way to speed that query.

http://wiki.postgresql.org/wiki/SlowQueryQuestions

-Kevin
--
Sent via pgsql-admin mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
Baptiste LHOSTE
2012-12-31 16:20:26 UTC
Permalink
Hi,
Post by Kevin Grittner
Thanks. I wasn't suggesting you increase the duration; I just
wanted perspective on whether it could be the result of unusually
long run times rather than blocking, and how severe that increase
was known ot be.
Thank you very much, With that much information we should be much
better able to get a sense of the nature of the problem. It will
take a while to sift through it and properly analyze it. But even
on a first pass I think there is a lot of valuable information that
(1) There is no sign of unusual pressure on OS memory; OS cache
usage remains stable from before the incident to the end of the
monitored period.
(2) Disk wait time climbed early in the incident and remained high
to the end.
Just for information, our server has 4 disk SAS in raid 0. I do not remember if I have already mention it.
Post by Kevin Grittner
(3) Disk read volume *before* the incident shows a peak of about
the same as during the incident, with somewhat lower disk wait
time. (Do we know what was causing that? It ended before the other
results were captured.)
Maybe it's the consequence of the step 4 of our process : "we copy new data (around 150 000 rows) in the target partition"
These data have been read from files then have been copied to the database.
That could explain the peak on the disk read volume.
Post by Kevin Grittner
(4) Not a single incident of blocking was captured in any of the
lists of pg_stat_activity or pg_locks.
(5) The TRUNCATE statements completed and moved on to CREATE INDEX,
which continued to accrue CPU time during the episode.
(6) Of the three autovacuum worker processes, two were running just
an ANALYZE on every sample, and were moving on from table to table.
(7) One autovacuum process was running VACUUM ANALYZE against a
single table for the entire duration of the incident. It was slowly
accumulating CPU time during the incident.
On the face of it, it appears that with your normal production
settings your storage system is right at the edge of what it can
handle, and making autovacuum more aggressive to try to keep the
statistics on the second type of table more up-to-date is pushing
the load past its capacity. You might be able to change the
autovacuum thresholds and scale factors without changing
autovacuum_vacuum_cost_delay and autovacuum_vacuum_cost_limit (or
making smaller changes to them). You could probably throw hardware
at it to fix the problem. Even with settings which work fine when
everything is up-to-date you may experience some impact on
production when you frist turn it on and autovacuum is attempting
to "catch up".
We will try to change autovacuum thresholds and scale factors without changing autovacuum_vacuum_cost_delay and autovacuum_vacuum_cost_limit.
Post by Kevin Grittner
I'm not actually clear, when I look back, at what the problem is
that you are trying to solve -- you say that a particular type of
query is running for 2 to 3 minutes, and note that statistics on a
particular type of table are only being re-sampled once every 5 to
6 days. It's not clear that more frequent statistical sampling of
the tables would change the plans. Perhaps you should post one such
query to the performance list, with supporting data, and see
whether someone can suggest a way to speed that query.
http://wiki.postgresql.org/wiki/SlowQueryQuestions
These queries are very simple : delete from table where start_date < availableTimestamp.
We performed an EXPLAIN to try to understand what could be the problem.
The query planner said that the index on start_date could not be used because it was not up-to-date.
That why we decided to increase the frequency of the autovacuum process.

How a server (8 CPUs) which has a 0.56 load over the last 15 minutes could not handle 3 autovacuum processes, for me it is very confusing.

Thanks anyway for your time and help.

Happy New Year's Eve.

Best regards,

Baptiste

---
Baptiste LHOSTE
***@alaloop.com

ALALOOP S.A.S. - Technopole Izarbel - 64210 Bidart
Téléphone : +33 (0) 5 59 41 51 10
www.alaloop.com
--
Sent via pgsql-admin mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
Kevin Grittner
2012-12-31 16:41:07 UTC
Permalink
Post by Baptiste LHOSTE
These queries are very simple : delete from table where
start_date < availableTimestamp. We performed an EXPLAIN to try
to understand what could be the problem. The query planner said
that the index on start_date could not be used because it was not
up-to-date.
Could you show that output you base that on?
Post by Baptiste LHOSTE
How a server (8 CPUs) which has a 0.56 load over the last 15
minutes could not handle 3 autovacuum processes, for me it is
very confusing.
When the bottleneck is disk I/O the CPUs count is not going to
help. Threads which have not been context-switched out, but are
sitting waiting for the electric motors to drag the disk arm to the
right cylinder probably don't count against the load average.

Note that while three autovacuum processes normally don't cause any
grief, you seem to be near the tipping point anyway, so it may be a
case of "the straw that broke the camel's back". Especially since
you made autovacuum many times more resource-hungry than it is by
default.

-Kevin
--
Sent via pgsql-admin mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
Baptiste LHOSTE
2013-01-03 10:26:37 UTC
Permalink
Hi,
Post by Kevin Grittner
Could you show that output you base that on?
EXPLAIN on table which was recently analyzed by the autovacuum process :

explain delete from agg_t1343_incoming_a3_src_net_and_dst_net_f5 where start_date < 1353317127200;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------Index Scan using agg_t1343_incoming_a3_src_net_and_dst_net_f5_start_date on agg_t1343_incoming_a3_src_net_and_dst_net_f5 (cost=0.00..9.01 rows=41 width=6)
Index Cond: (start_date < 1353317127200::bigint)
(2 rows)

Here you can find the duration and the number of deleted rows of previous query.
Query duration : 4s 538ms for 15960 rows deleted



EXPLAIN on table which was analyzed four days ago by the autovacuum process :

explain delete from agg_t1187_incoming_a6_dst_port_and_proto_f5 where start_date < 1353317127200;
QUERY PLAN
--------------------------------------------------------------------------------------------------
Seq Scan on agg_t1187_incoming_a6_dst_port_and_proto_f5 (cost=0.00..58063.86 rows=3269 width=6)
Filter: (start_date < 1353317127200::bigint)
(2 rows)

Here you can find the duration and the number of deleted rows of previous query.
Query duration : 52s 368ms for 21130 rows deleted

The first EXPLAIN mention that an Index scan is used but the second one mention that a sequence scan is used.

That why we concluded that we had to have our index up-to-date.
Post by Kevin Grittner
When the bottleneck is disk I/O the CPUs count is not going to
help. Threads which have not been context-switched out, but are
sitting waiting for the electric motors to drag the disk arm to the
right cylinder probably don't count against the load average.
My mistake, when I said that the server had a 0.56 load over the last 15 minutes, it was before the change on autovacuum thresholds, because after that the load just blow up.
Post by Kevin Grittner
Note that while three autovacuum processes normally don't cause any
grief, you seem to be near the tipping point anyway, so it may be a
case of "the straw that broke the camel's back". Especially since
you made autovacuum many times more resource-hungry than it is by
default.
We tried to change the autovacuum thresholds without changing autovacuum_vacuum_cost_delay and autovacuum_vacuum_cost_limit.

The server managed to handle the work during 25 minutes then it just started to take too much time on CREATE INDEX statements.

I just figure that when we perform the full process (with deletion of old data), CREATE INDEX and TUNCATE take too much time.

At the same time the autovacuum process seems to perform more tasks on second type of tables.

Best regards,

Baptiste

---
Baptiste LHOSTE
***@alaloop.com

ALALOOP S.A.S. - Technopole Izarbel - 64210 Bidart
Téléphone : +33 (0) 5 59 41 51 10
www.alaloop.com
--
Sent via pgsql-admin mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
Baptiste LHOSTE
2013-01-17 09:23:39 UTC
Permalink
Hi,

We are still trying to fix our issue and we found following logs :

2013-01-17 09:55:01 CET LOG: automatic vacuum of table "flows.public.agg_t1213_incoming_a6_dst_port_and_proto_f5": index scans: 1
pages: 0 removed, 136547 remain
tuples: 0 removed, 4044679 remain
system usage: CPU 3.21s/5.21u sec elapsed 2005.15 sec

2013-01-17 10:12:50 CET LOG: automatic vacuum of table "flows.public.agg_t1214_outgoing_a1_src_net_f5": index scans: 1
pages: 59886 removed, 37828 remain
tuples: 1645338 removed, 3750874 remain
system usage: CPU 3.01s/4.08u sec elapsed 1015.75 sec

How is it possible that first task took twice the time of the second without any tuples to remove ?

Baptiste
--
Sent via pgsql-admin mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
Albe Laurenz
2013-01-17 11:30:27 UTC
Permalink
Post by Baptiste LHOSTE
2013-01-17 09:55:01 CET LOG: automatic vacuum of table
"flows.public.agg_t1213_incoming_a6_dst_port_and_proto_f5": index scans: 1
pages: 0 removed, 136547 remain
tuples: 0 removed, 4044679 remain
system usage: CPU 3.21s/5.21u sec elapsed 2005.15 sec
2013-01-17 10:12:50 CET LOG: automatic vacuum of table
"flows.public.agg_t1214_outgoing_a1_src_net_f5": index scans: 1
pages: 59886 removed, 37828 remain
tuples: 1645338 removed, 3750874 remain
system usage: CPU 3.01s/4.08u sec elapsed 1015.75 sec
How is it possible that first task took twice the time of the second without any tuples to remove ?
Maybe more of the first table is cached.
Maybe contention on the table or the I/O system in general
varied between the two VACUUMs.

Yours,
Laurenz Albe
--
Sent via pgsql-admin mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
Loading...