Location via proxy:   [ UP ]  
[Report a bug]   [Manage cookies]                
Skip to content

Commit 79b2ee2

Browse files
committed
Add a bit of debug logging to backend_read_statsfile().
This is in hopes of learning more about what causes "pgstat wait timeout" warnings in the buildfarm. This patch should probably be reverted once we've learned what we can. As coded, it will result in regression test "failures" at half the delay that the existing code does, so I expect to see a few more than before.
1 parent 4dab3d5 commit 79b2ee2

File tree

1 file changed

+25
-4
lines changed

1 file changed

+25
-4
lines changed

src/backend/postmaster/pgstat.c

Lines changed: 25 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -3754,8 +3754,10 @@ pgstat_read_statsfile_timestamp(bool permanent, TimestampTz *ts)
37543754
static void
37553755
backend_read_statsfile(void)
37563756
{
3757+
TimestampTz cur_ts;
37573758
TimestampTz min_ts;
37583759
int count;
3760+
int last_delay_errno = 0;
37593761

37603762
/* already read it? */
37613763
if (pgStatDBHash)
@@ -3776,12 +3778,11 @@ backend_read_statsfile(void)
37763778
* PGSTAT_STAT_INTERVAL; and we don't want to lie to the collector about
37773779
* what our cutoff time really is.
37783780
*/
3781+
cur_ts = GetCurrentTimestamp();
37793782
if (IsAutoVacuumWorkerProcess())
3780-
min_ts = TimestampTzPlusMilliseconds(GetCurrentTimestamp(),
3781-
-PGSTAT_RETRY_DELAY);
3783+
min_ts = TimestampTzPlusMilliseconds(cur_ts, -PGSTAT_RETRY_DELAY);
37823784
else
3783-
min_ts = TimestampTzPlusMilliseconds(GetCurrentTimestamp(),
3784-
-PGSTAT_STAT_INTERVAL);
3785+
min_ts = TimestampTzPlusMilliseconds(cur_ts, -PGSTAT_STAT_INTERVAL);
37853786

37863787
/*
37873788
* Loop until fresh enough stats file is available or we ran out of time.
@@ -3798,9 +3799,29 @@ backend_read_statsfile(void)
37983799
file_ts >= min_ts)
37993800
break;
38003801

3802+
/* Make debugging printouts once we've waited unreasonably long */
3803+
if (count >= PGSTAT_POLL_LOOP_COUNT/2)
3804+
{
3805+
TimestampTz now_ts = GetCurrentTimestamp();
3806+
3807+
#ifdef HAVE_INT64_TIMESTAMP
3808+
elog(WARNING, "pgstat waiting for " INT64_FORMAT " usec (%d loops), file timestamp " INT64_FORMAT " target timestamp " INT64_FORMAT " last errno %d",
3809+
now_ts - cur_ts, count,
3810+
file_ts, min_ts,
3811+
last_delay_errno);
3812+
#else
3813+
elog(WARNING, "pgstat waiting for %.6f sec (%d loops), file timestamp %.6f target timestamp %.6f last errno %d",
3814+
now_ts - cur_ts, count,
3815+
file_ts, min_ts,
3816+
last_delay_errno);
3817+
#endif
3818+
}
3819+
38013820
/* Not there or too old, so kick the collector and wait a bit */
3821+
errno = 0;
38023822
pgstat_send_inquiry(min_ts);
38033823
pg_usleep(PGSTAT_RETRY_DELAY * 1000L);
3824+
last_delay_errno = errno;
38043825
}
38053826

38063827
if (count >= PGSTAT_POLL_LOOP_COUNT)

0 commit comments

Comments
 (0)