"pgstat wait timeout" warnings
We occasionally see $SUBJECT in the buildfarm, and I've also recently
had reports of them from Red Hat customers. The obvious theory is that
these reflect high load preventing the stats collector from responding,
but it would really take pretty crushing load to make that happen if
there were not anything funny going on.
It struck me just now while reviewing the latch code that pg_usleep
could sleep for less than the expected time if a signal happened, and
if that happened repeatedly for some reason, perhaps the loop could
complete in much less than the nominal time. I'm not sure I believe
that idea either, but anyway I'm feeling motivated to try to gather more
data.
Does anyone have a problem with sticking a lot of debugging printout
into backend_read_statsfile() in HEAD only? I'm envisioning it starting
to dump assorted information including elapsed time, errno values, etc
once the loop counter is more than halfway to expiration, which is
already a situation that we shouldn't see under normal conditions.
regards, tom lane
On 10.08.2011 21:45, Tom Lane wrote:
We occasionally see $SUBJECT in the buildfarm, and I've also recently
had reports of them from Red Hat customers. The obvious theory is that
these reflect high load preventing the stats collector from responding,
but it would really take pretty crushing load to make that happen if
there were not anything funny going on.It struck me just now while reviewing the latch code that pg_usleep
could sleep for less than the expected time if a signal happened, and
if that happened repeatedly for some reason, perhaps the loop could
complete in much less than the nominal time. I'm not sure I believe
that idea either, but anyway I'm feeling motivated to try to gather more
data.
I've also seen this on my laptop occasionally. The most recent case I
remember was when I COPYed a lot of data, so that the harddisk was
really busy. The system was a bit unresponsive anyway, because of all
the I/O happening.
So my theory is that if the I/O is really busy, write() on the stats
file blocks for more than 5 seconds, and you get the timeout.
Does anyone have a problem with sticking a lot of debugging printout
into backend_read_statsfile() in HEAD only? I'm envisioning it starting
to dump assorted information including elapsed time, errno values, etc
once the loop counter is more than halfway to expiration, which is
already a situation that we shouldn't see under normal conditions.
No objections here.
--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com
--On 10. August 2011 21:54:06 +0300 Heikki Linnakangas
<heikki.linnakangas@enterprisedb.com> wrote:
So my theory is that if the I/O is really busy, write() on the stats file
blocks for more than 5 seconds, and you get the timeout.
I've seen it on customer instances with very high INSERT peak loads (several
dozens backends INSERTing/UPDATEing data concurrently). We are using a RAM disk
for stats_temp_directory now for a while, and the timeout never occured again.
--
Thanks
Bernd
On Thursday, August 11, 2011 11:49:12 Bernd Helmle wrote:
--On 10. August 2011 21:54:06 +0300 Heikki Linnakangas
<heikki.linnakangas@enterprisedb.com> wrote:
So my theory is that if the I/O is really busy, write() on the stats
file
blocks for more than 5 seconds, and you get the timeout.I've seen it on customer instances with very high INSERT peak loads (several
dozens backends INSERTing/UPDATEing data concurrently). We are using a RAM
disk for stats_temp_directory now for a while, and the timeout never
occured again.
Yes, I have seen it several times as well. I can actually reproduce it without
much problems, so if you have some idea to test...
I also routinely use stats_temp_directory + tmpfs to solve this (and related
issues). I really think the stats file mechanism should be improved
fundamentally.
Andres
Andres Freund <andres@anarazel.de> writes:
--On 10. August 2011 21:54:06 +0300 Heikki Linnakangas
<heikki.linnakangas@enterprisedb.com> wrote:So my theory is that if the I/O is really busy, write() on the stats file
blocks for more than 5 seconds, and you get the timeout.
Yes, I have seen it several times as well. I can actually reproduce it
without much problems, so if you have some idea to test...
It doesn't surprise me that it's possible to reproduce it under extreme
I/O load. What I am wondering about is whether there's some bug/effect
that allows it to happen without that.
regards, tom lane
On Thu, Aug 11, 2011 at 10:30 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Andres Freund <andres@anarazel.de> writes:
--On 10. August 2011 21:54:06 +0300 Heikki Linnakangas
<heikki.linnakangas@enterprisedb.com> wrote:So my theory is that if the I/O is really busy, write() on the stats file
blocks for more than 5 seconds, and you get the timeout.Yes, I have seen it several times as well. I can actually reproduce it
without much problems, so if you have some idea to test...It doesn't surprise me that it's possible to reproduce it under extreme
I/O load. What I am wondering about is whether there's some bug/effect
that allows it to happen without that.
I got it several times during a pgbench -i -s 5000 run this morning.
I guess that's a lot of I/O, but I'm not sure I'd refer to one process
filling a table with data as "extreme".
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company