db/pgbackrest
1
0
Fork 0
mirror of https://github.com/pgbackrest/pgbackrest.git synced 2024-12-12 10:04:14 +02:00
Code Issues Releases Activity

Adjust Wait object to be more accurate when nested.

Browse Source 
The prior code gave a "free" extra iteration at the end of the wait, functionality that was copied directly from the equivalent code in Perl. This works and is mostly negligible except when wait loops are nested, in which case outer loops will always run twice even if an inner loop times out, which has a multiplying effect. For example, three nested wait loops with a timeout of three seconds will result in the inner loop being run four times (for a total of twelve seconds) even if it times out each time.

Instead make waitMore() stop exactly when time is up. This makes more sense because a complete failure and timeout of an inner loop means retrying an outer loop is probably a waste of time since that inner loop will likely continue to fail.

Also make waitRemaining() recalculate the remaining time rather than depending on the prior result.

Some tests needed to be adjusted to take into account there being one less loop. In general this led to a simplification of the tests.

Reinit a begin value in the wait unit tests. This is not related to the current change but it does make the time measurements more accurate and less likely to fail on an edge case, which has been observed from time to time.

This change appears to have a benefit for test runtime, which seems plausible especially for nested waits, but a larger sample of CI runs are needed to be sure.
This commit is contained in:
David Steele 2023-09-09 11:22:33 -04:00
parent d57900839a
commit 5314dbffc7
9 changed files with 71 additions and 50 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

68
src/common/wait.c
View File

@ -12,7 +12,6 @@ Object type
***********************************************************************************************************************************/
struct Wait
{
WaitPub pub; // Publicly accessible variables
TimeMSec waitTime; // Total time to wait (in usec)
TimeMSec sleepTime; // Next sleep time (in usec)
TimeMSec sleepPrevTime; // Previous time slept (in usec)
@ -21,7 +20,7 @@ struct Wait
/**********************************************************************************************************************************/
FN_EXTERN Wait *
waitNew(TimeMSec waitTime)
waitNew(const TimeMSec waitTime)
{
FUNCTION_LOG_BEGIN(logLevelTrace);
FUNCTION_LOG_PARAM(TIMEMSEC, waitTime);
@ -33,16 +32,14 @@ waitNew(TimeMSec waitTime)
{
*this = (Wait)
{
.pub =
{
.remainTime = waitTime,
},
.waitTime = waitTime,
};
// Calculate first sleep time -- start with 1/10th of a second for anything >= 1 second
if (this->waitTime >= MSEC_PER_SEC)
{
this->sleepTime = MSEC_PER_SEC / 10;
}
// Unless the wait time is really small -- in that case divide wait time by 10
else
this->sleepTime = this->waitTime / 10;
@ -55,9 +52,34 @@ waitNew(TimeMSec waitTime)
FUNCTION_LOG_RETURN(WAIT, this);
}
/**********************************************************************************************************************************/
FN_EXTERN TimeMSec
waitRemaining(Wait *const this)
{
FUNCTION_TEST_BEGIN();
FUNCTION_TEST_PARAM(WAIT, this);
FUNCTION_TEST_END();
TimeMSec result = 0;
// If any wait time remains
if (this->sleepTime > 0)
{
// Returning remaining time, if any, else set sleepTime to 0 so next call to waitMore will return false
const TimeMSec elapsedTime = timeMSec() - this->beginTime;
if (elapsedTime < this->waitTime)
result = this->waitTime - elapsedTime;
else
this->sleepTime = 0;
}
FUNCTION_TEST_RETURN(TIME_MSEC, result);
}
/**********************************************************************************************************************************/
FN_EXTERN bool
waitMore(Wait *this)
waitMore(Wait *const this)
{
FUNCTION_LOG_BEGIN(logLevelTrace);
FUNCTION_LOG_PARAM(WAIT, this);
@ -70,33 +92,35 @@ waitMore(Wait *this)
// If sleep is 0 then the wait time has already ended
if (this->sleepTime > 0)
{
// Sleep required amount
sleepMSec(this->sleepTime);
// Get the end time
TimeMSec elapsedTime = timeMSec() - this->beginTime;
// Get the elapsed time
const TimeMSec elapsedTime = timeMSec() - this->beginTime;
// Is there more time to go?
if (elapsedTime < this->waitTime)
{
// Calculate sleep time as a sum of current and last (a Fibonacci-type sequence)
TimeMSec sleepNextTime = this->sleepTime + this->sleepPrevTime;
// Calculate remaining sleep time
const TimeMSec remainTime = this->waitTime - elapsedTime;
// Make sure sleep time does not go beyond end time (this won't be negative because of the if condition above)
if (sleepNextTime > this->waitTime - elapsedTime)
sleepNextTime = this->waitTime - elapsedTime;
// Calculate sleep time as a sum of current and last (a Fibonacci-type sequence)
TimeMSec sleepTime = this->sleepTime + this->sleepPrevTime;
// Make sure sleep time does not go beyond remaining time (this won't be negative because of the if condition above)
if (sleepTime > remainTime)
sleepTime = remainTime;
// Sleep required amount
sleepMSec(sleepTime);
// Store new sleep times
this->sleepPrevTime = this->sleepTime;
this->sleepTime = sleepNextTime;
this->pub.remainTime = this->waitTime - elapsedTime;
this->sleepTime = sleepTime;
// Need to wait more
result = true;
}
// Else set sleep to zero so next call will return false
else
this->sleepTime = 0;
// Need to wait more
result = true;
}
FUNCTION_LOG_RETURN(BOOL, result);

11
src/common/wait.h
View File

@ -20,17 +20,8 @@ FN_EXTERN Wait *waitNew(TimeMSec waitTime);
/***********************************************************************************************************************************
Getters/Setters
***********************************************************************************************************************************/
typedef struct WaitPub
{
TimeMSec remainTime; // Wait time remaining (in usec)
} WaitPub;
// How much time is remaining? Recalculated each time waitMore() is called.
FN_INLINE_ALWAYS TimeMSec
waitRemaining(const Wait *const this)
{
return THIS_PUB(Wait)->remainTime;
}
FN_EXTERN TimeMSec waitRemaining(Wait *this);
/***********************************************************************************************************************************
Functions

2
test/src/module/common/execTest.c
View File

@ -95,7 +95,7 @@ testRun(void)
option = strLstNew();
strLstAddZ(option, "2");
TEST_ASSIGN(exec, execNew(STRDEF("sleep"), option, STRDEF("sleep"), 1000), "new sleep exec");
TEST_ASSIGN(exec, execNew(STRDEF("sleep"), option, STRDEF("sleep"), 1500), "new sleep exec");
TEST_RESULT_VOID(execOpen(exec), "open cat exec");
TEST_ERROR(execFreeResource(exec), ExecuteError, "sleep did not exit when expected");

3
test/src/module/common/ioHttpTest.c
View File

@ -306,8 +306,7 @@ testRun(void)
TEST_ERROR_FMT(
httpRequestResponse(httpRequestNewP(client, STRDEF("GET"), STRDEF("/")), false), HostConnectError,
"unable to connect to 'localhost:%u': [111] Connection refused\n"
"[RETRY DETAIL OMITTED]",
"unable to connect to 'localhost:%u': [111] Connection refused",
hrnServerPort(0));
HRN_FORK_BEGIN()

2
test/src/module/common/ioTlsTest.c
View File

@ -388,7 +388,7 @@ testRun(void)
// Connection errors
// -------------------------------------------------------------------------------------------------------------------------
TEST_ASSIGN(
client, tlsClientNewP(sckClientNew(STRDEF("99.99.99.99.99"), 7777, 0, 0), STRDEF("X"), 0, 0, true), "new client");
client, tlsClientNewP(sckClientNew(STRDEF("99.99.99.99.99"), 7777, 0, 0), STRDEF("X"), 100, 0, true), "new client");
TEST_RESULT_STR_Z(ioClientName(client), "99.99.99.99.99:7777", " check name");
TEST_ERROR(
ioClientOpen(client), HostConnectError, "unable to get address for '99.99.99.99.99': [-2] Name or service not known");

16
test/src/module/common/waitTest.c
View File

@ -30,8 +30,20 @@ testRun(void)
TEST_RESULT_BOOL(waitMore(wait), false, " no wait more");
// -------------------------------------------------------------------------------------------------------------------------
TEST_TITLE("100ms using only waitRemaining()");
TEST_ASSIGN(wait, waitNew(100), "new wait");
sleepMSec(100);
TEST_RESULT_UINT(waitRemaining(wait), 0, " check remaining time");
// -------------------------------------------------------------------------------------------------------------------------
TEST_TITLE("200ms wait");
begin = timeMSec();
TEST_ASSIGN(wait, waitNew(200), "new wait = 0.2 sec");
TEST_RESULT_UINT(waitRemaining(wait), 200, " check remaining time");
TEST_RESULT_BOOL(waitRemaining(wait) <= 200, true, " check remaining time upper range");
TEST_RESULT_BOOL(waitRemaining(wait) >= 150, true, " check remaining time lowe range");
TEST_RESULT_UINT(wait->waitTime, 200, " check wait time");
TEST_RESULT_UINT(wait->sleepTime, 20, " check sleep time");
TEST_RESULT_UINT(wait->sleepPrevTime, 0, " check sleep prev time");
@ -47,6 +59,8 @@ testRun(void)
TEST_RESULT_VOID(waitFree(wait), " free wait");
// -------------------------------------------------------------------------------------------------------------------------
TEST_TITLE("1100ms wait");
begin = timeMSec();
TEST_ASSIGN(wait, waitNew(1100), "new wait = 1.1 sec");

8
test/src/module/db/dbTest.c
View File

@ -548,14 +548,14 @@ testRun(void)
// Timeout waiting for sync
HRNPQ_MACRO_REPLAY_TARGET_REACHED_GE_10(2, "5/5", false, "5/3"),
HRNPQ_MACRO_REPLAY_TARGET_REACHED_PROGRESS_GE_10(2, "5/5", false, "5/3", "5/3", false, 250),
HRNPQ_MACRO_REPLAY_TARGET_REACHED_PROGRESS_GE_10(2, "5/5", false, "5/3", "5/3", false, 0),
HRNPQ_MACRO_REPLAY_TARGET_REACHED_PROGRESS_GE_10(2, "5/5", false, "5/3", "5/3", false, 100),
HRNPQ_MACRO_REPLAY_TARGET_REACHED_PROGRESS_GE_10(2, "5/5", false, "5/3", "5/3", false, 100),
// Checkpoint target timeout waiting for sync
HRNPQ_MACRO_REPLAY_TARGET_REACHED_GE_10(2, "5/5", true, "5/5"),
HRNPQ_MACRO_CHECKPOINT(2),
HRNPQ_MACRO_CHECKPOINT_TARGET_REACHED_GE_10(2, "5/5", false, "5/4", 250),
HRNPQ_MACRO_CHECKPOINT_TARGET_REACHED_GE_10(2, "5/5", false, "5/4", 0),
HRNPQ_MACRO_CHECKPOINT_TARGET_REACHED_GE_10(2, "5/5", false, "5/4", 100),
HRNPQ_MACRO_CHECKPOINT_TARGET_REACHED_GE_10(2, "5/5", false, "5/4", 100),
// Wait for standby to sync
HRNPQ_MACRO_REPLAY_TARGET_REACHED_GE_10(2, "5/5", false, "5/3"),

8
test/src/module/postgres/clientTest.c
View File

@ -168,8 +168,6 @@ testRun(void)
{.function = HRNPQ_SENDQUERY, .param = "[\"" TEST_QUERY "\"]", .resultInt = 1},
{.function = HRNPQ_CONSUMEINPUT, .sleep = 600},
{.function = HRNPQ_ISBUSY, .resultInt = 1},
{.function = HRNPQ_CONSUMEINPUT},
{.function = HRNPQ_ISBUSY, .resultInt = 1},
{.function = HRNPQ_GETCANCEL},
{.function = HRNPQ_CANCEL, .resultInt = 1},
{.function = HRNPQ_FREECANCEL},
@ -196,9 +194,9 @@ testRun(void)
harnessPqScriptSet((HarnessPq [])
{
{.function = HRNPQ_SENDQUERY, .param = "[\"" TEST_QUERY "\"]", .resultInt = 1},
{.function = HRNPQ_CONSUMEINPUT, .sleep = 600},
{.function = HRNPQ_CONSUMEINPUT, .sleep = 300},
{.function = HRNPQ_ISBUSY, .resultInt = 1},
{.function = HRNPQ_CONSUMEINPUT},
{.function = HRNPQ_CONSUMEINPUT, .sleep = 300},
{.function = HRNPQ_ISBUSY, .resultInt = 1},
{.function = HRNPQ_GETCANCEL},
{.function = HRNPQ_CANCEL, .resultInt = 0, .resultZ = TEST_PQ_ERROR},
@ -225,8 +223,6 @@ testRun(void)
{.function = HRNPQ_SENDQUERY, .param = "[\"" TEST_QUERY "\"]", .resultInt = 1},
{.function = HRNPQ_CONSUMEINPUT, .sleep = 600},
{.function = HRNPQ_ISBUSY, .resultInt = 1},
{.function = HRNPQ_CONSUMEINPUT},
{.function = HRNPQ_ISBUSY, .resultInt = 1},
{.function = HRNPQ_GETCANCEL, .resultNull = true},
{.function = NULL}
});

3
test/src/module/storage/sftpTest.c
View File

@ -507,9 +507,6 @@ testRun(void)
.resultInt = LIBSSH2_ERROR_SFTP_PROTOCOL},
{.function = HRNLIBSSH2_SFTP_LAST_ERROR, .resultUInt = LIBSSH2_FX_NO_SUCH_FILE},
// Path missing
{.function = HRNLIBSSH2_SFTP_STAT_EX, .param = "[\"" TEST_PATH "/missing\",0]",
.resultInt = LIBSSH2_ERROR_SFTP_PROTOCOL},
{.function = HRNLIBSSH2_SFTP_LAST_ERROR, .resultUInt = LIBSSH2_FX_NO_SUCH_FILE},
{.function = HRNLIBSSH2_SFTP_STAT_EX, .param = "[\"" TEST_PATH "\",0]",
.attrPerms = LIBSSH2_SFTP_S_IFDIR, .resultInt = LIBSSH2_ERROR_NONE},
// Permission denied