Thread: Status of autovacuum and the sporadic stats failures ?
I'm still getting random failures from some of my buildfarm members which is starting to get a bit irritating and annoying :-( some recent failures: http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=zebra&dt=2007-02-06%2015:25:04 http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=clownfish&dt=2007-02-06%2000:03:04 http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=clownfish&dt=2007-02-04%2003:03:09 http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=impala&dt=2007-02-02%2003:03:02 any ideas ? Stefan
Stefan Kaltenbrunner wrote: > I'm still getting random failures from some of my buildfarm members > which is starting to get a bit irritating and annoying :-( > > some recent failures: > > http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=zebra&dt=2007-02-06%2015:25:04 > http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=clownfish&dt=2007-02-06%2000:03:04 > http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=clownfish&dt=2007-02-04%2003:03:09 > http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=impala&dt=2007-02-02%2003:03:02 > > > any ideas ? Since they are sporadic, my guess is that it's due to autovacuum not letting pgstat catch up. I'd try either setting autovacuum_vacuum_cost_delay to a low value, or extending the sleep period in the stats test, to give more time for pgstat to catch up with those messages. Setting the cost_delay sounds a reasonable thing to do anyway, and in fact I already proposed it and nobody objected (AFAIR). Now we only have to agree on a reasonable value. -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
Alvaro Herrera wrote: > Setting the cost_delay sounds a reasonable thing to do anyway, and in > fact I already proposed it and nobody objected (AFAIR). Now we only > have to agree on a reasonable value. Also note this message: Date: Sat, 27 Jan 2007 21:51:40 -0500 Message-ID: <27665.1169952700@sss.pgh.pa.us> From: Tom Lane <tgl@sss.pgh.pa.us> Subject: Re: [GENERAL] Stats collector frozen? [...] > If this theory is correct, then we can improve the reliability of the > stats test a good deal if we put a sleep() at the *start* of the test, > to let any old backends get out of the way. It seems worth a try > anyway. I'll add this to HEAD and if the stats failure noise seems to > go down, we can back-port it. which was followed by this commit revision 1.6 date: 2007-01-28 00:02:31 -0300; author: tgl; state: Exp; lines: +4 -0; Add a delay at the start of the stats test, to let any prior stats activity quiesce. Possibly this will fix the large increase in non-reproducible stats test failures we've noted since turning on stats_row_level by default. Apparently it wasn't enough to completely eliminate the problems. Did it reduce them? I haven't been watching the buildfarm closely enough to know for sure. -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
Alvaro Herrera wrote: > Stefan Kaltenbrunner wrote: >> I'm still getting random failures from some of my buildfarm members >> which is starting to get a bit irritating and annoying :-( >> >> some recent failures: >> >> http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=zebra&dt=2007-02-06%2015:25:04 >> http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=clownfish&dt=2007-02-06%2000:03:04 >> http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=clownfish&dt=2007-02-04%2003:03:09 >> http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=impala&dt=2007-02-02%2003:03:02 >> >> >> any ideas ? > > Since they are sporadic, my guess is that it's due to autovacuum not > letting pgstat catch up. I'd try either setting > autovacuum_vacuum_cost_delay to a low value, or extending the sleep > period in the stats test, to give more time for pgstat to catch up with > those messages. hmm now that I look closer - all those members above are actually VMs of some sort and the host is rather busy at times (multiple VMs competing for CPU and IO) so that might be a factor here. > > Setting the cost_delay sounds a reasonable thing to do anyway, and in > fact I already proposed it and nobody objected (AFAIR). Now we only > have to agree on a reasonable value. note sure on a reasonable value but we still have time to test different values if needed for 8.3 - but I think we should really try to get rid of those sporadic failures because they might lead to getting other issues going unnoticed. Stefan
Alvaro Herrera wrote: > Alvaro Herrera wrote: > >> Setting the cost_delay sounds a reasonable thing to do anyway, and in >> fact I already proposed it and nobody objected (AFAIR). Now we only >> have to agree on a reasonable value. > > Also note this message: > > Date: Sat, 27 Jan 2007 21:51:40 -0500 > Message-ID: <27665.1169952700@sss.pgh.pa.us> > From: Tom Lane <tgl@sss.pgh.pa.us> > Subject: Re: [GENERAL] Stats collector frozen? > > [...] >> If this theory is correct, then we can improve the reliability of the >> stats test a good deal if we put a sleep() at the *start* of the test, >> to let any old backends get out of the way. It seems worth a try >> anyway. I'll add this to HEAD and if the stats failure noise seems to >> go down, we can back-port it. > > which was followed by this commit > > revision 1.6 > date: 2007-01-28 00:02:31 -0300; author: tgl; state: Exp; lines: +4 -0; > Add a delay at the start of the stats test, to let any prior stats > activity quiesce. Possibly this will fix the large increase in > non-reproducible stats test failures we've noted since turning on > stats_row_level by default. > > > Apparently it wasn't enough to completely eliminate the problems. Did > it reduce them? I haven't been watching the buildfarm closely enough to > know for sure. at least for my members it seems it did not have any effect at all. I actually think I got more failures in the period afterwards but the failures are too sporadic to quantify that(and in some way also depends on the number of commits done which directly influence the number of builds/tests). Stefan
Alvaro Herrera <alvherre@commandprompt.com> writes:
> Also note this message:
>> If this theory is correct, then we can improve the reliability of the
>> stats test a good deal if we put a sleep() at the *start* of the test,
>> to let any old backends get out of the way. It seems worth a try
>> anyway. I'll add this to HEAD and if the stats failure noise seems to
>> go down, we can back-port it.
> Apparently it wasn't enough to completely eliminate the problems. Did
> it reduce them? I haven't been watching the buildfarm closely enough to
> know for sure.
It doesn't seem to have helped much if at all :-(.
The $64 question in my mind is whether the failures represent pgstats
not working at all, or just being pretty slow when the system is under
load. It seems likely to be the latter, but ... I don't want to just
keep jacking the sleep up indefinitely, anyway; that will slow the
regression tests down for little reason.
I'm tempted to propose replacing the fixed sleep with a short plpgsql
function that sleeps for a second, checks to see if the stats have
changed, repeats if not; giving up only after perhaps 30 seconds.
It'd be interesting to try to gather stats on the length of the delay
taken, but I don't see a good way to do that within the current
regression-test infrastructure.
regards, tom lane
Tom Lane wrote: > I'm tempted to propose replacing the fixed sleep with a short plpgsql > function that sleeps for a second, checks to see if the stats have > changed, repeats if not; giving up only after perhaps 30 seconds. > > It'd be interesting to try to gather stats on the length of the delay > taken, but I don't see a good way to do that within the current > regression-test infrastructure. > > > Have it log something that will appear on the postmaster log but not the client log? Buildfarm members mostly post their complete postmaster logs, and we could postprocess those. cheers andrew
Andrew Dunstan <andrew@dunslane.net> writes:
> Tom Lane wrote:
>> I'm tempted to propose replacing the fixed sleep with a short plpgsql
>> function that sleeps for a second, checks to see if the stats have
>> changed, repeats if not; giving up only after perhaps 30 seconds.
>>
>> It'd be interesting to try to gather stats on the length of the delay
>> taken, but I don't see a good way to do that within the current
>> regression-test infrastructure.
> Have it log something that will appear on the postmaster log but not the
> client log? Buildfarm members mostly post their complete postmaster
> logs, and we could postprocess those.
Or even just eyeball them. Good idea --- I'll do it as soon as I get a
chance to catch my breath. Today's a bit busy :-(
Or if someone else wants to run with the idea, go for it.
regards, tom lane
Andrew Dunstan <andrew@dunslane.net> writes:
> Tom Lane wrote:
>> It'd be interesting to try to gather stats on the length of the delay
>> taken, but I don't see a good way to do that within the current
>> regression-test infrastructure.
> Have it log something that will appear on the postmaster log but not the
> client log? Buildfarm members mostly post their complete postmaster
> logs, and we could postprocess those.
I've applied a patch along this line --- it'll emit LOG messages like
LOG: wait_for_stats delayed 0.112799018621445 seconds
The patch itself is pretty ugly :-(. I thought at first that we could
just have a plpgsql function loop until it saw a change in the stats,
but that does not work because the backend keeps its stats snapshot
until end of transaction --- so if the stats aren't updated when the
function first looks, they never will appear to. My second try was to
watch the mod timestamp of pgstat.stat, but that didn't work real well
either because it has only one-second resolution. As committed, the
patch is watching for a change in the size of pgstat.stat, which it
forces by making a new table. Ugh. I think it's worth doing as a means
of gathering information about what's happening in the buildfarm, but
I don't really want to leave it there for posterity.
We could make it cleaner by inventing a function to clear out the cached
statistics within a transaction, perhaps "pg_stat_reset_snaphot()" or
some such name. If anyone thinks that that would be of general
usefulness, I'll see about making it happen.
regards, tom lane
-- save current stats-file size
CREATE TEMP TABLE prevfilesize AS SELECT size FROM pg_stat_file('global/pgstat.stat');
-- make and touch a previously nonexistent table
CREATE TABLE stats_hack (f1 int);
SELECT * FROM stats_hack;
-- wait for stats collector to update
create function wait_for_stats() returns void as $$
declare start_time timestamptz := clock_timestamp(); oldsize bigint; newsize bigint;
begin -- fetch previous stats-file size select size into oldsize from prevfilesize;
-- we don't want to wait forever; loop will exit after 30 seconds for i in 1 .. 300 loop
-- look for update of stats file select size into newsize from pg_stat_file('global/pgstat.stat');
exit when newsize != oldsize;
-- wait a little perform pg_sleep(0.1);
end loop;
-- report time waited in postmaster log (where it won't change test output) raise log 'wait_for_stats delayed %
seconds', extract(epoch from clock_timestamp() - start_time);
end
$$ language plpgsql;
SELECT wait_for_stats();
DROP TABLE stats_hack;
Tom Lane wrote: > We could make it cleaner by inventing a function to clear out the cached > statistics within a transaction, perhaps "pg_stat_reset_snaphot()" or > some such name. If anyone thinks that that would be of general > usefulness, I'll see about making it happen. During the development of the launcher/worker autovac separation, I thought a bit about how to handle stats invalidation. The launcher process needs to read the stat file every once in a while, but the worker doesn't care if the stats are very up to date. I came up with the idea of storing the stat hash in a particular memory context, and have a flag in pgstat.c that's reset when that context is reset. So each caller can define what's the appropriate lifetime. In launcher, stats would be reset once every main loop (after which an autovacuum_naptime sleep takes place, which means that the original coding of reading it every autovac iteration is kept). In worker, it's read only once, at the start of the process. And in backends (though I didn't implement it), stats could be stored in TopTransationContext and the flag reset in CommitTransaction and AbortTransaction. It would be quite easy to provide a function to reset stats within a transaction, by having the hash allocated in a context child of TopTransation. One problem is how to make sure that the flag is reset when the context is. If we had "cleanup callbacks" for memory contexts this would be trivial and robust. -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
Alvaro Herrera <alvherre@commandprompt.com> writes:
> Tom Lane wrote:
>> We could make it cleaner by inventing a function to clear out the cached
>> statistics within a transaction, perhaps "pg_stat_reset_snaphot()" or
>> some such name. If anyone thinks that that would be of general
>> usefulness, I'll see about making it happen.
> I came up with the idea of storing the stat hash in a particular memory
> context, and have a flag in pgstat.c that's reset when that context is
> reset. So each caller can define what's the appropriate lifetime.
None of your use-cases require tracking multiple sets of stats within a
transaction, so I don't see why bother with that when we can just add a
"flush the stats" call.
regards, tom lane
Tom Lane wrote: > Alvaro Herrera <alvherre@commandprompt.com> writes: > > Tom Lane wrote: > >> We could make it cleaner by inventing a function to clear out the cached > >> statistics within a transaction, perhaps "pg_stat_reset_snaphot()" or > >> some such name. If anyone thinks that that would be of general > >> usefulness, I'll see about making it happen. > > > I came up with the idea of storing the stat hash in a particular memory > > context, and have a flag in pgstat.c that's reset when that context is > > reset. So each caller can define what's the appropriate lifetime. > > None of your use-cases require tracking multiple sets of stats within a > transaction, so I don't see why bother with that when we can just add a > "flush the stats" call. Yeah, it's the same thing (and simpler), except that you move the responsability of resetting the memory context to pgstats instead of the calling code. In any case, if you were to provide a mechanism for stats flush, autovacuum would have an use case for it, so that's a +1. -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
> Tom Lane wrote: > > None of your use-cases require tracking multiple sets of stats within a > > transaction, so I don't see why bother with that when we can just add a > > "flush the stats" call. FWIW I'm thinking that the corresponding code for handling the backends' stats could be simplified, removing the hack that stores it in TopTransactionContext, and just having a call to the stats flush function in AbortTransaction and CommitTransaction. -- Alvaro Herrera http://www.CommandPrompt.com/ The PostgreSQL Company - Command Prompt, Inc.
Tom Lane wrote: > Andrew Dunstan <andrew@dunslane.net> writes: > > Tom Lane wrote: > >> It'd be interesting to try to gather stats on the length of the delay > >> taken, but I don't see a good way to do that within the current > >> regression-test infrastructure. > > > Have it log something that will appear on the postmaster log but not the > > client log? Buildfarm members mostly post their complete postmaster > > logs, and we could postprocess those. > > I've applied a patch along this line --- it'll emit LOG messages like > > LOG: wait_for_stats delayed 0.112799018621445 seconds Beluga just failed: http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=beluga&dt=2007-02-07%2019:30:01 The delay seems too short though: LOG: wait_for_stats delayed 0.000748 seconds -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
Alvaro Herrera <alvherre@commandprompt.com> writes: > Beluga just failed: > http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=beluga&dt=2007-02-07%2019:30:01 Wow, that is a really interesting failure, because it implies that the stats collector had seen the seqscan report but not the indexscan report: WHERE st.relname='tenk2' AND cl.relname='tenk2'; ?column? | ?column? | ?column? | ?column? ----------+----------+----------+---------- ! t | t | t | t (1 row) SELECT st.heap_blks_read + st.heap_blks_hit >= pr.heap_blks + cl.relpages, --- 105,111 ---- WHERE st.relname='tenk2' AND cl.relname='tenk2'; ?column? | ?column? | ?column? | ?column? ----------+----------+----------+---------- ! t | t | f | f (1 row) SELECT st.heap_blks_read + st.heap_blks_hit >= pr.heap_blks + cl.relpages, I haven't seen that too many times, if at all. > The delay seems too short though: > LOG: wait_for_stats delayed 0.000748 seconds This indicates there wasn't any delay, ie, on the first examination pgstat.stat had a different size from what it had been at the "CREATE TEMP TABLE prevfilesize" command. [ thinks about that for awhile ] Oh, I see the problem: at the instant of checking the file size the first time, the stats collector must have been already in process of writing a new version of the file, which had some but not all of the updates we want. And if that happened to be a different size from the older version, we could fall through the wait as soon as it got installed. So this waiting mechanism isn't good enough: it proves that a new set of stats has been *installed* since we started waiting, but it doesn't provide any guarantee about when the computation of that set started. Back to the drawing board ... If we had the suggested pg_stat_reset_snapshot function, then we could wait until the indexscan count changes from the prior reading, which would provide a more bulletproof synchronization approach. So maybe I should just go do that. I had hoped to find a technique that was potentially backpatchable into at least the last release or two, but maybe there's no chance. regards, tom lane
Alvaro Herrera <alvherre@commandprompt.com> writes:
> FWIW I'm thinking that the corresponding code for handling the backends'
> stats could be simplified, removing the hack that stores it in
> TopTransactionContext, and just having a call to the stats flush
> function in AbortTransaction and CommitTransaction.
Yeah, thanks for the idea. The pgstats code itself is now decoupled
from transaction boundaries. It still has one hack to know that
autovacuum wants to keep its stats for the whole run, but it'll probably
be a lot easier to whack it around the way you want now.
regards, tom lane