public inbox for [email protected]
help / color / mirror / Atom feed[PATCH 2/5] Refactor pg_rewind for more clear decision making.
4+ messages / 3 participants
[nested] [flat]
* [PATCH 2/5] Refactor pg_rewind for more clear decision making.
@ 2020-08-19 12:34 Heikki Linnakangas <[email protected]>
0 siblings, 0 replies; 4+ messages in thread
From: Heikki Linnakangas @ 2020-08-19 12:34 UTC (permalink / raw)
Deciding what to do with each file is now a separate step after all the
necessary information has been gathered. It is more clear that way.
Previously, the decision-making was divided between process_source_file()
and process_target_file(), and it was a bit hard to piece together what the
overall rules were.
---
src/bin/pg_rewind/copy_fetch.c | 14 +-
src/bin/pg_rewind/file_ops.c | 16 +-
src/bin/pg_rewind/filemap.c | 514 ++++++++++++++++----------------
src/bin/pg_rewind/filemap.h | 67 +++--
src/bin/pg_rewind/libpq_fetch.c | 12 +-
src/bin/pg_rewind/parsexlog.c | 2 +-
src/bin/pg_rewind/pg_rewind.c | 8 +-
7 files changed, 332 insertions(+), 301 deletions(-)
diff --git a/src/bin/pg_rewind/copy_fetch.c b/src/bin/pg_rewind/copy_fetch.c
index 1edab5f1867..18fad32600e 100644
--- a/src/bin/pg_rewind/copy_fetch.c
+++ b/src/bin/pg_rewind/copy_fetch.c
@@ -210,7 +210,7 @@ copy_executeFileMap(filemap_t *map)
for (i = 0; i < map->narray; i++)
{
entry = map->array[i];
- execute_pagemap(&entry->pagemap, entry->path);
+ execute_pagemap(&entry->target_modified_pages, entry->path);
switch (entry->action)
{
@@ -219,16 +219,16 @@ copy_executeFileMap(filemap_t *map)
break;
case FILE_ACTION_COPY:
- rewind_copy_file_range(entry->path, 0, entry->newsize, true);
+ rewind_copy_file_range(entry->path, 0, entry->source_size, true);
break;
case FILE_ACTION_TRUNCATE:
- truncate_target_file(entry->path, entry->newsize);
+ truncate_target_file(entry->path, entry->source_size);
break;
case FILE_ACTION_COPY_TAIL:
- rewind_copy_file_range(entry->path, entry->oldsize,
- entry->newsize, false);
+ rewind_copy_file_range(entry->path, entry->target_size,
+ entry->source_size, false);
break;
case FILE_ACTION_CREATE:
@@ -238,6 +238,10 @@ copy_executeFileMap(filemap_t *map)
case FILE_ACTION_REMOVE:
remove_target(entry);
break;
+
+ case FILE_ACTION_UNDECIDED:
+ pg_fatal("no action decided for \"%s\"", entry->path);
+ break;
}
}
diff --git a/src/bin/pg_rewind/file_ops.c b/src/bin/pg_rewind/file_ops.c
index 55439db20ba..ec37d0b2e0d 100644
--- a/src/bin/pg_rewind/file_ops.c
+++ b/src/bin/pg_rewind/file_ops.c
@@ -126,8 +126,9 @@ void
remove_target(file_entry_t *entry)
{
Assert(entry->action == FILE_ACTION_REMOVE);
+ Assert(entry->target_exists);
- switch (entry->type)
+ switch (entry->target_type)
{
case FILE_TYPE_DIRECTORY:
remove_target_dir(entry->path);
@@ -140,6 +141,10 @@ remove_target(file_entry_t *entry)
case FILE_TYPE_SYMLINK:
remove_target_symlink(entry->path);
break;
+
+ case FILE_TYPE_UNDEFINED:
+ pg_fatal("undefined file type for \"%s\"", entry->path);
+ break;
}
}
@@ -147,21 +152,26 @@ void
create_target(file_entry_t *entry)
{
Assert(entry->action == FILE_ACTION_CREATE);
+ Assert(!entry->target_exists);
- switch (entry->type)
+ switch (entry->source_type)
{
case FILE_TYPE_DIRECTORY:
create_target_dir(entry->path);
break;
case FILE_TYPE_SYMLINK:
- create_target_symlink(entry->path, entry->link_target);
+ create_target_symlink(entry->path, entry->source_link_target);
break;
case FILE_TYPE_REGULAR:
/* can't happen. Regular files are created with open_target_file. */
pg_fatal("invalid action (CREATE) for regular file");
break;
+
+ case FILE_TYPE_UNDEFINED:
+ pg_fatal("undefined file type for \"%s\"", entry->path);
+ break;
}
}
diff --git a/src/bin/pg_rewind/filemap.c b/src/bin/pg_rewind/filemap.c
index 1879257b66a..431e8e760e0 100644
--- a/src/bin/pg_rewind/filemap.c
+++ b/src/bin/pg_rewind/filemap.c
@@ -26,6 +26,8 @@ static bool isRelDataFile(const char *path);
static char *datasegpath(RelFileNode rnode, ForkNumber forknum,
BlockNumber segno);
static int path_cmp(const void *a, const void *b);
+
+static file_entry_t *get_filemap_entry(const char *path, bool create);
static int final_filemap_cmp(const void *a, const void *b);
static void filemap_list_to_array(filemap_t *map);
static bool check_file_excluded(const char *path, bool is_source);
@@ -146,6 +148,65 @@ filemap_create(void)
filemap = map;
}
+/* Look up or create entry for 'path' */
+static file_entry_t *
+get_filemap_entry(const char *path, bool create)
+{
+ filemap_t *map = filemap;
+ file_entry_t *entry;
+ file_entry_t **e;
+ file_entry_t key;
+ file_entry_t *key_ptr;
+
+ if (map->array)
+ {
+ key.path = (char *) path;
+ key_ptr = &key;
+ e = bsearch(&key_ptr, map->array, map->narray, sizeof(file_entry_t *),
+ path_cmp);
+ }
+ else
+ e = NULL;
+
+ if (e)
+ entry = *e;
+ else if (!create)
+ entry = NULL;
+ else
+ {
+ /* Create a new entry for this file */
+ entry = pg_malloc(sizeof(file_entry_t));
+ entry->path = pg_strdup(path);
+ entry->isrelfile = isRelDataFile(path);
+ entry->action = FILE_ACTION_UNDECIDED;
+
+ entry->target_exists = false;
+ entry->target_type = FILE_TYPE_UNDEFINED;
+ entry->target_size = 0;
+ entry->target_link_target = NULL;
+ entry->target_modified_pages.bitmap = NULL;
+ entry->target_modified_pages.bitmapsize = 0;
+
+ entry->source_exists = false;
+ entry->source_type = FILE_TYPE_UNDEFINED;
+ entry->source_size = 0;
+ entry->source_link_target = NULL;
+
+ entry->next = NULL;
+
+ if (map->last)
+ {
+ map->last->next = entry;
+ map->last = entry;
+ }
+ else
+ map->first = map->last = entry;
+ map->nlist++;
+ }
+
+ return entry;
+}
+
/*
* Callback for processing source file list.
*
@@ -154,18 +215,19 @@ filemap_create(void)
* exists in the target and whether the size matches.
*/
void
-process_source_file(const char *path, file_type_t type, size_t newsize,
+process_source_file(const char *path, file_type_t type, size_t size,
const char *link_target)
{
- bool exists;
- char localpath[MAXPGPATH];
- struct stat statbuf;
- filemap_t *map = filemap;
- file_action_t action = FILE_ACTION_NONE;
- size_t oldsize = 0;
file_entry_t *entry;
- Assert(map->array == NULL);
+ Assert(filemap->array == NULL);
+
+ /*
+ * Skip the control file. It is handled specially, after copying all the
+ * other files.
+ */
+ if (strcmp(path, "global/pg_control") == 0)
+ return;
/*
* Skip any files matching the exclusion filters. This has the effect to
@@ -199,142 +261,12 @@ process_source_file(const char *path, file_type_t type, size_t newsize,
if (type != FILE_TYPE_REGULAR && isRelDataFile(path))
pg_fatal("data file \"%s\" in source is not a regular file", path);
- snprintf(localpath, sizeof(localpath), "%s/%s", datadir_target, path);
-
- /* Does the corresponding file exist in the target data dir? */
- if (lstat(localpath, &statbuf) < 0)
- {
- if (errno != ENOENT)
- pg_fatal("could not stat file \"%s\": %m",
- localpath);
-
- exists = false;
- }
- else
- exists = true;
-
- switch (type)
- {
- case FILE_TYPE_DIRECTORY:
- if (exists && !S_ISDIR(statbuf.st_mode) && strcmp(path, "pg_wal") != 0)
- {
- /* it's a directory in source, but not in target. Strange.. */
- pg_fatal("\"%s\" is not a directory", localpath);
- }
-
- if (!exists)
- action = FILE_ACTION_CREATE;
- else
- action = FILE_ACTION_NONE;
- oldsize = 0;
- break;
-
- case FILE_TYPE_SYMLINK:
- if (exists &&
-#ifndef WIN32
- !S_ISLNK(statbuf.st_mode)
-#else
- !pgwin32_is_junction(localpath)
-#endif
- )
- {
- /*
- * It's a symbolic link in source, but not in target.
- * Strange..
- */
- pg_fatal("\"%s\" is not a symbolic link", localpath);
- }
-
- if (!exists)
- action = FILE_ACTION_CREATE;
- else
- action = FILE_ACTION_NONE;
- oldsize = 0;
- break;
-
- case FILE_TYPE_REGULAR:
- if (exists && !S_ISREG(statbuf.st_mode))
- pg_fatal("\"%s\" is not a regular file", localpath);
-
- if (!exists || !isRelDataFile(path))
- {
- /*
- * File exists in source, but not in target. Or it's a
- * non-data file that we have no special processing for. Copy
- * it in toto.
- *
- * An exception: PG_VERSIONs should be identical, but avoid
- * overwriting it for paranoia.
- */
- if (pg_str_endswith(path, "PG_VERSION"))
- {
- action = FILE_ACTION_NONE;
- oldsize = statbuf.st_size;
- }
- else
- {
- action = FILE_ACTION_COPY;
- oldsize = 0;
- }
- }
- else
- {
- /*
- * It's a data file that exists in both.
- *
- * If it's larger in target, we can truncate it. There will
- * also be a WAL record of the truncation in the source
- * system, so WAL replay would eventually truncate the target
- * too, but we might as well do it now.
- *
- * If it's smaller in the target, it means that it has been
- * truncated in the target, or enlarged in the source, or
- * both. If it was truncated in the target, we need to copy
- * the missing tail from the source system. If it was enlarged
- * in the source system, there will be WAL records in the
- * source system for the new blocks, so we wouldn't need to
- * copy them here. But we don't know which scenario we're
- * dealing with, and there's no harm in copying the missing
- * blocks now, so do it now.
- *
- * If it's the same size, do nothing here. Any blocks modified
- * in the target will be copied based on parsing the target
- * system's WAL, and any blocks modified in the source will be
- * updated after rewinding, when the source system's WAL is
- * replayed.
- */
- oldsize = statbuf.st_size;
- if (oldsize < newsize)
- action = FILE_ACTION_COPY_TAIL;
- else if (oldsize > newsize)
- action = FILE_ACTION_TRUNCATE;
- else
- action = FILE_ACTION_NONE;
- }
- break;
- }
-
- /* Create a new entry for this file */
- entry = pg_malloc(sizeof(file_entry_t));
- entry->path = pg_strdup(path);
- entry->type = type;
- entry->action = action;
- entry->oldsize = oldsize;
- entry->newsize = newsize;
- entry->link_target = link_target ? pg_strdup(link_target) : NULL;
- entry->next = NULL;
- entry->pagemap.bitmap = NULL;
- entry->pagemap.bitmapsize = 0;
- entry->isrelfile = isRelDataFile(path);
-
- if (map->last)
- {
- map->last->next = entry;
- map->last = entry;
- }
- else
- map->first = map->last = entry;
- map->nlist++;
+ /* Remember this source file */
+ entry = get_filemap_entry(path, true);
+ entry->source_exists = true;
+ entry->source_type = type;
+ entry->source_size = size;
+ entry->source_link_target = link_target ? pg_strdup(link_target) : NULL;
}
/*
@@ -345,33 +277,24 @@ process_source_file(const char *path, file_type_t type, size_t newsize,
* deletion.
*/
void
-process_target_file(const char *path, file_type_t type, size_t oldsize,
+process_target_file(const char *path, file_type_t type, size_t size,
const char *link_target)
{
- bool exists;
- char localpath[MAXPGPATH];
- struct stat statbuf;
- file_entry_t key;
- file_entry_t *key_ptr;
filemap_t *map = filemap;
file_entry_t *entry;
+ /*
+ * Skip the control file. It is handled specially, after copying all the
+ * other files.
+ */
+ if (strcmp(path, "global/pg_control") == 0)
+ return;
+
/*
* Do not apply any exclusion filters here. This has advantage to remove
* from the target data folder all paths which have been filtered out from
* the source data folder when processing the source files.
*/
-
- snprintf(localpath, sizeof(localpath), "%s/%s", datadir_target, path);
- if (lstat(localpath, &statbuf) < 0)
- {
- if (errno != ENOENT)
- pg_fatal("could not stat file \"%s\": %m",
- localpath);
-
- exists = false;
- }
-
if (map->array == NULL)
{
/* on first call, initialize lookup array */
@@ -389,120 +312,76 @@ process_target_file(const char *path, file_type_t type, size_t oldsize,
}
/*
- * Like in process_source_file, pretend that xlog is always a directory.
+ * Like in process_source_file, pretend that pg_wal is always a directory.
*/
if (strcmp(path, "pg_wal") == 0 && type == FILE_TYPE_SYMLINK)
type = FILE_TYPE_DIRECTORY;
- key.path = (char *) path;
- key_ptr = &key;
- exists = (bsearch(&key_ptr, map->array, map->narray, sizeof(file_entry_t *),
- path_cmp) != NULL);
-
- /* Remove any file or folder that doesn't exist in the source system. */
- if (!exists)
- {
- entry = pg_malloc(sizeof(file_entry_t));
- entry->path = pg_strdup(path);
- entry->type = type;
- entry->action = FILE_ACTION_REMOVE;
- entry->oldsize = oldsize;
- entry->newsize = 0;
- entry->link_target = link_target ? pg_strdup(link_target) : NULL;
- entry->next = NULL;
- entry->pagemap.bitmap = NULL;
- entry->pagemap.bitmapsize = 0;
- entry->isrelfile = isRelDataFile(path);
-
- if (map->last == NULL)
- map->first = entry;
- else
- map->last->next = entry;
- map->last = entry;
- map->nlist++;
- }
- else
- {
- /*
- * We already handled all files that exist in the source system in
- * process_source_file().
- */
- }
+ /* Remember this target file */
+ entry = get_filemap_entry(path, true);
+ entry->target_exists = true;
+ entry->target_type = type;
+ entry->target_size = size;
+ entry->target_link_target = link_target ? pg_strdup(link_target) : NULL;
}
/*
* This callback gets called while we read the WAL in the target, for every
- * block that have changed in the target system. It makes note of all the
+ * block that have changed in the target system. It makes note of all the
* changed blocks in the pagemap of the file.
+ *
+ * NOTE: All the files on both systems must have already been added to the
+ * file map!
*/
void
-process_block_change(ForkNumber forknum, RelFileNode rnode, BlockNumber blkno)
+process_target_wal_block_change(ForkNumber forknum, RelFileNode rnode,
+ BlockNumber blkno)
{
char *path;
- file_entry_t key;
- file_entry_t *key_ptr;
file_entry_t *entry;
BlockNumber blkno_inseg;
int segno;
- filemap_t *map = filemap;
- file_entry_t **e;
- Assert(map->array);
+ Assert(filemap->array);
segno = blkno / RELSEG_SIZE;
blkno_inseg = blkno % RELSEG_SIZE;
path = datasegpath(rnode, forknum, segno);
-
- key.path = (char *) path;
- key_ptr = &key;
-
- e = bsearch(&key_ptr, map->array, map->narray, sizeof(file_entry_t *),
- path_cmp);
- if (e)
- entry = *e;
- else
- entry = NULL;
+ entry = get_filemap_entry(path, false);
pfree(path);
if (entry)
{
+ int64 end_offset;
+
Assert(entry->isrelfile);
- switch (entry->action)
- {
- case FILE_ACTION_NONE:
- case FILE_ACTION_TRUNCATE:
- /* skip if we're truncating away the modified block anyway */
- if ((blkno_inseg + 1) * BLCKSZ <= entry->newsize)
- datapagemap_add(&entry->pagemap, blkno_inseg);
- break;
-
- case FILE_ACTION_COPY_TAIL:
-
- /*
- * skip the modified block if it is part of the "tail" that
- * we're copying anyway.
- */
- if ((blkno_inseg + 1) * BLCKSZ <= entry->oldsize)
- datapagemap_add(&entry->pagemap, blkno_inseg);
- break;
-
- case FILE_ACTION_COPY:
- case FILE_ACTION_REMOVE:
- break;
-
- case FILE_ACTION_CREATE:
- pg_fatal("unexpected page modification for directory or symbolic link \"%s\"", entry->path);
- }
+ if (entry->target_type != FILE_TYPE_REGULAR)
+ pg_fatal("unexpected page modification for directory or symbolic link \"%s\"",
+ entry->path);
+
+ /*
+ * If the block beyond the EOF in the source system, no need to
+ * remember it now, because we're going to truncate it away from the
+ * target anyway. Also no need to remember the block if it's beyond
+ * the current EOF in the target system; we will copy it over with the
+ * "tail" from the source system, anyway.
+ */
+ end_offset = (blkno_inseg + 1) * BLCKSZ;
+ if (end_offset <= entry->source_size &&
+ end_offset <= entry->target_size)
+ datapagemap_add(&entry->target_modified_pages, blkno_inseg);
}
else
{
/*
* If we don't have any record of this file in the file map, it means
- * that it's a relation that doesn't exist in the source system, and
- * it was subsequently removed in the target system, too. We can
- * safely ignore it.
+ * that it's a relation that doesn't exist in the source system. It
+ * could exist in the target system; we haven't moved the target-only
+ * entries from the linked list to the array yet! But in any case, if
+ * it doesn't exist in the source it will be removed from the target
+ * too, and we can safely ignore it.
*/
}
}
@@ -593,16 +472,6 @@ filemap_list_to_array(filemap_t *map)
map->first = map->last = NULL;
}
-void
-filemap_finalize(void)
-{
- filemap_t *map = filemap;
-
- filemap_list_to_array(map);
- qsort(map->array, map->narray, sizeof(file_entry_t *),
- final_filemap_cmp);
-}
-
static const char *
action_to_str(file_action_t action)
{
@@ -643,26 +512,26 @@ calculate_totals(void)
{
entry = map->array[i];
- if (entry->type != FILE_TYPE_REGULAR)
+ if (entry->source_type != FILE_TYPE_REGULAR)
continue;
- map->total_size += entry->newsize;
+ map->total_size += entry->source_size;
if (entry->action == FILE_ACTION_COPY)
{
- map->fetch_size += entry->newsize;
+ map->fetch_size += entry->source_size;
continue;
}
if (entry->action == FILE_ACTION_COPY_TAIL)
- map->fetch_size += (entry->newsize - entry->oldsize);
+ map->fetch_size += (entry->source_size - entry->target_size);
- if (entry->pagemap.bitmapsize > 0)
+ if (entry->target_modified_pages.bitmapsize > 0)
{
datapagemap_iterator_t *iter;
BlockNumber blk;
- iter = datapagemap_iterate(&entry->pagemap);
+ iter = datapagemap_iterate(&entry->target_modified_pages);
while (datapagemap_next(iter, &blk))
map->fetch_size += BLCKSZ;
@@ -682,13 +551,13 @@ print_filemap(void)
{
entry = map->array[i];
if (entry->action != FILE_ACTION_NONE ||
- entry->pagemap.bitmapsize > 0)
+ entry->target_modified_pages.bitmapsize > 0)
{
pg_log_debug("%s (%s)", entry->path,
action_to_str(entry->action));
- if (entry->pagemap.bitmapsize > 0)
- datapagemap_print(&entry->pagemap);
+ if (entry->target_modified_pages.bitmapsize > 0)
+ datapagemap_print(&entry->target_modified_pages);
}
}
fflush(stdout);
@@ -837,3 +706,126 @@ final_filemap_cmp(const void *a, const void *b)
else
return strcmp(fa->path, fb->path);
}
+
+/*
+ * Decide what to do with each file.
+ */
+void
+filemap_finalize()
+{
+ int i;
+
+ filemap_list_to_array(filemap);
+
+ for (i = 0; i < filemap->narray; i++)
+ {
+ file_entry_t *entry = filemap->array[i];
+ file_action_t action;
+
+ if (!entry->target_exists && entry->source_exists)
+ {
+ /*
+ * File exists in source, but not in target. Copy
+ * it in toto. (If it's a relation data file, WAL replay
+ * after rewinding should re-create it anyway. But there's
+ * no harm in copying it now.)
+ */
+ if (entry->source_type == FILE_TYPE_DIRECTORY ||
+ entry->source_type == FILE_TYPE_SYMLINK)
+ {
+ action = FILE_ACTION_CREATE;
+ }
+ else
+ action = FILE_ACTION_COPY;
+ }
+ else if (entry->target_exists && !entry->source_exists)
+ {
+ /* Delete file from target */
+ action = FILE_ACTION_REMOVE;
+ }
+ else if (entry->target_exists && entry->source_exists)
+ {
+ /* File exists in both systems */
+ if (entry->source_type != entry->target_type)
+ {
+ /* But it's a different kind of object. Strange.. */
+ pg_fatal("file \"%s\" is of different type in source and target", entry->path);
+ }
+
+ switch (entry->source_type)
+ {
+ case FILE_TYPE_DIRECTORY:
+ action = FILE_ACTION_NONE;
+ break;
+
+ case FILE_TYPE_SYMLINK:
+ // FIXME: Check if it points to the same target?
+ action = FILE_ACTION_NONE;
+ break;
+
+ case FILE_TYPE_REGULAR:
+ if (!entry->isrelfile)
+ {
+ /*
+ * It's a non-data file that we have no special processing for. Copy
+ * it in toto.
+ *
+ * An exception: PG_VERSIONs should be identical, but avoid
+ * overwriting it for paranoia.
+ */
+ if (!pg_str_endswith(entry->path, "PG_VERSION"))
+ action = FILE_ACTION_COPY;
+ else
+ action = FILE_ACTION_NONE;
+ }
+ else
+ {
+ /*
+ * It's a data file that exists in both systems.
+ *
+ * If it's larger in target, we can truncate it. There will
+ * also be a WAL record of the truncation in the source
+ * system, so WAL replay would eventually truncate the target
+ * too, but we might as well do it now.
+ *
+ * If it's smaller in the target, it means that it has been
+ * truncated in the target, or enlarged in the source, or
+ * both. If it was truncated in the target, we need to copy
+ * the missing tail from the source system. If it was enlarged
+ * in the source system, there will be WAL records in the
+ * source system for the new blocks, so we wouldn't need to
+ * copy them here. But we don't know which scenario we're
+ * dealing with, and there's no harm in copying the missing
+ * blocks now, so do it now.
+ *
+ * If it's the same size, do nothing here. Any blocks modified
+ * in the target will be copied based on parsing the target
+ * system's WAL, and any blocks modified in the source will be
+ * updated after rewinding, when the source system's WAL is
+ * replayed.
+ */
+ if (entry->target_size < entry->source_size)
+ action = FILE_ACTION_COPY_TAIL;
+ else if (entry->target_size > entry->source_size)
+ action = FILE_ACTION_TRUNCATE;
+ else
+ action = FILE_ACTION_NONE;
+ }
+ break;
+ case FILE_TYPE_UNDEFINED:
+ pg_fatal("unknown file type for \"%s\"", entry->path);
+ break;
+ }
+ }
+ else
+ {
+ /* Doesn't exist in either server. Why does it have an entry at all?? */
+ action = FILE_ACTION_NONE;
+ }
+ entry->action = action;
+ }
+
+ /* Sort the actions to the order that they should be performed */
+ qsort(filemap->array, filemap->narray, sizeof(file_entry_t *),
+ final_filemap_cmp);
+}
diff --git a/src/bin/pg_rewind/filemap.h b/src/bin/pg_rewind/filemap.h
index 0cb7425170c..a5e8df57f40 100644
--- a/src/bin/pg_rewind/filemap.h
+++ b/src/bin/pg_rewind/filemap.h
@@ -14,17 +14,21 @@
/*
* For every file found in the local or remote system, we have a file entry
- * which says what we are going to do with the file. For relation files,
- * there is also a page map, marking pages in the file that were changed
- * locally.
- *
- * The enum values are sorted in the order we want actions to be processed.
+ * that contains information about the file on both systems. For relation
+ * files, there is also a page map that marks pages in the file that were
+ * changed in the target after the last common checkpoint. Each entry also
+ * contains an 'action' field, which says what we are going to do with the
+ * file.
*/
+
+/* these enum values are sorted in the order we want actions to be processed */
typedef enum
{
+ FILE_ACTION_UNDECIDED = 0, /* not decided yet */
+
FILE_ACTION_CREATE, /* create local directory or symbolic link */
FILE_ACTION_COPY, /* copy whole file, overwriting if exists */
- FILE_ACTION_COPY_TAIL, /* copy tail from 'oldsize' to 'newsize' */
+ FILE_ACTION_COPY_TAIL, /* copy tail from 'source_size' to 'target_size' */
FILE_ACTION_NONE, /* no action (we might still copy modified
* blocks based on the parsed WAL) */
FILE_ACTION_TRUNCATE, /* truncate local file to 'newsize' bytes */
@@ -33,6 +37,8 @@ typedef enum
typedef enum
{
+ FILE_TYPE_UNDEFINED = 0,
+
FILE_TYPE_REGULAR,
FILE_TYPE_DIRECTORY,
FILE_TYPE_SYMLINK
@@ -41,19 +47,30 @@ typedef enum
typedef struct file_entry_t
{
char *path;
- file_type_t type;
+ bool isrelfile; /* is it a relation data file? */
- file_action_t action;
+ /*
+ * Status of the file in the target.
+ */
+ bool target_exists;
+ file_type_t target_type;
+ size_t target_size; /* for a regular file */
+ char *target_link_target; /* for a symlink */
- /* for a regular file */
- size_t oldsize;
- size_t newsize;
- bool isrelfile; /* is it a relation data file? */
+ datapagemap_t target_modified_pages;
- datapagemap_t pagemap;
+ /*
+ * Status of the file in the source.
+ */
+ bool source_exists;
+ file_type_t source_type;
+ size_t source_size;
+ char *source_link_target; /* for a symlink */
- /* for a symlink */
- char *link_target;
+ /*
+ * What will we do to the file?
+ */
+ file_action_t action;
struct file_entry_t *next;
} file_entry_t;
@@ -70,20 +87,19 @@ typedef struct filemap_t
/*
* After processing all the remote files, the entries in the linked list
- * are moved to this array. After processing local files, too, all the
+ * are moved to this array. After processing local files, too, all the
* local entries are added to the array by filemap_finalize, and sorted in
- * the final order. After filemap_finalize, all the entries are in the
+ * the final order. After filemap_finalize, all the entries are in the
* array, and the linked list is empty.
*/
file_entry_t **array;
int narray; /* current length of array */
/*
- * Summary information. total_size is the total size of the source
- * cluster, and fetch_size is the number of bytes that needs to be copied.
+ * Summary information.
*/
- uint64 total_size;
- uint64 fetch_size;
+ uint64 total_size; /* total size of the source cluster */
+ uint64 fetch_size; /* number of bytes that needs to be copied */
} filemap_t;
extern filemap_t *filemap;
@@ -94,11 +110,12 @@ extern void print_filemap(void);
/* Functions for populating the filemap */
extern void process_source_file(const char *path, file_type_t type,
- size_t newsize, const char *link_target);
+ size_t size, const char *link_target);
extern void process_target_file(const char *path, file_type_t type,
- size_t newsize, const char *link_target);
-extern void process_block_change(ForkNumber forknum, RelFileNode rnode,
- BlockNumber blkno);
+ size_t size, const char *link_target);
+extern void process_target_wal_block_change(ForkNumber forknum,
+ RelFileNode rnode,
+ BlockNumber blkno);
extern void filemap_finalize(void);
#endif /* FILEMAP_H */
diff --git a/src/bin/pg_rewind/libpq_fetch.c b/src/bin/pg_rewind/libpq_fetch.c
index bf4dfc23b96..7fc9161b8c8 100644
--- a/src/bin/pg_rewind/libpq_fetch.c
+++ b/src/bin/pg_rewind/libpq_fetch.c
@@ -465,7 +465,7 @@ libpq_executeFileMap(filemap_t *map)
entry = map->array[i];
/* If this is a relation file, copy the modified blocks */
- execute_pagemap(&entry->pagemap, entry->path);
+ execute_pagemap(&entry->target_modified_pages, entry->path);
switch (entry->action)
{
@@ -476,15 +476,15 @@ libpq_executeFileMap(filemap_t *map)
case FILE_ACTION_COPY:
/* Truncate the old file out of the way, if any */
open_target_file(entry->path, true);
- fetch_file_range(entry->path, 0, entry->newsize);
+ fetch_file_range(entry->path, 0, entry->source_size);
break;
case FILE_ACTION_TRUNCATE:
- truncate_target_file(entry->path, entry->newsize);
+ truncate_target_file(entry->path, entry->source_size);
break;
case FILE_ACTION_COPY_TAIL:
- fetch_file_range(entry->path, entry->oldsize, entry->newsize);
+ fetch_file_range(entry->path, entry->target_size, entry->source_size);
break;
case FILE_ACTION_REMOVE:
@@ -494,6 +494,10 @@ libpq_executeFileMap(filemap_t *map)
case FILE_ACTION_CREATE:
create_target(entry);
break;
+
+ case FILE_ACTION_UNDECIDED:
+ pg_fatal("no action decided for \"%s\"", entry->path);
+ break;
}
}
diff --git a/src/bin/pg_rewind/parsexlog.c b/src/bin/pg_rewind/parsexlog.c
index 2229c86f9af..2baeb74ae93 100644
--- a/src/bin/pg_rewind/parsexlog.c
+++ b/src/bin/pg_rewind/parsexlog.c
@@ -436,6 +436,6 @@ extractPageInfo(XLogReaderState *record)
if (forknum != MAIN_FORKNUM)
continue;
- process_block_change(forknum, rnode, blkno);
+ process_target_wal_block_change(forknum, rnode, blkno);
}
}
diff --git a/src/bin/pg_rewind/pg_rewind.c b/src/bin/pg_rewind/pg_rewind.c
index c9b9e480c0f..210984d302b 100644
--- a/src/bin/pg_rewind/pg_rewind.c
+++ b/src/bin/pg_rewind/pg_rewind.c
@@ -369,7 +369,7 @@ main(int argc, char **argv)
chkpttli);
/*
- * Build the filemap, by comparing the source and target data directories.
+ * Collect information about all files in the target and source systems.
*/
filemap_create();
if (showprogress)
@@ -390,8 +390,12 @@ main(int argc, char **argv)
pg_log_info("reading WAL in target");
extractPageMap(datadir_target, chkptrec, lastcommontliIndex,
ControlFile_target.checkPoint, restore_command);
- filemap_finalize();
+ /*
+ * We have collected all information we need from both systems. Decide
+ * what to do with each file.
+ */
+ filemap_finalize();
if (showprogress)
calculate_totals();
--
2.20.1
--------------D93EDEBFB124D563B723F4BD
Content-Type: text/x-patch; charset=UTF-8;
name="0003-pg_rewind-Replace-the-hybrid-list-array-data-structu.patch"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
filename*0="0003-pg_rewind-Replace-the-hybrid-list-array-data-structu.pa";
filename*1="tch"
^ permalink raw reply [nested|flat] 4+ messages in thread
* Timeout control within tests
@ 2022-02-18 05:28 Noah Misch <[email protected]>
2022-02-18 05:48 ` Re: Timeout control within tests Andres Freund <[email protected]>
0 siblings, 1 reply; 4+ messages in thread
From: Noah Misch @ 2022-02-18 05:28 UTC (permalink / raw)
To: pgsql-hackers
On Fri, Feb 05, 2021 at 03:55:20PM -0500, Tom Lane wrote:
> We have, almost invariably, regretted it when we tried to use short
> timeouts in test cases.
> More generally, sometimes people want to do things like run a test
> under valgrind. So it's not just "underpowered machines" that may
> need a generous timeout. Even if we did reduce the default, I'd
> want a way (probably via an environment variable, cf PGCTLTIMEOUT)
> to kick it back up.
I have a few use cases for that:
1. My buildfarm members have more and more competition for CPU and I/O.
Examples where I suspect animal slowness caused a 180s timeout:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=topminnow&dt=2021-04-11%2003%3A11%3A39
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tern&dt=2021-07-26%2004%3A38%3A29
2. When I'm developing a change and I locally break a test in a way that leads
to a timeout, I like to be able to lower that timeout.
3. I want more tests to use the right timeout from the start. Low-timeout
tests appear at least a few times per year:
d03eeab Mon May 31 00:29:58 2021 -0700 Raise a timeout to 180s, in test 010_logical_decoding_timelines.pl.
388b959 Sat Feb 27 07:02:56 2021 -0800 Raise a timeout to 180s, in contrib/test_decoding.
08dde1b Tue Dec 22 11:10:12 2020 -0500 Increase timeout in 021_row_visibility.pl.
8961355 Sat Apr 25 18:45:27 2020 -0700 Raise a timeout to 180s, in test 003_recovery_targets.pl.
1db439a Mon Dec 10 20:15:42 2018 -0800 Raise some timeouts to 180s, in test code.
I propose to have environment variable PG_TEST_TIMEOUT_DEFAULT control the
timeout used in the places that currently hard-code 180s. TAP tests should
retrieve the value via $PostgreSQL::Test::Utils::timeout_default. pg_regress
tests should retrieve it via \getenv. I would like to back-patch the TAP
part, for cause (1). (The pg_regress part hasn't been a buildfarm problem,
and \getenv is new in v15.) Patches attached. I considered and excluded
other changes, for now:
a. I considered consolidating this with PGISOLATIONTIMEOUT (default 300). One
could remove the older variable entirely or make isolationtester use the
first-available of [PGISOLATIONTIMEOUT, 2 * PG_TEST_TIMEOUT_DEFAULT, 360].
Does anyone have an opinion on what, if anything, to do there?
b. I briefly made stats.sql accept PG_TEST_TIMEOUT_DEFAULT to override its
hard-coded 30s timeout. However, a higher timeout won't help when a UDP
buffer fills. If the test were structured to observe evidence of a vacant
UDP buffer before proceeding with the test stat messages, a higher timeout
could make more sense. I added a comment.
c. One could remove timeout-duration function arguments (e.g. from
pg_recvlogical_upto) and just have the function consult timeout_default.
This felt like highly-optional refactoring.
Author: Noah Misch <[email protected]>
Commit: Noah Misch <[email protected]>
Introduce PG_TEST_TIMEOUT_DEFAULT for TAP suite can't-happen timeouts.
Slow hosts may avoid load-induced, spurious failures by setting
environment variable PG_TEST_TIMEOUT_DEFAULT to some number of seconds
greater than 180. Developers may see faster failures by setting that
environment variable to some lesser number of seconds. In tests, write
$PostgreSQL::Test::Utils::timeout_default wherever the convention has
been to write 180. This change raises the default for some briefer
timeouts. Back-patch to v10 (all supported versions).
Reviewed by FIXME.
Discussion: https://postgr.es/m/FIXME
diff --git a/contrib/amcheck/t/002_cic.pl b/contrib/amcheck/t/002_cic.pl
index d604def..b8e4ac7 100644
--- a/contrib/amcheck/t/002_cic.pl
+++ b/contrib/amcheck/t/002_cic.pl
@@ -18,7 +18,8 @@ my ($node, $result);
#
$node = PostgreSQL::Test::Cluster->new('CIC_test');
$node->init;
-$node->append_conf('postgresql.conf', 'lock_timeout = 180000');
+$node->append_conf('postgresql.conf',
+ 'lock_timeout = ' . (1000 * $PostgreSQL::Test::Utils::timeout_default));
$node->start;
$node->safe_psql('postgres', q(CREATE EXTENSION amcheck));
$node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));
diff --git a/contrib/amcheck/t/003_cic_2pc.pl b/contrib/amcheck/t/003_cic_2pc.pl
index f668ed3..e66ccd9 100644
--- a/contrib/amcheck/t/003_cic_2pc.pl
+++ b/contrib/amcheck/t/003_cic_2pc.pl
@@ -22,7 +22,8 @@ my ($node, $result);
$node = PostgreSQL::Test::Cluster->new('CIC_2PC_test');
$node->init;
$node->append_conf('postgresql.conf', 'max_prepared_transactions = 10');
-$node->append_conf('postgresql.conf', 'lock_timeout = 180000');
+$node->append_conf('postgresql.conf',
+ 'lock_timeout = ' . (1000 * $PostgreSQL::Test::Utils::timeout_default));
$node->start;
$node->safe_psql('postgres', q(CREATE EXTENSION amcheck));
$node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));
@@ -38,7 +39,7 @@ $node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));
my $main_in = '';
my $main_out = '';
-my $main_timer = IPC::Run::timeout(180);
+my $main_timer = IPC::Run::timeout($PostgreSQL::Test::Utils::timeout_default);
my $main_h =
$node->background_psql('postgres', \$main_in, \$main_out,
@@ -52,7 +53,7 @@ pump $main_h until $main_out =~ /syncpoint1/ || $main_timer->is_expired;
my $cic_in = '';
my $cic_out = '';
-my $cic_timer = IPC::Run::timeout(180);
+my $cic_timer = IPC::Run::timeout($PostgreSQL::Test::Utils::timeout_default);
my $cic_h =
$node->background_psql('postgres', \$cic_in, \$cic_out,
$cic_timer, on_error_stop => 1);
@@ -113,9 +114,10 @@ PREPARE TRANSACTION 'persists_forever';
));
$node->restart;
-my $reindex_in = '';
-my $reindex_out = '';
-my $reindex_timer = IPC::Run::timeout(180);
+my $reindex_in = '';
+my $reindex_out = '';
+my $reindex_timer =
+ IPC::Run::timeout($PostgreSQL::Test::Utils::timeout_default);
my $reindex_h =
$node->background_psql('postgres', \$reindex_in, \$reindex_out,
$reindex_timer, on_error_stop => 1);
diff --git a/src/bin/pg_ctl/t/004_logrotate.pl b/src/bin/pg_ctl/t/004_logrotate.pl
index d290452..d73ce03 100644
--- a/src/bin/pg_ctl/t/004_logrotate.pl
+++ b/src/bin/pg_ctl/t/004_logrotate.pl
@@ -39,7 +39,7 @@ sub check_log_pattern
my $node = shift;
my $lfname = fetch_file_name($logfiles, $format);
- my $max_attempts = 180 * 10;
+ my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $logcontents;
for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
@@ -78,7 +78,7 @@ $node->start();
$node->psql('postgres', 'SELECT 1/0');
# might need to retry if logging collector process is slow...
-my $max_attempts = 180 * 10;
+my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $current_logfiles;
for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
diff --git a/src/bin/pg_dump/t/002_pg_dump.pl b/src/bin/pg_dump/t/002_pg_dump.pl
index dd065c7..6906d91 100644
--- a/src/bin/pg_dump/t/002_pg_dump.pl
+++ b/src/bin/pg_dump/t/002_pg_dump.pl
@@ -295,7 +295,8 @@ my %pgdump_runs = (
'--no-sync',
"--file=$tempdir/only_dump_test_table.sql",
'--table=dump_test.test_table',
- '--lock-wait-timeout=1000000',
+ '--lock-wait-timeout='
+ . (1000 * $PostgreSQL::Test::Utils::timeout_default),
'postgres',
],
},
diff --git a/src/bin/psql/t/010_tab_completion.pl b/src/bin/psql/t/010_tab_completion.pl
index 005961f..a549106 100644
--- a/src/bin/psql/t/010_tab_completion.pl
+++ b/src/bin/psql/t/010_tab_completion.pl
@@ -94,7 +94,7 @@ close $FH;
my $in = '';
my $out = '';
-my $timer = timer(5);
+my $timer = timer($PostgreSQL::Test::Utils::timeout_default);
my $h = $node->interactive_psql('postgres', \$in, \$out, $timer);
@@ -111,7 +111,7 @@ sub check_completion
# reset output collector
$out = "";
# restart per-command timer
- $timer->start(5);
+ $timer->start($PostgreSQL::Test::Utils::timeout_default);
# send the data to be sent
$in .= $send;
# wait ...
@@ -442,7 +442,7 @@ check_completion("blarg \t\t", qr//, "check completion failure path");
clear_query();
# send psql an explicit \q to shut it down, else pty won't close properly
-$timer->start(5);
+$timer->start($PostgreSQL::Test::Utils::timeout_default);
$in .= "\\q\n";
finish $h or die "psql returned $?";
$timer->reset;
diff --git a/src/bin/psql/t/020_cancel.pl b/src/bin/psql/t/020_cancel.pl
index 3224f8e..d57d342 100644
--- a/src/bin/psql/t/020_cancel.pl
+++ b/src/bin/psql/t/020_cancel.pl
@@ -46,12 +46,13 @@ SKIP: {
my $psql_pid;
until (-s "$tempdir/psql.pid" and ($psql_pid = PostgreSQL::Test::Utils::slurp_file("$tempdir/psql.pid")) =~ /^\d+\n/s)
{
- ($count++ < 180 * 100) or die "pid file did not appear";
+ ($count++ < 100 * $PostgreSQL::Test::Utils::timeout_default)
+ or die "pid file did not appear";
usleep(10_000)
}
# Send sleep command and wait until the server has registered it
- $stdin = "select pg_sleep(180);\n";
+ $stdin = "select pg_sleep($PostgreSQL::Test::Utils::timeout_default);\n";
pump $h while length $stdin;
$node->poll_query_until('postgres', q{SELECT (SELECT count(*) FROM pg_stat_activity WHERE query ~ '^select pg_sleep') > 0;})
or die "timed out";
diff --git a/src/bin/scripts/t/080_pg_isready.pl b/src/bin/scripts/t/080_pg_isready.pl
index e8436dc..c45ca66 100644
--- a/src/bin/scripts/t/080_pg_isready.pl
+++ b/src/bin/scripts/t/080_pg_isready.pl
@@ -18,8 +18,8 @@ my $node = PostgreSQL::Test::Cluster->new('main');
$node->init;
$node->start;
-# use a long timeout for the benefit of very slow buildfarm machines
-$node->command_ok([qw(pg_isready --timeout=60)],
+$node->command_ok(
+ [ 'pg_isready', "--timeout=$PostgreSQL::Test::Utils::timeout_default" ],
'succeeds with server running');
done_testing();
diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/PostgreSQL/Test/Cluster.pm
index ed70eff..c6fe4ca 100644
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -36,7 +36,8 @@ PostgreSQL::Test::Cluster - class representing PostgreSQL server instance
my ($stdout, $stderr, $timed_out);
my $cmdret = $node->psql('postgres', 'SELECT pg_sleep(600)',
stdout => \$stdout, stderr => \$stderr,
- timeout => 180, timed_out => \$timed_out,
+ timeout => $PostgreSQL::Test::Utils::timeout_default,
+ timed_out => \$timed_out,
extra_params => ['--single-transaction'],
on_error_die => 1)
print "Sleep timed out" if $timed_out;
@@ -1725,7 +1726,8 @@ e.g.
my ($stdout, $stderr, $timed_out);
my $cmdret = $node->psql('postgres', 'SELECT pg_sleep(600)',
stdout => \$stdout, stderr => \$stderr,
- timeout => 180, timed_out => \$timed_out,
+ timeout => $PostgreSQL::Test::Utils::timeout_default,
+ timed_out => \$timed_out,
extra_params => ['--single-transaction'])
will set $cmdret to undef and $timed_out to a true value.
@@ -1905,7 +1907,8 @@ scalar reference. This allows the caller to act on other parts of the system
while idling this backend.
The specified timer object is attached to the harness, as well. It's caller's
-responsibility to select the timeout length, and to restart the timer after
+responsibility to set the timeout length (usually
+$PostgreSQL::Test::Utils::timeout_default), and to restart the timer after
each command if the timeout is per-command.
psql is invoked in tuples-only unaligned mode with reading of B<.psqlrc>
@@ -1993,9 +1996,10 @@ The process's stdin is sourced from the $stdin scalar reference,
and its stdout and stderr go to the $stdout scalar reference.
ptys are used so that psql thinks it's being called interactively.
-The specified timer object is attached to the harness, as well.
-It's caller's responsibility to select the timeout length, and to
-restart the timer after each command if the timeout is per-command.
+The specified timer object is attached to the harness, as well. It's caller's
+responsibility to set the timeout length (usually
+$PostgreSQL::Test::Utils::timeout_default), and to restart the timer after
+each command if the timeout is per-command.
psql is invoked in tuples-only unaligned mode with reading of B<.psqlrc>
disabled. That may be overridden by passing extra psql parameters.
@@ -2311,7 +2315,7 @@ sub connect_fails
Run B<$query> repeatedly, until it returns the B<$expected> result
('t', or SQL boolean true, by default).
Continues polling if B<psql> returns an error result.
-Times out after 180 seconds.
+Times out after $PostgreSQL::Test::Utils::timeout_default seconds.
Returns 1 if successful, 0 if timed out.
=cut
@@ -2329,7 +2333,7 @@ sub poll_query_until
'-d', $self->connstr($dbname)
];
my ($stdout, $stderr);
- my $max_attempts = 180 * 10;
+ my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $attempts = 0;
while ($attempts < $max_attempts)
@@ -2353,8 +2357,8 @@ sub poll_query_until
$attempts++;
}
- # The query result didn't change in 180 seconds. Give up. Print the
- # output from the last attempt, hopefully that's useful for debugging.
+ # Give up. Print the output from the last attempt, hopefully that's useful
+ # for debugging.
diag qq(poll_query_until timed out executing this query:
$query
expecting this output:
@@ -2667,7 +2671,7 @@ sub wait_for_slot_catchup
Waits for the contents of the server log file, starting at the given offset, to
match the supplied regular expression. Checks the entire log if no offset is
-given. Times out after 180 seconds.
+given. Times out after $PostgreSQL::Test::Utils::timeout_default seconds.
If successful, returns the length of the entire log file, in bytes.
@@ -2678,7 +2682,7 @@ sub wait_for_log
my ($self, $regexp, $offset) = @_;
$offset = 0 unless defined $offset;
- my $max_attempts = 180 * 10;
+ my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $attempts = 0;
while ($attempts < $max_attempts)
@@ -2693,7 +2697,6 @@ sub wait_for_log
$attempts++;
}
- # The logs didn't match within 180 seconds. Give up.
croak "timed out waiting for match: $regexp";
}
diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/PostgreSQL/Test/Utils.pm
index 57fcb24..e8bf2e0 100644
--- a/src/test/perl/PostgreSQL/Test/Utils.pm
+++ b/src/test/perl/PostgreSQL/Test/Utils.pm
@@ -91,8 +91,8 @@ our @EXPORT = qw(
$use_unix_sockets
);
-our ($windows_os, $is_msys2, $use_unix_sockets, $tmp_check, $log_path,
- $test_logfile);
+our ($windows_os, $is_msys2, $use_unix_sockets, $timeout_default,
+ $tmp_check, $log_path, $test_logfile);
BEGIN
{
@@ -157,6 +157,10 @@ BEGIN
# supported, but it can be overridden if desired.
$use_unix_sockets =
(!$windows_os || defined $ENV{PG_TEST_USE_UNIX_SOCKETS});
+
+ $timeout_default = $ENV{PG_TEST_TIMEOUT_DEFAULT};
+ $timeout_default = 180
+ if not defined $timeout_default or $timeout_default eq '';
}
=pod
diff --git a/src/test/perl/README b/src/test/perl/README
index 0511c55..4b160cc 100644
--- a/src/test/perl/README
+++ b/src/test/perl/README
@@ -23,6 +23,12 @@ tmp_check/log/ to get more info. Files named 'regress_log_XXX' are log
output from the perl test scripts themselves, and should be examined first.
Other files are postmaster logs, and may be helpful as additional data.
+The tests default to a timeout of 180 seconds for many individual operations.
+Slow hosts may avoid load-induced, spurious failures by setting environment
+variable PG_TEST_TIMEOUT_DEFAULT to some number of seconds greater than 180.
+Developers may see faster failures by setting that environment variable to
+some lesser number of seconds.
+
Data directories will also be left behind for analysis when a test fails;
they are named according to the test filename. But if the environment
variable PG_TEST_NOCLEAN is set, data directories will be retained
diff --git a/src/test/recovery/t/003_recovery_targets.pl b/src/test/recovery/t/003_recovery_targets.pl
index 25dd5ee..e8e1a42 100644
--- a/src/test/recovery/t/003_recovery_targets.pl
+++ b/src/test/recovery/t/003_recovery_targets.pl
@@ -172,8 +172,8 @@ run_log(
$node_standby->logfile, 'start'
]);
-# wait up to 180s for postgres to terminate
-foreach my $i (0 .. 1800)
+# wait for postgres to terminate
+foreach my $i (0 .. 10 * $PostgreSQL::Test::Utils::timeout_default)
{
last if !-f $node_standby->data_dir . '/postmaster.pid';
usleep(100_000);
diff --git a/src/test/recovery/t/006_logical_decoding.pl b/src/test/recovery/t/006_logical_decoding.pl
index fa6bd45..9cec279 100644
--- a/src/test/recovery/t/006_logical_decoding.pl
+++ b/src/test/recovery/t/006_logical_decoding.pl
@@ -107,7 +107,8 @@ $node_primary->safe_psql('postgres',
);
my $stdout_recv = $node_primary->pg_recvlogical_upto(
- 'postgres', 'test_slot', $endpos, 180,
+ 'postgres', 'test_slot', $endpos,
+ $PostgreSQL::Test::Utils::timeout_default,
'include-xids' => '0',
'skip-empty-xacts' => '1');
chomp($stdout_recv);
@@ -119,7 +120,8 @@ $node_primary->poll_query_until('postgres',
) or die "slot never became inactive";
$stdout_recv = $node_primary->pg_recvlogical_upto(
- 'postgres', 'test_slot', $endpos, 180,
+ 'postgres', 'test_slot', $endpos,
+ $PostgreSQL::Test::Utils::timeout_default,
'include-xids' => '0',
'skip-empty-xacts' => '1');
chomp($stdout_recv);
diff --git a/src/test/recovery/t/010_logical_decoding_timelines.pl b/src/test/recovery/t/010_logical_decoding_timelines.pl
index 6e8b0b1..01ff31e 100644
--- a/src/test/recovery/t/010_logical_decoding_timelines.pl
+++ b/src/test/recovery/t/010_logical_decoding_timelines.pl
@@ -157,7 +157,7 @@ like(
($ret, $stdout, $stderr) = $node_replica->psql(
'postgres',
"SELECT data FROM pg_logical_slot_peek_changes('before_basebackup', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');",
- timeout => 180);
+ timeout => $PostgreSQL::Test::Utils::timeout_default);
is($ret, 0, 'replay from slot before_basebackup succeeds');
my $final_expected_output_bb = q(BEGIN
@@ -186,7 +186,7 @@ my $endpos = $node_replica->safe_psql('postgres',
$stdout = $node_replica->pg_recvlogical_upto(
'postgres', 'before_basebackup',
- $endpos, 180,
+ $endpos, $PostgreSQL::Test::Utils::timeout_default,
'include-xids' => '0',
'skip-empty-xacts' => '1');
diff --git a/src/test/recovery/t/013_crash_restart.pl b/src/test/recovery/t/013_crash_restart.pl
index 3b740eb..a0bce59 100644
--- a/src/test/recovery/t/013_crash_restart.pl
+++ b/src/test/recovery/t/013_crash_restart.pl
@@ -18,11 +18,7 @@ use PostgreSQL::Test::Utils;
use Test::More;
use Config;
-# To avoid hanging while expecting some specific input from a psql
-# instance being driven by us, add a timeout high enough that it
-# should never trigger even on very slow machines, unless something
-# is really wrong.
-my $psql_timeout = IPC::Run::timer(60);
+my $psql_timeout = IPC::Run::timer($PostgreSQL::Test::Utils::timeout_default);
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init(allows_streaming => 1);
diff --git a/src/test/recovery/t/017_shm.pl b/src/test/recovery/t/017_shm.pl
index 678a252..f636efc 100644
--- a/src/test/recovery/t/017_shm.pl
+++ b/src/test/recovery/t/017_shm.pl
@@ -132,7 +132,7 @@ my $slow_client = IPC::Run::start(
\$stdout,
'2>',
\$stderr,
- IPC::Run::timeout(900)); # five times the poll_query_until timeout
+ IPC::Run::timeout(5 * $PostgreSQL::Test::Utils::timeout_default));
ok( $gnat->poll_query_until(
'postgres',
"SELECT 1 FROM pg_stat_activity WHERE query = '$slow_query'", '1'),
@@ -143,10 +143,11 @@ $gnat->kill9;
unlink($gnat->data_dir . '/postmaster.pid');
$gnat->rotate_logfile; # on Windows, can't open old log for writing
log_ipcs();
-# Reject ordinary startup. Retry for the same reasons poll_start() does.
+# Reject ordinary startup. Retry for the same reasons poll_start() does,
+# every 0.1s for at least $PostgreSQL::Test::Utils::timeout_default seconds.
my $pre_existing_msg = qr/pre-existing shared memory block/;
{
- my $max_attempts = 180 * 10; # Retry every 0.1s for at least 180s.
+ my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $attempts = 0;
while ($attempts < $max_attempts)
{
@@ -193,7 +194,7 @@ sub poll_start
{
my ($node) = @_;
- my $max_attempts = 180 * 10;
+ my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $attempts = 0;
while ($attempts < $max_attempts)
@@ -209,8 +210,8 @@ sub poll_start
$attempts++;
}
- # No success within 180 seconds. Try one last time without fail_ok, which
- # will BAIL_OUT unless it succeeds.
+ # Try one last time without fail_ok, which will BAIL_OUT unless it
+ # succeeds.
$node->start && return 1;
return 0;
}
diff --git a/src/test/recovery/t/019_replslot_limit.pl b/src/test/recovery/t/019_replslot_limit.pl
index 4257bd4..0da7b83 100644
--- a/src/test/recovery/t/019_replslot_limit.pl
+++ b/src/test/recovery/t/019_replslot_limit.pl
@@ -291,7 +291,7 @@ my @result =
SELECT pg_switch_wal();
CHECKPOINT;
SELECT 'finished';",
- timeout => '60'));
+ timeout => $PostgreSQL::Test::Utils::timeout_default));
is($result[1], 'finished', 'check if checkpoint command is not blocked');
$node_primary2->stop;
@@ -343,7 +343,7 @@ $logstart = get_log_size($node_primary3);
kill 'STOP', $senderpid, $receiverpid;
advance_wal($node_primary3, 2);
-my $max_attempts = 180;
+my $max_attempts = $PostgreSQL::Test::Utils::timeout_default;
while ($max_attempts-- >= 0)
{
if (find_in_log(
@@ -366,7 +366,7 @@ $node_primary3->poll_query_until('postgres',
"lost")
or die "timed out waiting for slot to be lost";
-$max_attempts = 180;
+$max_attempts = $PostgreSQL::Test::Utils::timeout_default;
while ($max_attempts-- >= 0)
{
if (find_in_log(
diff --git a/src/test/recovery/t/021_row_visibility.pl b/src/test/recovery/t/021_row_visibility.pl
index e274351..8d97db5 100644
--- a/src/test/recovery/t/021_row_visibility.pl
+++ b/src/test/recovery/t/021_row_visibility.pl
@@ -32,11 +32,8 @@ $node_standby->init_from_backup($node_primary, $backup_name,
$node_standby->append_conf('postgresql.conf', 'max_prepared_transactions=10');
$node_standby->start;
-# To avoid hanging while expecting some specific input from a psql
-# instance being driven by us, add a timeout high enough that it
-# should never trigger even on very slow machines, unless something
-# is really wrong.
-my $psql_timeout = IPC::Run::timer(300);
+my $psql_timeout =
+ IPC::Run::timer(2 * $PostgreSQL::Test::Utils::timeout_default);
# One psql to primary and standby each, for all queries. That allows
# to check uncommitted changes being replicated and such.
diff --git a/src/test/recovery/t/022_crash_temp_files.pl b/src/test/recovery/t/022_crash_temp_files.pl
index 6ab3092..d295061 100644
--- a/src/test/recovery/t/022_crash_temp_files.pl
+++ b/src/test/recovery/t/022_crash_temp_files.pl
@@ -15,11 +15,7 @@ if ($Config{osname} eq 'MSWin32')
exit;
}
-# To avoid hanging while expecting some specific input from a psql
-# instance being driven by us, add a timeout high enough that it
-# should never trigger even on very slow machines, unless something
-# is really wrong.
-my $psql_timeout = IPC::Run::timer(60);
+my $psql_timeout = IPC::Run::timer($PostgreSQL::Test::Utils::timeout_default);
my $node = PostgreSQL::Test::Cluster->new('node_crash');
$node->init();
diff --git a/src/test/recovery/t/024_archive_recovery.pl b/src/test/recovery/t/024_archive_recovery.pl
index c10bb5b..ce347e0 100644
--- a/src/test/recovery/t/024_archive_recovery.pl
+++ b/src/test/recovery/t/024_archive_recovery.pl
@@ -81,8 +81,8 @@ sub test_recovery_wal_level_minimal
$recovery_node->logfile, 'start'
]);
- # Wait up to 180s for postgres to terminate
- foreach my $i (0 .. 1800)
+ # wait for postgres to terminate
+ foreach my $i (0 .. 10 * $PostgreSQL::Test::Utils::timeout_default)
{
last if !-f $recovery_node->data_dir . '/postmaster.pid';
usleep(100_000);
diff --git a/src/test/subscription/t/015_stream.pl b/src/test/subscription/t/015_stream.pl
index 9f221fc..6561b18 100644
--- a/src/test/subscription/t/015_stream.pl
+++ b/src/test/subscription/t/015_stream.pl
@@ -58,7 +58,7 @@ is($result, qq(2|2|2), 'check initial data was copied to subscriber');
my $in = '';
my $out = '';
-my $timer = IPC::Run::timeout(180);
+my $timer = IPC::Run::timeout($PostgreSQL::Test::Utils::timeout_default);
my $h = $node_publisher->background_psql('postgres', \$in, \$out, $timer,
on_error_stop => 0);
Author: Noah Misch <[email protected]>
Commit: Noah Misch <[email protected]>
Use PG_TEST_TIMEOUT_DEFAULT for pg_regress suite can't-happen timeouts.
Currently, only contrib/test_decoding has this property. Use \getenv to
load the timeout value.
Reviewed by FIXME.
Discussion: https://postgr.es/m/FIXME
diff --git a/contrib/test_decoding/expected/twophase.out b/contrib/test_decoding/expected/twophase.out
index e5e0f96..e89dc74 100644
--- a/contrib/test_decoding/expected/twophase.out
+++ b/contrib/test_decoding/expected/twophase.out
@@ -137,7 +137,10 @@ WHERE locktype = 'relation'
(3 rows)
-- The above CLUSTER command shouldn't cause a timeout on 2pc decoding.
-SET statement_timeout = '180s';
+\set env_timeout ''
+\getenv env_timeout PG_TEST_TIMEOUT_DEFAULT
+SELECT COALESCE(NULLIF(:'env_timeout', ''), '180') || 's' AS timeout \gset
+SET statement_timeout = :'timeout';
SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');
data
---------------------------------------------------------------------------
diff --git a/contrib/test_decoding/sql/twophase.sql b/contrib/test_decoding/sql/twophase.sql
index 05f18e8..aff5114 100644
--- a/contrib/test_decoding/sql/twophase.sql
+++ b/contrib/test_decoding/sql/twophase.sql
@@ -69,7 +69,10 @@ FROM pg_locks
WHERE locktype = 'relation'
AND relation = 'test_prepared1'::regclass;
-- The above CLUSTER command shouldn't cause a timeout on 2pc decoding.
-SET statement_timeout = '180s';
+\set env_timeout ''
+\getenv env_timeout PG_TEST_TIMEOUT_DEFAULT
+SELECT COALESCE(NULLIF(:'env_timeout', ''), '180') || 's' AS timeout \gset
+SET statement_timeout = :'timeout';
SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');
RESET statement_timeout;
COMMIT PREPARED 'test_prepared_lock';
diff --git a/src/test/regress/expected/stats.out b/src/test/regress/expected/stats.out
index 3e9ab09..b7416c8 100644
--- a/src/test/regress/expected/stats.out
+++ b/src/test/regress/expected/stats.out
@@ -34,7 +34,10 @@ declare
updated3 bool;
updated4 bool;
begin
- -- we don't want to wait forever; loop will exit after 30 seconds
+ -- We don't want to wait forever. No timeout suffices if the OS drops our
+ -- stats traffic because an earlier test file left a full UDP buffer.
+ -- Hence, don't use PG_TEST_TIMEOUT_DEFAULT, which may be large for
+ -- can't-happen timeouts. Exit after 30 seconds.
for i in 1 .. 300 loop
-- With parallel query, the seqscan and indexscan on tenk2 might be done
diff --git a/src/test/regress/sql/stats.sql b/src/test/regress/sql/stats.sql
index 82e6f24..dbc2dd2 100644
--- a/src/test/regress/sql/stats.sql
+++ b/src/test/regress/sql/stats.sql
@@ -33,7 +33,10 @@ declare
updated3 bool;
updated4 bool;
begin
- -- we don't want to wait forever; loop will exit after 30 seconds
+ -- We don't want to wait forever. No timeout suffices if the OS drops our
+ -- stats traffic because an earlier test file left a full UDP buffer.
+ -- Hence, don't use PG_TEST_TIMEOUT_DEFAULT, which may be large for
+ -- can't-happen timeouts. Exit after 30 seconds.
for i in 1 .. 300 loop
-- With parallel query, the seqscan and indexscan on tenk2 might be done
Attachments:
[text/plain] tap-timeout-default-var-v1.patch (21.2K, ../../[email protected]/2-tap-timeout-default-var-v1.patch)
download | inline diff:
Author: Noah Misch <[email protected]>
Commit: Noah Misch <[email protected]>
Introduce PG_TEST_TIMEOUT_DEFAULT for TAP suite can't-happen timeouts.
Slow hosts may avoid load-induced, spurious failures by setting
environment variable PG_TEST_TIMEOUT_DEFAULT to some number of seconds
greater than 180. Developers may see faster failures by setting that
environment variable to some lesser number of seconds. In tests, write
$PostgreSQL::Test::Utils::timeout_default wherever the convention has
been to write 180. This change raises the default for some briefer
timeouts. Back-patch to v10 (all supported versions).
Reviewed by FIXME.
Discussion: https://postgr.es/m/FIXME
diff --git a/contrib/amcheck/t/002_cic.pl b/contrib/amcheck/t/002_cic.pl
index d604def..b8e4ac7 100644
--- a/contrib/amcheck/t/002_cic.pl
+++ b/contrib/amcheck/t/002_cic.pl
@@ -18,7 +18,8 @@ my ($node, $result);
#
$node = PostgreSQL::Test::Cluster->new('CIC_test');
$node->init;
-$node->append_conf('postgresql.conf', 'lock_timeout = 180000');
+$node->append_conf('postgresql.conf',
+ 'lock_timeout = ' . (1000 * $PostgreSQL::Test::Utils::timeout_default));
$node->start;
$node->safe_psql('postgres', q(CREATE EXTENSION amcheck));
$node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));
diff --git a/contrib/amcheck/t/003_cic_2pc.pl b/contrib/amcheck/t/003_cic_2pc.pl
index f668ed3..e66ccd9 100644
--- a/contrib/amcheck/t/003_cic_2pc.pl
+++ b/contrib/amcheck/t/003_cic_2pc.pl
@@ -22,7 +22,8 @@ my ($node, $result);
$node = PostgreSQL::Test::Cluster->new('CIC_2PC_test');
$node->init;
$node->append_conf('postgresql.conf', 'max_prepared_transactions = 10');
-$node->append_conf('postgresql.conf', 'lock_timeout = 180000');
+$node->append_conf('postgresql.conf',
+ 'lock_timeout = ' . (1000 * $PostgreSQL::Test::Utils::timeout_default));
$node->start;
$node->safe_psql('postgres', q(CREATE EXTENSION amcheck));
$node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));
@@ -38,7 +39,7 @@ $node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));
my $main_in = '';
my $main_out = '';
-my $main_timer = IPC::Run::timeout(180);
+my $main_timer = IPC::Run::timeout($PostgreSQL::Test::Utils::timeout_default);
my $main_h =
$node->background_psql('postgres', \$main_in, \$main_out,
@@ -52,7 +53,7 @@ pump $main_h until $main_out =~ /syncpoint1/ || $main_timer->is_expired;
my $cic_in = '';
my $cic_out = '';
-my $cic_timer = IPC::Run::timeout(180);
+my $cic_timer = IPC::Run::timeout($PostgreSQL::Test::Utils::timeout_default);
my $cic_h =
$node->background_psql('postgres', \$cic_in, \$cic_out,
$cic_timer, on_error_stop => 1);
@@ -113,9 +114,10 @@ PREPARE TRANSACTION 'persists_forever';
));
$node->restart;
-my $reindex_in = '';
-my $reindex_out = '';
-my $reindex_timer = IPC::Run::timeout(180);
+my $reindex_in = '';
+my $reindex_out = '';
+my $reindex_timer =
+ IPC::Run::timeout($PostgreSQL::Test::Utils::timeout_default);
my $reindex_h =
$node->background_psql('postgres', \$reindex_in, \$reindex_out,
$reindex_timer, on_error_stop => 1);
diff --git a/src/bin/pg_ctl/t/004_logrotate.pl b/src/bin/pg_ctl/t/004_logrotate.pl
index d290452..d73ce03 100644
--- a/src/bin/pg_ctl/t/004_logrotate.pl
+++ b/src/bin/pg_ctl/t/004_logrotate.pl
@@ -39,7 +39,7 @@ sub check_log_pattern
my $node = shift;
my $lfname = fetch_file_name($logfiles, $format);
- my $max_attempts = 180 * 10;
+ my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $logcontents;
for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
@@ -78,7 +78,7 @@ $node->start();
$node->psql('postgres', 'SELECT 1/0');
# might need to retry if logging collector process is slow...
-my $max_attempts = 180 * 10;
+my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $current_logfiles;
for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
diff --git a/src/bin/pg_dump/t/002_pg_dump.pl b/src/bin/pg_dump/t/002_pg_dump.pl
index dd065c7..6906d91 100644
--- a/src/bin/pg_dump/t/002_pg_dump.pl
+++ b/src/bin/pg_dump/t/002_pg_dump.pl
@@ -295,7 +295,8 @@ my %pgdump_runs = (
'--no-sync',
"--file=$tempdir/only_dump_test_table.sql",
'--table=dump_test.test_table',
- '--lock-wait-timeout=1000000',
+ '--lock-wait-timeout='
+ . (1000 * $PostgreSQL::Test::Utils::timeout_default),
'postgres',
],
},
diff --git a/src/bin/psql/t/010_tab_completion.pl b/src/bin/psql/t/010_tab_completion.pl
index 005961f..a549106 100644
--- a/src/bin/psql/t/010_tab_completion.pl
+++ b/src/bin/psql/t/010_tab_completion.pl
@@ -94,7 +94,7 @@ close $FH;
my $in = '';
my $out = '';
-my $timer = timer(5);
+my $timer = timer($PostgreSQL::Test::Utils::timeout_default);
my $h = $node->interactive_psql('postgres', \$in, \$out, $timer);
@@ -111,7 +111,7 @@ sub check_completion
# reset output collector
$out = "";
# restart per-command timer
- $timer->start(5);
+ $timer->start($PostgreSQL::Test::Utils::timeout_default);
# send the data to be sent
$in .= $send;
# wait ...
@@ -442,7 +442,7 @@ check_completion("blarg \t\t", qr//, "check completion failure path");
clear_query();
# send psql an explicit \q to shut it down, else pty won't close properly
-$timer->start(5);
+$timer->start($PostgreSQL::Test::Utils::timeout_default);
$in .= "\\q\n";
finish $h or die "psql returned $?";
$timer->reset;
diff --git a/src/bin/psql/t/020_cancel.pl b/src/bin/psql/t/020_cancel.pl
index 3224f8e..d57d342 100644
--- a/src/bin/psql/t/020_cancel.pl
+++ b/src/bin/psql/t/020_cancel.pl
@@ -46,12 +46,13 @@ SKIP: {
my $psql_pid;
until (-s "$tempdir/psql.pid" and ($psql_pid = PostgreSQL::Test::Utils::slurp_file("$tempdir/psql.pid")) =~ /^\d+\n/s)
{
- ($count++ < 180 * 100) or die "pid file did not appear";
+ ($count++ < 100 * $PostgreSQL::Test::Utils::timeout_default)
+ or die "pid file did not appear";
usleep(10_000)
}
# Send sleep command and wait until the server has registered it
- $stdin = "select pg_sleep(180);\n";
+ $stdin = "select pg_sleep($PostgreSQL::Test::Utils::timeout_default);\n";
pump $h while length $stdin;
$node->poll_query_until('postgres', q{SELECT (SELECT count(*) FROM pg_stat_activity WHERE query ~ '^select pg_sleep') > 0;})
or die "timed out";
diff --git a/src/bin/scripts/t/080_pg_isready.pl b/src/bin/scripts/t/080_pg_isready.pl
index e8436dc..c45ca66 100644
--- a/src/bin/scripts/t/080_pg_isready.pl
+++ b/src/bin/scripts/t/080_pg_isready.pl
@@ -18,8 +18,8 @@ my $node = PostgreSQL::Test::Cluster->new('main');
$node->init;
$node->start;
-# use a long timeout for the benefit of very slow buildfarm machines
-$node->command_ok([qw(pg_isready --timeout=60)],
+$node->command_ok(
+ [ 'pg_isready', "--timeout=$PostgreSQL::Test::Utils::timeout_default" ],
'succeeds with server running');
done_testing();
diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/PostgreSQL/Test/Cluster.pm
index ed70eff..c6fe4ca 100644
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -36,7 +36,8 @@ PostgreSQL::Test::Cluster - class representing PostgreSQL server instance
my ($stdout, $stderr, $timed_out);
my $cmdret = $node->psql('postgres', 'SELECT pg_sleep(600)',
stdout => \$stdout, stderr => \$stderr,
- timeout => 180, timed_out => \$timed_out,
+ timeout => $PostgreSQL::Test::Utils::timeout_default,
+ timed_out => \$timed_out,
extra_params => ['--single-transaction'],
on_error_die => 1)
print "Sleep timed out" if $timed_out;
@@ -1725,7 +1726,8 @@ e.g.
my ($stdout, $stderr, $timed_out);
my $cmdret = $node->psql('postgres', 'SELECT pg_sleep(600)',
stdout => \$stdout, stderr => \$stderr,
- timeout => 180, timed_out => \$timed_out,
+ timeout => $PostgreSQL::Test::Utils::timeout_default,
+ timed_out => \$timed_out,
extra_params => ['--single-transaction'])
will set $cmdret to undef and $timed_out to a true value.
@@ -1905,7 +1907,8 @@ scalar reference. This allows the caller to act on other parts of the system
while idling this backend.
The specified timer object is attached to the harness, as well. It's caller's
-responsibility to select the timeout length, and to restart the timer after
+responsibility to set the timeout length (usually
+$PostgreSQL::Test::Utils::timeout_default), and to restart the timer after
each command if the timeout is per-command.
psql is invoked in tuples-only unaligned mode with reading of B<.psqlrc>
@@ -1993,9 +1996,10 @@ The process's stdin is sourced from the $stdin scalar reference,
and its stdout and stderr go to the $stdout scalar reference.
ptys are used so that psql thinks it's being called interactively.
-The specified timer object is attached to the harness, as well.
-It's caller's responsibility to select the timeout length, and to
-restart the timer after each command if the timeout is per-command.
+The specified timer object is attached to the harness, as well. It's caller's
+responsibility to set the timeout length (usually
+$PostgreSQL::Test::Utils::timeout_default), and to restart the timer after
+each command if the timeout is per-command.
psql is invoked in tuples-only unaligned mode with reading of B<.psqlrc>
disabled. That may be overridden by passing extra psql parameters.
@@ -2311,7 +2315,7 @@ sub connect_fails
Run B<$query> repeatedly, until it returns the B<$expected> result
('t', or SQL boolean true, by default).
Continues polling if B<psql> returns an error result.
-Times out after 180 seconds.
+Times out after $PostgreSQL::Test::Utils::timeout_default seconds.
Returns 1 if successful, 0 if timed out.
=cut
@@ -2329,7 +2333,7 @@ sub poll_query_until
'-d', $self->connstr($dbname)
];
my ($stdout, $stderr);
- my $max_attempts = 180 * 10;
+ my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $attempts = 0;
while ($attempts < $max_attempts)
@@ -2353,8 +2357,8 @@ sub poll_query_until
$attempts++;
}
- # The query result didn't change in 180 seconds. Give up. Print the
- # output from the last attempt, hopefully that's useful for debugging.
+ # Give up. Print the output from the last attempt, hopefully that's useful
+ # for debugging.
diag qq(poll_query_until timed out executing this query:
$query
expecting this output:
@@ -2667,7 +2671,7 @@ sub wait_for_slot_catchup
Waits for the contents of the server log file, starting at the given offset, to
match the supplied regular expression. Checks the entire log if no offset is
-given. Times out after 180 seconds.
+given. Times out after $PostgreSQL::Test::Utils::timeout_default seconds.
If successful, returns the length of the entire log file, in bytes.
@@ -2678,7 +2682,7 @@ sub wait_for_log
my ($self, $regexp, $offset) = @_;
$offset = 0 unless defined $offset;
- my $max_attempts = 180 * 10;
+ my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $attempts = 0;
while ($attempts < $max_attempts)
@@ -2693,7 +2697,6 @@ sub wait_for_log
$attempts++;
}
- # The logs didn't match within 180 seconds. Give up.
croak "timed out waiting for match: $regexp";
}
diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/PostgreSQL/Test/Utils.pm
index 57fcb24..e8bf2e0 100644
--- a/src/test/perl/PostgreSQL/Test/Utils.pm
+++ b/src/test/perl/PostgreSQL/Test/Utils.pm
@@ -91,8 +91,8 @@ our @EXPORT = qw(
$use_unix_sockets
);
-our ($windows_os, $is_msys2, $use_unix_sockets, $tmp_check, $log_path,
- $test_logfile);
+our ($windows_os, $is_msys2, $use_unix_sockets, $timeout_default,
+ $tmp_check, $log_path, $test_logfile);
BEGIN
{
@@ -157,6 +157,10 @@ BEGIN
# supported, but it can be overridden if desired.
$use_unix_sockets =
(!$windows_os || defined $ENV{PG_TEST_USE_UNIX_SOCKETS});
+
+ $timeout_default = $ENV{PG_TEST_TIMEOUT_DEFAULT};
+ $timeout_default = 180
+ if not defined $timeout_default or $timeout_default eq '';
}
=pod
diff --git a/src/test/perl/README b/src/test/perl/README
index 0511c55..4b160cc 100644
--- a/src/test/perl/README
+++ b/src/test/perl/README
@@ -23,6 +23,12 @@ tmp_check/log/ to get more info. Files named 'regress_log_XXX' are log
output from the perl test scripts themselves, and should be examined first.
Other files are postmaster logs, and may be helpful as additional data.
+The tests default to a timeout of 180 seconds for many individual operations.
+Slow hosts may avoid load-induced, spurious failures by setting environment
+variable PG_TEST_TIMEOUT_DEFAULT to some number of seconds greater than 180.
+Developers may see faster failures by setting that environment variable to
+some lesser number of seconds.
+
Data directories will also be left behind for analysis when a test fails;
they are named according to the test filename. But if the environment
variable PG_TEST_NOCLEAN is set, data directories will be retained
diff --git a/src/test/recovery/t/003_recovery_targets.pl b/src/test/recovery/t/003_recovery_targets.pl
index 25dd5ee..e8e1a42 100644
--- a/src/test/recovery/t/003_recovery_targets.pl
+++ b/src/test/recovery/t/003_recovery_targets.pl
@@ -172,8 +172,8 @@ run_log(
$node_standby->logfile, 'start'
]);
-# wait up to 180s for postgres to terminate
-foreach my $i (0 .. 1800)
+# wait for postgres to terminate
+foreach my $i (0 .. 10 * $PostgreSQL::Test::Utils::timeout_default)
{
last if !-f $node_standby->data_dir . '/postmaster.pid';
usleep(100_000);
diff --git a/src/test/recovery/t/006_logical_decoding.pl b/src/test/recovery/t/006_logical_decoding.pl
index fa6bd45..9cec279 100644
--- a/src/test/recovery/t/006_logical_decoding.pl
+++ b/src/test/recovery/t/006_logical_decoding.pl
@@ -107,7 +107,8 @@ $node_primary->safe_psql('postgres',
);
my $stdout_recv = $node_primary->pg_recvlogical_upto(
- 'postgres', 'test_slot', $endpos, 180,
+ 'postgres', 'test_slot', $endpos,
+ $PostgreSQL::Test::Utils::timeout_default,
'include-xids' => '0',
'skip-empty-xacts' => '1');
chomp($stdout_recv);
@@ -119,7 +120,8 @@ $node_primary->poll_query_until('postgres',
) or die "slot never became inactive";
$stdout_recv = $node_primary->pg_recvlogical_upto(
- 'postgres', 'test_slot', $endpos, 180,
+ 'postgres', 'test_slot', $endpos,
+ $PostgreSQL::Test::Utils::timeout_default,
'include-xids' => '0',
'skip-empty-xacts' => '1');
chomp($stdout_recv);
diff --git a/src/test/recovery/t/010_logical_decoding_timelines.pl b/src/test/recovery/t/010_logical_decoding_timelines.pl
index 6e8b0b1..01ff31e 100644
--- a/src/test/recovery/t/010_logical_decoding_timelines.pl
+++ b/src/test/recovery/t/010_logical_decoding_timelines.pl
@@ -157,7 +157,7 @@ like(
($ret, $stdout, $stderr) = $node_replica->psql(
'postgres',
"SELECT data FROM pg_logical_slot_peek_changes('before_basebackup', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');",
- timeout => 180);
+ timeout => $PostgreSQL::Test::Utils::timeout_default);
is($ret, 0, 'replay from slot before_basebackup succeeds');
my $final_expected_output_bb = q(BEGIN
@@ -186,7 +186,7 @@ my $endpos = $node_replica->safe_psql('postgres',
$stdout = $node_replica->pg_recvlogical_upto(
'postgres', 'before_basebackup',
- $endpos, 180,
+ $endpos, $PostgreSQL::Test::Utils::timeout_default,
'include-xids' => '0',
'skip-empty-xacts' => '1');
diff --git a/src/test/recovery/t/013_crash_restart.pl b/src/test/recovery/t/013_crash_restart.pl
index 3b740eb..a0bce59 100644
--- a/src/test/recovery/t/013_crash_restart.pl
+++ b/src/test/recovery/t/013_crash_restart.pl
@@ -18,11 +18,7 @@ use PostgreSQL::Test::Utils;
use Test::More;
use Config;
-# To avoid hanging while expecting some specific input from a psql
-# instance being driven by us, add a timeout high enough that it
-# should never trigger even on very slow machines, unless something
-# is really wrong.
-my $psql_timeout = IPC::Run::timer(60);
+my $psql_timeout = IPC::Run::timer($PostgreSQL::Test::Utils::timeout_default);
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init(allows_streaming => 1);
diff --git a/src/test/recovery/t/017_shm.pl b/src/test/recovery/t/017_shm.pl
index 678a252..f636efc 100644
--- a/src/test/recovery/t/017_shm.pl
+++ b/src/test/recovery/t/017_shm.pl
@@ -132,7 +132,7 @@ my $slow_client = IPC::Run::start(
\$stdout,
'2>',
\$stderr,
- IPC::Run::timeout(900)); # five times the poll_query_until timeout
+ IPC::Run::timeout(5 * $PostgreSQL::Test::Utils::timeout_default));
ok( $gnat->poll_query_until(
'postgres',
"SELECT 1 FROM pg_stat_activity WHERE query = '$slow_query'", '1'),
@@ -143,10 +143,11 @@ $gnat->kill9;
unlink($gnat->data_dir . '/postmaster.pid');
$gnat->rotate_logfile; # on Windows, can't open old log for writing
log_ipcs();
-# Reject ordinary startup. Retry for the same reasons poll_start() does.
+# Reject ordinary startup. Retry for the same reasons poll_start() does,
+# every 0.1s for at least $PostgreSQL::Test::Utils::timeout_default seconds.
my $pre_existing_msg = qr/pre-existing shared memory block/;
{
- my $max_attempts = 180 * 10; # Retry every 0.1s for at least 180s.
+ my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $attempts = 0;
while ($attempts < $max_attempts)
{
@@ -193,7 +194,7 @@ sub poll_start
{
my ($node) = @_;
- my $max_attempts = 180 * 10;
+ my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
my $attempts = 0;
while ($attempts < $max_attempts)
@@ -209,8 +210,8 @@ sub poll_start
$attempts++;
}
- # No success within 180 seconds. Try one last time without fail_ok, which
- # will BAIL_OUT unless it succeeds.
+ # Try one last time without fail_ok, which will BAIL_OUT unless it
+ # succeeds.
$node->start && return 1;
return 0;
}
diff --git a/src/test/recovery/t/019_replslot_limit.pl b/src/test/recovery/t/019_replslot_limit.pl
index 4257bd4..0da7b83 100644
--- a/src/test/recovery/t/019_replslot_limit.pl
+++ b/src/test/recovery/t/019_replslot_limit.pl
@@ -291,7 +291,7 @@ my @result =
SELECT pg_switch_wal();
CHECKPOINT;
SELECT 'finished';",
- timeout => '60'));
+ timeout => $PostgreSQL::Test::Utils::timeout_default));
is($result[1], 'finished', 'check if checkpoint command is not blocked');
$node_primary2->stop;
@@ -343,7 +343,7 @@ $logstart = get_log_size($node_primary3);
kill 'STOP', $senderpid, $receiverpid;
advance_wal($node_primary3, 2);
-my $max_attempts = 180;
+my $max_attempts = $PostgreSQL::Test::Utils::timeout_default;
while ($max_attempts-- >= 0)
{
if (find_in_log(
@@ -366,7 +366,7 @@ $node_primary3->poll_query_until('postgres',
"lost")
or die "timed out waiting for slot to be lost";
-$max_attempts = 180;
+$max_attempts = $PostgreSQL::Test::Utils::timeout_default;
while ($max_attempts-- >= 0)
{
if (find_in_log(
diff --git a/src/test/recovery/t/021_row_visibility.pl b/src/test/recovery/t/021_row_visibility.pl
index e274351..8d97db5 100644
--- a/src/test/recovery/t/021_row_visibility.pl
+++ b/src/test/recovery/t/021_row_visibility.pl
@@ -32,11 +32,8 @@ $node_standby->init_from_backup($node_primary, $backup_name,
$node_standby->append_conf('postgresql.conf', 'max_prepared_transactions=10');
$node_standby->start;
-# To avoid hanging while expecting some specific input from a psql
-# instance being driven by us, add a timeout high enough that it
-# should never trigger even on very slow machines, unless something
-# is really wrong.
-my $psql_timeout = IPC::Run::timer(300);
+my $psql_timeout =
+ IPC::Run::timer(2 * $PostgreSQL::Test::Utils::timeout_default);
# One psql to primary and standby each, for all queries. That allows
# to check uncommitted changes being replicated and such.
diff --git a/src/test/recovery/t/022_crash_temp_files.pl b/src/test/recovery/t/022_crash_temp_files.pl
index 6ab3092..d295061 100644
--- a/src/test/recovery/t/022_crash_temp_files.pl
+++ b/src/test/recovery/t/022_crash_temp_files.pl
@@ -15,11 +15,7 @@ if ($Config{osname} eq 'MSWin32')
exit;
}
-# To avoid hanging while expecting some specific input from a psql
-# instance being driven by us, add a timeout high enough that it
-# should never trigger even on very slow machines, unless something
-# is really wrong.
-my $psql_timeout = IPC::Run::timer(60);
+my $psql_timeout = IPC::Run::timer($PostgreSQL::Test::Utils::timeout_default);
my $node = PostgreSQL::Test::Cluster->new('node_crash');
$node->init();
diff --git a/src/test/recovery/t/024_archive_recovery.pl b/src/test/recovery/t/024_archive_recovery.pl
index c10bb5b..ce347e0 100644
--- a/src/test/recovery/t/024_archive_recovery.pl
+++ b/src/test/recovery/t/024_archive_recovery.pl
@@ -81,8 +81,8 @@ sub test_recovery_wal_level_minimal
$recovery_node->logfile, 'start'
]);
- # Wait up to 180s for postgres to terminate
- foreach my $i (0 .. 1800)
+ # wait for postgres to terminate
+ foreach my $i (0 .. 10 * $PostgreSQL::Test::Utils::timeout_default)
{
last if !-f $recovery_node->data_dir . '/postmaster.pid';
usleep(100_000);
diff --git a/src/test/subscription/t/015_stream.pl b/src/test/subscription/t/015_stream.pl
index 9f221fc..6561b18 100644
--- a/src/test/subscription/t/015_stream.pl
+++ b/src/test/subscription/t/015_stream.pl
@@ -58,7 +58,7 @@ is($result, qq(2|2|2), 'check initial data was copied to subscriber');
my $in = '';
my $out = '';
-my $timer = IPC::Run::timeout(180);
+my $timer = IPC::Run::timeout($PostgreSQL::Test::Utils::timeout_default);
my $h = $node_publisher->background_psql('postgres', \$in, \$out, $timer,
on_error_stop => 0);
[text/plain] regress-timeout-default-var-v1.patch (3.3K, ../../[email protected]/3-regress-timeout-default-var-v1.patch)
download | inline diff:
Author: Noah Misch <[email protected]>
Commit: Noah Misch <[email protected]>
Use PG_TEST_TIMEOUT_DEFAULT for pg_regress suite can't-happen timeouts.
Currently, only contrib/test_decoding has this property. Use \getenv to
load the timeout value.
Reviewed by FIXME.
Discussion: https://postgr.es/m/FIXME
diff --git a/contrib/test_decoding/expected/twophase.out b/contrib/test_decoding/expected/twophase.out
index e5e0f96..e89dc74 100644
--- a/contrib/test_decoding/expected/twophase.out
+++ b/contrib/test_decoding/expected/twophase.out
@@ -137,7 +137,10 @@ WHERE locktype = 'relation'
(3 rows)
-- The above CLUSTER command shouldn't cause a timeout on 2pc decoding.
-SET statement_timeout = '180s';
+\set env_timeout ''
+\getenv env_timeout PG_TEST_TIMEOUT_DEFAULT
+SELECT COALESCE(NULLIF(:'env_timeout', ''), '180') || 's' AS timeout \gset
+SET statement_timeout = :'timeout';
SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');
data
---------------------------------------------------------------------------
diff --git a/contrib/test_decoding/sql/twophase.sql b/contrib/test_decoding/sql/twophase.sql
index 05f18e8..aff5114 100644
--- a/contrib/test_decoding/sql/twophase.sql
+++ b/contrib/test_decoding/sql/twophase.sql
@@ -69,7 +69,10 @@ FROM pg_locks
WHERE locktype = 'relation'
AND relation = 'test_prepared1'::regclass;
-- The above CLUSTER command shouldn't cause a timeout on 2pc decoding.
-SET statement_timeout = '180s';
+\set env_timeout ''
+\getenv env_timeout PG_TEST_TIMEOUT_DEFAULT
+SELECT COALESCE(NULLIF(:'env_timeout', ''), '180') || 's' AS timeout \gset
+SET statement_timeout = :'timeout';
SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');
RESET statement_timeout;
COMMIT PREPARED 'test_prepared_lock';
diff --git a/src/test/regress/expected/stats.out b/src/test/regress/expected/stats.out
index 3e9ab09..b7416c8 100644
--- a/src/test/regress/expected/stats.out
+++ b/src/test/regress/expected/stats.out
@@ -34,7 +34,10 @@ declare
updated3 bool;
updated4 bool;
begin
- -- we don't want to wait forever; loop will exit after 30 seconds
+ -- We don't want to wait forever. No timeout suffices if the OS drops our
+ -- stats traffic because an earlier test file left a full UDP buffer.
+ -- Hence, don't use PG_TEST_TIMEOUT_DEFAULT, which may be large for
+ -- can't-happen timeouts. Exit after 30 seconds.
for i in 1 .. 300 loop
-- With parallel query, the seqscan and indexscan on tenk2 might be done
diff --git a/src/test/regress/sql/stats.sql b/src/test/regress/sql/stats.sql
index 82e6f24..dbc2dd2 100644
--- a/src/test/regress/sql/stats.sql
+++ b/src/test/regress/sql/stats.sql
@@ -33,7 +33,10 @@ declare
updated3 bool;
updated4 bool;
begin
- -- we don't want to wait forever; loop will exit after 30 seconds
+ -- We don't want to wait forever. No timeout suffices if the OS drops our
+ -- stats traffic because an earlier test file left a full UDP buffer.
+ -- Hence, don't use PG_TEST_TIMEOUT_DEFAULT, which may be large for
+ -- can't-happen timeouts. Exit after 30 seconds.
for i in 1 .. 300 loop
-- With parallel query, the seqscan and indexscan on tenk2 might be done
^ permalink raw reply [nested|flat] 4+ messages in thread
* Re: Timeout control within tests
2022-02-18 05:28 Timeout control within tests Noah Misch <[email protected]>
@ 2022-02-18 05:48 ` Andres Freund <[email protected]>
2022-02-18 07:19 ` Re: Timeout control within tests Noah Misch <[email protected]>
0 siblings, 1 reply; 4+ messages in thread
From: Andres Freund @ 2022-02-18 05:48 UTC (permalink / raw)
To: Noah Misch <[email protected]>; +Cc: pgsql-hackers
Hi,
On 2022-02-17 21:28:42 -0800, Noah Misch wrote:
> I propose to have environment variable PG_TEST_TIMEOUT_DEFAULT control the
> timeout used in the places that currently hard-code 180s.
Meson's test runner has the concept of a "timeout multiplier" for ways of
running tests. Meson's stuff is about entire tests (i.e. one tap test), so
doesn't apply here, but I wonder if we shouldn't do something similar? That
way we could adjust different timeouts with one setting, instead of many
different fobs to adjust?
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 4+ messages in thread
* Re: Timeout control within tests
2022-02-18 05:28 Timeout control within tests Noah Misch <[email protected]>
2022-02-18 05:48 ` Re: Timeout control within tests Andres Freund <[email protected]>
@ 2022-02-18 07:19 ` Noah Misch <[email protected]>
0 siblings, 0 replies; 4+ messages in thread
From: Noah Misch @ 2022-02-18 07:19 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: pgsql-hackers
On Thu, Feb 17, 2022 at 09:48:25PM -0800, Andres Freund wrote:
> On 2022-02-17 21:28:42 -0800, Noah Misch wrote:
> > I propose to have environment variable PG_TEST_TIMEOUT_DEFAULT control the
> > timeout used in the places that currently hard-code 180s.
>
> Meson's test runner has the concept of a "timeout multiplier" for ways of
> running tests. Meson's stuff is about entire tests (i.e. one tap test), so
> doesn't apply here, but I wonder if we shouldn't do something similar?
Hmmm. It is good if the user can express an intent that continues to make
sense if we change the default timeout. For the buildfarm use case, a
multiplier is moderately better on that axis (PG_TEST_TIMEOUT_MULTIPLIER=100
beats PG_TEST_TIMEOUT_DEFAULT=18000). For the hacker use case, an absolute
value is substantially better on that axis (PG_TEST_TIMEOUT_DEFAULT=3 beats
PG_TEST_TIMEOUT_MULTIPLIER=.016666).
> That
> way we could adjust different timeouts with one setting, instead of many
> different fobs to adjust?
I expect multiplier vs. absolute value doesn't change the expected number of
settings. If this change proceeds, we'd have three: PG_TEST_TIMEOUT_DEFAULT,
PGCTLTIMEOUT, and PGISOLATIONTIMEOUT. PGCTLTIMEOUT is separate for conceptual
reasons, and PGISOLATIONTIMEOUT is separate for historical reasons. There's
little use case for setting them to unequal values. If Meson can pass down
the overall timeout in effect for the test file, we could compute all three
variables from the passed-down value. Orthogonal to Meson, as I mentioned, we
could eliminate PGISOLATIONTIMEOUT.
timeouts.spec used to have substantial timeouts that had to elapse for the
test to pass. (Commit 741d7f1 ended that era.) A multiplier would have been
a good fit for that use case. If a similar test came back, we'd likely want
two multipliers, a low one for elapsing timeouts and a high one for
non-elapsing timeouts. A multiplier of 10-100 is reasonable for non-elapsing
timeouts, with the exact value being irrelevant on the buildfarm. Setting an
elapsing timeout higher than necessary causes measurable waste.
One could argue for offering both a multiplier variable and an absolute-value
variable. If there's just one variable, I think the absolute-value variable
is more compelling, due to the aforementioned hacker use case. What do you
think?
^ permalink raw reply [nested|flat] 4+ messages in thread
end of thread, other threads:[~2022-02-18 07:19 UTC | newest]
Thread overview: 4+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2020-08-19 12:34 [PATCH 2/5] Refactor pg_rewind for more clear decision making. Heikki Linnakangas <[email protected]>
2022-02-18 05:28 Timeout control within tests Noah Misch <[email protected]>
2022-02-18 05:48 ` Re: Timeout control within tests Andres Freund <[email protected]>
2022-02-18 07:19 ` Re: Timeout control within tests Noah Misch <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox