From: Marina Polyakova <m.polyakova@postgrespro.ru>
To: pgsql-hackers@postgresql.org
Cc: Fabien COELHO <coelho@cri.ensmp.fr>
Cc: Alvaro Herrera <alvherre@2ndquadrant.com>
Cc: Ildus Kurbangaliev <i.kurbangaliev@postgrespro.ru>
Cc: Teodor Sigaev <teodor@sigaev.ru>
Subject: Re: [HACKERS] WIP Patch: Pgbench Serialization and deadlock errors
Date: Tue, 07 Aug 2018 13:56:50 +0300
Message-ID: <25d7b1f518c218a8c335bdfc6c858ea1@postgrespro.ru> (raw)
In-Reply-To: <alpine.DEB.2.21.1807121801250.27883@lancre>
References: <20180508193621.dphlgwrd5yz67o2z@alvherre.pgsql>
<0569c5309cf536a839e2a3a1433bd113@postgrespro.ru>
<alpine.DEB.2.21.1807091451520.17811@lancre>
<a6299efa310e1d106144f761259f4fd6@postgrespro.ru>
<alpine.DEB.2.21.1807111435250.27883@lancre>
<976a25a46420c93866ada4051976b1be@postgrespro.ru>
<alpine.DEB.2.21.1807112124210.27883@lancre>
<f153ffd55f481d714ee44afc99ecc67e@postgrespro.ru>
<alpine.DEB.2.21.1807121801250.27883@lancre>
Hello, hackers!
Here there's a tenth version of the patch for error handling and
retrying of transactions with serialization/deadlock failures in pgbench
(based on the commit e0ee93053998b159e395deed7c42e02b1f921552) thanks to
the comments of Fabien Coelho and Alvaro Herrera in this thread.
v10-0001-Pgbench-errors-use-the-RandomState-structure-for.patch
- a patch for the RandomState structure (this is used to reset a
client's random seed during the repeating of transactions after
serialization/deadlock failures).
v10-0002-Pgbench-errors-use-a-separate-function-to-report.patch
- a patch for a separate error reporting function (this is used to
report client failures that do not cause an aborts and this depends on
the level of debugging).
v10-0003-Pgbench-errors-use-the-Variables-structure-for-c.patch
- a patch for the Variables structure (this is used to reset client
variables during the repeating of transactions after
serialization/deadlock failures).
v10-0004-Pgbench-errors-and-serialization-deadlock-retrie.patch
- the main patch for handling client errors and repetition of
transactions with serialization/deadlock failures (see the detailed
description in the file).
As Fabien wrote in [5], some of the new tests were too slow. Earlier on
my laptop they increased the testing time of pgbench from 5.5 seconds to
12.5 seconds. In the new version the testing time of pgbench takes about
7 seconds. These tests include one test for serialization failure and
retry, as well as one test for deadlock failure and retry. Both of them
are in file 001_pgbench_with_server.pl, each test uses only one pgbench
run, they use PL/pgSQL scripts instead of a parallel psql session.
Any suggestions are welcome!
All that was fixed from the previous version:
[1]
https://www.postgresql.org/message-id/alpine.DEB.2.21.1806090810090.5307%40lancre> ISTM that the struct itself does not need a name, ie. "typedef struct {
> ... } RandomState" is enough.
> There could be clear comments, say in the TState and CState structs,
> about
> what randomness is impacted (i.e. script choices, etc.).
> getZipfianRand, computeHarmonicZipfian: The "thread" parameter was
> justified because it was used for two fieds. As the random state is
> separated, I'd suggest that the other argument should be a zipfcache
> pointer.
> While reading your patch, it occurs to me that a run is not
> deterministic
> at the thread level under throttling and sampling, because the random
> state is sollicited differently depending on when transaction ends.
> This
> suggest that maybe each thread random_state use should have its own
> random
> state.
[2]
https://www.postgresql.org/message-id/alpine.DEB.2.21.1806091514060.3655%40lancre> The structure typedef does not need a name. "typedef struct { } V...".
> I tend to disagree with naming things after their type, eg "array". I'd
> suggest "vars" instead. "nvariables" could be "nvars" for consistency
> with
> that and "vars_sorted", and because "foo.variables->nvariables" starts
> looking heavy.
> I'd suggest but "Variables" type declaration just after "Variable" type
> declaration in the file.
[3]
https://www.postgresql.org/message-id/alpine.DEB.2.21.1806100837380.3655%40lancre> The semantics of the existing code is changed, the FATAL levels calls
> abort() and replace existing exit(1) calls. Maybe you want an ERROR
> level as well.
> I do not understand why names are changed, eg ELEVEL_FATAL instead of
> FATAL. ISTM that part of the point of the move would be to be
> homogeneous,
> which suggests that the same names should be reused.
[4]
https://www.postgresql.org/message-id/alpine.DEB.2.21.1807081014260.17811%40lancre> I'd suggest to have just one clean and simple pgbench internal function
> to
> handle errors and possibly exit, debug... Something like
>
> void pgb_error(FATAL, "error %d raised", 12);
>
> Implemented as
>
> void pgb_error(int/enum XXX level, const char * format, ...)
> {
> test level and maybe return immediately (eg debug);
> print to stderr;
> exit/abort/return depending;
> }
[5]
https://www.postgresql.org/message-id/alpine.DEB.2.21.1807091451520.17811%40lancre> Leves ELEVEL_LOG_CLIENT_{FAIL,ABORTED} & LOG_MAIN look unclear to me.
> In particular, the "CLIENT" part is not very useful. If the
> distinction makes sense, I would have kept "LOG" for the initial one
> and
> add other ones for ABORT and PGBENCH, maybe.
> * There are no comments about "retries" in StatData, CState and Command
> structures.
> * Also, for StatData, I would like to understand the logic between cnt,
> skipped, retries, retried, errors, ... so a clear information about the
> expected invariant if any would be welcome. One has to go in the code
> to
> understand how these fields relate one to the other.
> * "errors_in_failed_tx" is some subcounter of "errors", for a special
> case. Why it is there fails me [I finally understood, and I think it
> should be removed, see end of review]. If we wanted to distinguish,
> then
> we should distinguish homogeneously: maybe just count the different
> error
> types, eg have things like "deadlock_errors", "serializable_errors",
> "other_errors", "internal_pgbench_errors" which would be orthogonal one
> to
> the other, and "errors" could be recomputed from these.
> * How "errors" differs from "ecnt" is unclear to me.
> * FailureStatus states are not homogeneously named. I'd suggest to use
> *_FAILURE for all cases. The miscellaneous case should probably be the
> last.
> * I do not understand the comments on CState enum: "First, remember the
> failure
> in CSTATE_FAILURE. Then process other commands of the failed
> transaction if any"
> Why would other commands be processed at all if the transaction is
> aborted?
> For me any error must leads to the rollback and possible retry of the
> transaction.
> ...
> So, for me, the FAILURE state should record/count the failure, then
> skip
> to RETRY if a retry is decided, else proceed to ABORT. Nothing else.
> This is much clearer that way.
>
> Then RETRY should reinstate the global state and proceed to start the
> *first*
> command again.
> * commandFailed: I think that it should be kept much simpler. In
> particular, having errors on errors does not help much: on
> ELEVEL_FATAL,
> it ignores the actual reported error and generates another error of the
> same level, so that the initial issue is hidden. Even if these are
> can't
> happen cases, hidding the origin if it occurs looks unhelpful. Just
> print
> it directly, and maybe abort if you think that it is a can't happen
> case.
> * copyRandomState: just use sizeof(RandomState) instead of making
> assumptions
> about the contents of the struct. Also, this function looks pretty
> useless,
> why not just do a plain assignment?
> * copyVariables: lacks comments to explain that the destination is
> cleaned up
> and so on. The cleanup phase could probaly be in a distinct function,
> so that
> the code would be clearer. Maybe the function variable names are too
> long.
>
> if (current_source->svalue)
>
> in the context of a guard for a strdup, maybe:
>
> if (current_source->svalue != NULL)
> * executeCondition: this hides client automaton state changes which
> were
> clearly visible beforehand in the switch, and the different handling of
> if & elif is also hidden.
>
> I'm against this unnecessary restructuring and to hide such an
> information,
> all state changes should be clearly seen in the state switch so that it
> is
> easier to understand and follow.
>
> I do not see why touching the conditional stack on internal errors
> (evaluateExpr failure) brings anything, the whole transaction will be
> aborted
> anyway.
> The current RETRY state does memory allocations to generate a message
> with buffer allocation and so on. This looks like a costly and useless
> operation. If the user required "retries", then this is normal
> behavior,
> the retries are counted and will be printed out in the final report,
> and there is no point in printing out every single one of them.
> Maybe you want that debugging, but then coslty operations should be
> guarded.
> The number of transactions above the latency limit report can be
> simplified.
> Remove the if and just use one printf f with a %s for the optional
> comment.
> I'm not sure this optional comment is useful there.
> Before the patch, ISTM that all lines relied on one printf. you have
> changed to a style where a collection of printf is used to compose a
> line.
> I'd suggest to keep to the previous one-printf-prints-one-line style,
> where possible.
> You have added 20-columns alignment prints. This looks like too much
> and
> generates much too large lines. Probably 10 (billion) would be enough.
>
> Some people try to parse the output, so it should be deterministic. I'd
> add
> the needed columns always if appropriate (i.e. under retry), even if
> none
> occured.
> * processXactStats: An else is replaced by a detailed stats, with the
> initial
> "no detailed stats" comment kept. The function is called both in the
> thenb
> & else branch. The structure does not make sense anymore. I'm not sure
> this changed was needed.
> * getLatencyUsed: declared "double" so "return 0.0".
> * typo: ruin -> run; probably others, I did not check for them in
> detail.
> On my laptop, tests last 5.5 seconds before the patch, and about 13
> seconds
> after. This is much too large. Pgbench TAP tests do not deserve to take
> over
> twice as much time as before just on this patch.
>
> One reason which explains this large time is there is a new script with
> a
> new created instance. I'd suggest to append tests to the existing 2
> scripts, depending on whether they need a running instance or not.
>
> Secondly, I think that the design of the tests are too heavy. For such
> a
> feature, ISTM enough to check that it works, i.e. one test for
> deadlocks
> (trigger one or a few deadlocks), idem for serializable, maybe idem for
> other errors if any.
>
> The challenge is to do that reliably and efficiently, i.e. so that the
> test does
> not rely on chance and is still quite efficient.
>
> The trick you use is to run an interactive psql in parallel to pgbench
> so as to
> play with concurrent locks. That is interesting, but deserves more
> comments
> and explanatation, eg before the test functions.
>
> Maybe this could be achieved within pgbench by using some wait stuff in
> PL/pgSQL so that concurrent client can wait one another based on data
> in
> unlogged table updated by a CALL within an "embedded" transactions? Not
> sure. ...
>
> Anyway, TAP tests should be much lighter (in total time), and if
> possible
> much simpler.
>
> The latency limit to 900 ms try is a bad idea because it takes a lot of
> time.
> I did such tests before and they were removed by Tom Lane because of
> determinism
> and time issues. I would comment this test out for now.
> Documentation
> ...
> Having the "most important settings" on line 1-6 and 8 (i.e. skipping
> 7) looks
> silly. The important ones should simply be the first ones, and the 8th
> is not
> that important, or it is in 7th position.
>
> I do not understand why there is so much text about in failed sql
> transaction
> stuff, while we are mainly interested in serialization & deadlock
> errors, and
> this only falls in some "other" category. There seems to be more
> details about
> other errors that about deadlocks & serializable errors.
>
> The reporting should focus on what is of interest, either all errors,
> or some
> detailed split of these errors. The documentation should state clearly
> what
> are the counted errors, and then what are their effects on the reported
> stats.
> The "Errors and Serialization/Deadlock Retries" section is a good start
> in that
> direction, but it does not talk about pgbench internal errors (eg
> "cos(true)").
> I think it should more explicit about errors.
>
> Option --max-tries default value should be spelled out in the doc.
[6]
https://www.postgresql.org/message-id/alpine.DEB.2.21.1807111435250.27883%40lancre> So if absolutely necessary, a new option is still better than changing
> --debug syntax. If not necessary, then it is better:-)
> The fact that some data are collected does not mean that they should
> all
> be reported in detail. We can have detailed error count and report the
> sum
> of this errors for instance, or have some more verbose/detailed reports
> as options (eg --latencies does just that).
[7]
https://www.postgresql.org/message-id/20180711180417.3ytmmwmonsr5lra7%40alvherre.pgsql> LGTM, though I'd rename the random_state struct members so that it
> wouldn't look as confusing. Maybe that's just me.
> Please don't allocate Variable structs one by one. First time allocate
> some decent number (say 8) and then enlarge by duplicating size. That
> way you save realloc overhead. We use this technique everywhere else,
> no reason do different here. Other than that, LGTM.
[8]
https://www.postgresql.org/message-id/alpine.DEB.2.21.1807112124210.27883%40lancre> If you really need some complex dynamic buffer, and I would prefer
> that you avoid that, then the fallback is:
>
> if (level >= DEBUG)
> {
> initPQstuff(&msg);
> ...
> pgbench_error(DEBUG, "fixed message... %s\n", msg);
> freePQstuff(&msg);
> }
>
> The point is to avoid building the message with dynamic allocation and
> so
> if in the end it is not used.
--
Marina Polyakova
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
Attachments:download all (4 files, .tar.gz)v10-0001-Pgbench-errors-use-the-RandomState-structure-for.patch (text/x-diff, 10.8K) download
From d71a8157b48880722092e6e747f684fb31d8d019 Mon Sep 17 00:00:00 2001
From: Marina Polyakova <m.polyakova@postgrespro.ru>
Date: Tue, 7 Aug 2018 13:27:21 +0300
Subject: [PATCH v10 1/4] Pgbench errors: use the RandomState structure for
thread/client random seed.
This is most important when it is used to reset a client's random seed during
the repeating of transactions after serialization/deadlock failures.
Use the random state of the client for random functions PGBENCH_RANDOM_* during
the execution of the script. Use the random state of the each thread option (to
choose the script / get the throttle delay / to log with a sample rate) to make
all of them independent of each other and therefore deterministic at the thread
level.
---
src/bin/pgbench/pgbench.c | 104 +++++++++++++++++++++++++++++++++-------------
1 file changed, 74 insertions(+), 30 deletions(-)
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.cindex 41b756c..988e37b 100644--- a/src/bin/pgbench/pgbench.c+++ b/src/bin/pgbench/pgbench.c@@ -251,6 +251,14 @@ typedef struct StatsData
} StatsData;
/*
+ * Data structure for thread/client random seed.+ */+typedef struct+{+ unsigned short xseed[3];+} RandomState;++/*
* Connection state machine states.
*/
typedef enum
@@ -331,6 +339,12 @@ typedef struct
ConnectionStateEnum state; /* state machine's current state. */
ConditionalStack cstack; /* enclosing conditionals state */
+ /*+ * Separate randomness for each client. This is used for random functions+ * PGBENCH_RANDOM_* during the execution of the script.+ */+ RandomState random_state;+
int use_file; /* index in sql_script for this client */
int command; /* command number in script */
@@ -390,7 +404,16 @@ typedef struct
pthread_t thread; /* thread handle */
CState *state; /* array of CState */
int nstate; /* length of state[] */
- unsigned short random_state[3]; /* separate randomness for each thread */++ /*+ * Separate randomness for each thread. Each thread option uses its own+ * random state to make all of them independent of each other and therefore+ * deterministic at the thread level.+ */+ RandomState choose_script_rs; /* random state for selecting a script */+ RandomState throttling_rs; /* random state for transaction throttling */+ RandomState sampling_rs; /* random state for log sampling */+
int64 throttle_trigger; /* previous/next throttling (us) */
FILE *logfile; /* where to log, or NULL */
ZipfCache zipf_cache; /* for thread-safe zipfian random number
@@ -694,7 +717,7 @@ gotdigits:
/* random number generator: uniform distribution from min to max inclusive */
static int64
-getrand(TState *thread, int64 min, int64 max)+getrand(RandomState *random_state, int64 min, int64 max)
{
/*
* Odd coding is so that min and max have approximately the same chance of
@@ -705,7 +728,7 @@ getrand(TState *thread, int64 min, int64 max)
* protected by a mutex, and therefore a bottleneck on machines with many
* CPUs.
*/
- return min + (int64) ((max - min + 1) * pg_erand48(thread->random_state));+ return min + (int64) ((max - min + 1) * pg_erand48(random_state->xseed));
}
/*
@@ -714,7 +737,8 @@ getrand(TState *thread, int64 min, int64 max)
* value is exp(-parameter).
*/
static int64
-getExponentialRand(TState *thread, int64 min, int64 max, double parameter)+getExponentialRand(RandomState *random_state, int64 min, int64 max,+ double parameter)
{
double cut,
uniform,
@@ -724,7 +748,7 @@ getExponentialRand(TState *thread, int64 min, int64 max, double parameter)
Assert(parameter > 0.0);
cut = exp(-parameter);
/* erand in [0, 1), uniform in (0, 1] */
- uniform = 1.0 - pg_erand48(thread->random_state);+ uniform = 1.0 - pg_erand48(random_state->xseed);
/*
* inner expression in (cut, 1] (if parameter > 0), rand in [0, 1)
@@ -737,7 +761,8 @@ getExponentialRand(TState *thread, int64 min, int64 max, double parameter)
/* random number generator: gaussian distribution from min to max inclusive */
static int64
-getGaussianRand(TState *thread, int64 min, int64 max, double parameter)+getGaussianRand(RandomState *random_state, int64 min, int64 max,+ double parameter)
{
double stdev;
double rand;
@@ -765,8 +790,8 @@ getGaussianRand(TState *thread, int64 min, int64 max, double parameter)
* are expected in (0, 1] (see
* https://en.wikipedia.org/wiki/Box-Muller_transform)
*/
- double rand1 = 1.0 - pg_erand48(thread->random_state);- double rand2 = 1.0 - pg_erand48(thread->random_state);+ double rand1 = 1.0 - pg_erand48(random_state->xseed);+ double rand2 = 1.0 - pg_erand48(random_state->xseed);
/* Box-Muller basic form transform */
double var_sqrt = sqrt(-2.0 * log(rand1));
@@ -793,7 +818,7 @@ getGaussianRand(TState *thread, int64 min, int64 max, double parameter)
* will approximate a Poisson distribution centered on the given value.
*/
static int64
-getPoissonRand(TState *thread, int64 center)+getPoissonRand(RandomState *random_state, int64 center)
{
/*
* Use inverse transform sampling to generate a value > 0, such that the
@@ -802,7 +827,7 @@ getPoissonRand(TState *thread, int64 center)
double uniform;
/* erand in [0, 1), uniform in (0, 1] */
- uniform = 1.0 - pg_erand48(thread->random_state);+ uniform = 1.0 - pg_erand48(random_state->xseed);
return (int64) (-log(uniform) * ((double) center) + 0.5);
}
@@ -880,7 +905,7 @@ zipfFindOrCreateCacheCell(ZipfCache *cache, int64 n, double s)
* Luc Devroye, p. 550-551, Springer 1986.
*/
static int64
-computeIterativeZipfian(TState *thread, int64 n, double s)+computeIterativeZipfian(RandomState *random_state, int64 n, double s)
{
double b = pow(2.0, s - 1.0);
double x,
@@ -891,8 +916,8 @@ computeIterativeZipfian(TState *thread, int64 n, double s)
while (true)
{
/* random variates */
- u = pg_erand48(thread->random_state);- v = pg_erand48(thread->random_state);+ u = pg_erand48(random_state->xseed);+ v = pg_erand48(random_state->xseed);
x = floor(pow(u, -1.0 / (s - 1.0)));
@@ -910,10 +935,11 @@ computeIterativeZipfian(TState *thread, int64 n, double s)
* Jim Gray et al, SIGMOD 1994
*/
static int64
-computeHarmonicZipfian(TState *thread, int64 n, double s)+computeHarmonicZipfian(ZipfCache *zipf_cache, RandomState *random_state,+ int64 n, double s)
{
- ZipfCell *cell = zipfFindOrCreateCacheCell(&thread->zipf_cache, n, s);- double uniform = pg_erand48(thread->random_state);+ ZipfCell *cell = zipfFindOrCreateCacheCell(zipf_cache, n, s);+ double uniform = pg_erand48(random_state->xseed);
double uz = uniform * cell->harmonicn;
if (uz < 1.0)
@@ -925,7 +951,8 @@ computeHarmonicZipfian(TState *thread, int64 n, double s)
/* random number generator: zipfian distribution from min to max inclusive */
static int64
-getZipfianRand(TState *thread, int64 min, int64 max, double s)+getZipfianRand(ZipfCache *zipf_cache, RandomState *random_state, int64 min,+ int64 max, double s)
{
int64 n = max - min + 1;
@@ -934,8 +961,8 @@ getZipfianRand(TState *thread, int64 min, int64 max, double s)
return min - 1 + ((s > 1)
- ? computeIterativeZipfian(thread, n, s)- : computeHarmonicZipfian(thread, n, s));+ ? computeIterativeZipfian(random_state, n, s)+ : computeHarmonicZipfian(zipf_cache, random_state, n, s));
}
/*
@@ -2209,7 +2236,7 @@ evalStandardFunc(TState *thread, CState *st,
if (func == PGBENCH_RANDOM)
{
Assert(nargs == 2);
- setIntValue(retval, getrand(thread, imin, imax));+ setIntValue(retval, getrand(&st->random_state, imin, imax));
}
else /* gaussian & exponential */
{
@@ -2231,7 +2258,8 @@ evalStandardFunc(TState *thread, CState *st,
}
setIntValue(retval,
- getGaussianRand(thread, imin, imax, param));+ getGaussianRand(&st->random_state, imin,+ imax, param));
}
else if (func == PGBENCH_RANDOM_ZIPFIAN)
{
@@ -2243,7 +2271,9 @@ evalStandardFunc(TState *thread, CState *st,
return false;
}
setIntValue(retval,
- getZipfianRand(thread, imin, imax, param));+ getZipfianRand(&thread->zipf_cache,+ &st->random_state, imin,+ imax, param));
}
else /* exponential */
{
@@ -2256,7 +2286,8 @@ evalStandardFunc(TState *thread, CState *st,
}
setIntValue(retval,
- getExponentialRand(thread, imin, imax, param));+ getExponentialRand(&st->random_state, imin,+ imax, param));
}
}
@@ -2551,7 +2582,7 @@ chooseScript(TState *thread)
if (num_scripts == 1)
return 0;
- w = getrand(thread, 0, total_weight - 1);+ w = getrand(&thread->choose_script_rs, 0, total_weight - 1);
do
{
w -= sql_script[i++].weight;
@@ -2745,7 +2776,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
* away.
*/
Assert(throttle_delay > 0);
- wait = getPoissonRand(thread, throttle_delay);+ wait = getPoissonRand(&thread->throttling_rs, throttle_delay);
thread->throttle_trigger += wait;
st->txn_scheduled = thread->throttle_trigger;
@@ -2779,7 +2810,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
{
processXactStats(thread, st, &now, true, agg);
/* next rendez-vous */
- wait = getPoissonRand(thread, throttle_delay);+ wait = getPoissonRand(&thread->throttling_rs,+ throttle_delay);
thread->throttle_trigger += wait;
st->txn_scheduled = thread->throttle_trigger;
}
@@ -3322,7 +3354,7 @@ doLog(TState *thread, CState *st,
* to the random sample.
*/
if (sample_rate != 0.0 &&
- pg_erand48(thread->random_state) > sample_rate)+ pg_erand48(thread->sampling_rs.xseed) > sample_rate)
return;
/* should we aggregate the results or not? */
@@ -4750,6 +4782,17 @@ set_random_seed(const char *seed)
return true;
}
+/*+ * Initialize the random state of the client/thread.+ */+static void+initRandomState(RandomState *random_state)+{+ random_state->xseed[0] = random();+ random_state->xseed[1] = random();+ random_state->xseed[2] = random();+}+
int
main(int argc, char **argv)
@@ -5358,6 +5401,7 @@ main(int argc, char **argv)
for (i = 0; i < nclients; i++)
{
state[i].cstack = conditional_stack_create();
+ initRandomState(&state[i].random_state);
}
if (debug)
@@ -5491,9 +5535,9 @@ main(int argc, char **argv)
thread->state = &state[nclients_dealt];
thread->nstate =
(nclients - nclients_dealt + nthreads - i - 1) / (nthreads - i);
- thread->random_state[0] = random();- thread->random_state[1] = random();- thread->random_state[2] = random();+ initRandomState(&thread->choose_script_rs);+ initRandomState(&thread->throttling_rs);+ initRandomState(&thread->sampling_rs);
thread->logfile = NULL; /* filled in later */
thread->latency_late = 0;
thread->zipf_cache.nb_cells = 0;
--
2.7.4
v10-0002-Pgbench-errors-use-a-separate-function-to-report.patch (text/x-diff, 57.7K) download
From 29c1740fd3ad0921c6460e57d6745ea700ef6399 Mon Sep 17 00:00:00 2001
From: Marina Polyakova <m.polyakova@postgrespro.ru>
Date: Tue, 7 Aug 2018 13:28:35 +0300
Subject: [PATCH v10 2/4] Pgbench errors: use a separate function to report a
debug/log/error message
This is most important when it is used to report client failures that do not
cause an aborts and this depends on the level of debugging.
Rename the already used function pgbench_error() to pgbench_simple_error() for
flex lexer errors. Also export the function appendPQExpBufferVA from libpq.
---
src/bin/pgbench/pgbench.c | 846 +++++++++++++++++++++++--------------
src/interfaces/libpq/exports.txt | 1 +
src/interfaces/libpq/pqexpbuffer.c | 4 +-
src/interfaces/libpq/pqexpbuffer.h | 8 +
4 files changed, 530 insertions(+), 329 deletions(-)
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.cindex 988e37b..c45cd44 100644--- a/src/bin/pgbench/pgbench.c+++ b/src/bin/pgbench/pgbench.c@@ -484,8 +484,6 @@ static int num_scripts; /* number of scripts in sql_script[] */
static int num_commands = 0; /* total number of Command structs */
static int64 total_weight = 0;
-static int debug = 0; /* debug flag */-
/* Builtin test scripts */
typedef struct BuiltinScript
{
@@ -532,6 +530,31 @@ static const BuiltinScript builtin_script[] =
}
};
+typedef enum ErrorLevel+{+ /*+ * To report throttling, executed/sent/received commands etc.+ */+ DEBUG,++ /*+ * To report:+ * - abortion of the client (something bad e.g. the SQL/meta command failed+ * or the connection with the backend was lost);+ * - the log messages of the main program;+ * - PGBENCH_DEBUG messages.+ */+ LOG,++ /*+ * To report the error messages of the main program and immediately call+ * exit(1).+ */+ ERROR+} ErrorLevel;++static ErrorLevel log_min_messages = LOG; /* no debug by default */+
/* Function prototypes */
static void setNullValue(PgBenchValue *pv);
@@ -543,17 +566,19 @@ static void doLog(TState *thread, CState *st,
StatsData *agg, bool skipped, double latency, double lag);
static void processXactStats(TState *thread, CState *st, instr_time *now,
bool skipped, StatsData *agg);
-static void pgbench_error(const char *fmt,...) pg_attribute_printf(1, 2);+static void pgbench_simple_error(const char *fmt,...) pg_attribute_printf(1, 2);
static void addScript(ParsedScript script);
static void *threadRun(void *arg);
static void setalarm(int seconds);
static void finishCon(CState *st);
+static void pgbench_error(ErrorLevel elevel,+ const char *fmt,...) pg_attribute_printf(2, 3);
/* callback functions for our flex lexer */
static const PsqlScanCallbacks pgbench_callbacks = {
NULL, /* don't need get_variable functionality */
- pgbench_error+ pgbench_simple_error
};
@@ -691,7 +716,7 @@ strtoint64(const char *str)
/* require at least one digit */
if (!isdigit((unsigned char) *ptr))
- fprintf(stderr, "invalid input syntax for integer: \"%s\"\n", str);+ pgbench_error(LOG, "invalid input syntax for integer: \"%s\"\n", str);
/* process digits */
while (*ptr && isdigit((unsigned char) *ptr))
@@ -699,7 +724,10 @@ strtoint64(const char *str)
int64 tmp = result * 10 + (*ptr++ - '0');
if ((tmp / 10) != result) /* overflow? */
- fprintf(stderr, "value \"%s\" is out of range for type bigint\n", str);+ {+ pgbench_error(LOG, "value \"%s\" is out of range for type bigint\n",+ str);+ }
result = tmp;
}
@@ -710,7 +738,7 @@ gotdigits:
ptr++;
if (*ptr != '\0')
- fprintf(stderr, "invalid input syntax for integer: \"%s\"\n", str);+ pgbench_error(LOG, "invalid input syntax for integer: \"%s\"\n", str);
return ((sign < 0) ? -result : result);
}
@@ -1098,8 +1126,10 @@ executeStatement(PGconn *con, const char *sql)
res = PQexec(con, sql);
if (PQresultStatus(res) != PGRES_COMMAND_OK)
{
- fprintf(stderr, "%s", PQerrorMessage(con));- exit(1);+ /* we are sure that the function PQerrorMessage is always called */+ Assert(ERROR >= log_min_messages);++ pgbench_error(ERROR, "%s", PQerrorMessage(con));
}
PQclear(res);
}
@@ -1113,8 +1143,11 @@ tryExecuteStatement(PGconn *con, const char *sql)
res = PQexec(con, sql);
if (PQresultStatus(res) != PGRES_COMMAND_OK)
{
- fprintf(stderr, "%s", PQerrorMessage(con));- fprintf(stderr, "(ignoring this error and continuing anyway)\n");+ /* we are sure that the function PQerrorMessage is always called */+ Assert(LOG >= log_min_messages);++ pgbench_error(LOG, "%s(ignoring this error and continuing anyway)\n",+ PQerrorMessage(con));
}
PQclear(res);
}
@@ -1160,8 +1193,8 @@ doConnect(void)
if (!conn)
{
- fprintf(stderr, "connection to database \"%s\" failed\n",- dbName);+ pgbench_error(LOG, "connection to database \"%s\" failed\n",+ dbName);
return NULL;
}
@@ -1179,8 +1212,11 @@ doConnect(void)
/* check to see that the backend connection was successfully made */
if (PQstatus(conn) == CONNECTION_BAD)
{
- fprintf(stderr, "connection to database \"%s\" failed:\n%s",- dbName, PQerrorMessage(conn));+ /* we are sure that the function PQerrorMessage is always called */+ Assert(LOG >= log_min_messages);++ pgbench_error(LOG, "connection to database \"%s\" failed:\n%s",+ dbName, PQerrorMessage(conn));
PQfinish(conn);
return NULL;
}
@@ -1318,9 +1354,9 @@ makeVariableValue(Variable *var)
if (sscanf(var->svalue, "%lf%c", &dv, &xs) != 1)
{
- fprintf(stderr,- "malformed variable \"%s\" value: \"%s\"\n",- var->name, var->svalue);+ pgbench_error(LOG,+ "malformed variable \"%s\" value: \"%s\"\n",+ var->name, var->svalue);
return false;
}
setDoubleValue(&var->value, dv);
@@ -1365,10 +1401,11 @@ valid_variable_name(const char *name)
/*
* Lookup a variable by name, creating it if need be.
* Caller is expected to assign a value to the variable.
- * Returns NULL on failure (bad name).+ * On failure (bad name): if this is a client run returns NULL; exits the+ * program otherwise.
*/
static Variable *
-lookupCreateVariable(CState *st, const char *context, char *name)+lookupCreateVariable(CState *st, const char *context, char *name, bool client)
{
Variable *var;
@@ -1383,8 +1420,12 @@ lookupCreateVariable(CState *st, const char *context, char *name)
*/
if (!valid_variable_name(name))
{
- fprintf(stderr, "%s: invalid variable name: \"%s\"\n",- context, name);+ /*+ * About the error level used: if we process client commands, it a+ * normal failure; otherwise it is not and we exit the program.+ */+ pgbench_error(client ? LOG : ERROR,+ "%s: invalid variable name: \"%s\"\n", context, name);
return NULL;
}
@@ -1412,16 +1453,14 @@ lookupCreateVariable(CState *st, const char *context, char *name)
}
/* Assign a string value to a variable, creating it if need be */
-/* Returns false on failure (bad name) */-static bool+/* Exits on failure (bad name) */+static void
putVariable(CState *st, const char *context, char *name, const char *value)
{
Variable *var;
char *val;
- var = lookupCreateVariable(st, context, name);- if (!var)- return false;+ var = lookupCreateVariable(st, context, name, false);
/* dup then free, in case value is pointing at this variable */
val = pg_strdup(value);
@@ -1430,19 +1469,20 @@ putVariable(CState *st, const char *context, char *name, const char *value)
free(var->svalue);
var->svalue = val;
var->value.type = PGBT_NO_VALUE;
-- return true;
}
-/* Assign a value to a variable, creating it if need be */-/* Returns false on failure (bad name) */+/*+ * Assign a value to a variable, creating it if need be.+ * On failure (bad name): if this is a client run returns false; exits the+ * program otherwise.+ */
static bool
putVariableValue(CState *st, const char *context, char *name,
- const PgBenchValue *value)+ const PgBenchValue *value, bool client)
{
Variable *var;
- var = lookupCreateVariable(st, context, name);+ var = lookupCreateVariable(st, context, name, client);
if (!var)
return false;
@@ -1454,15 +1494,19 @@ putVariableValue(CState *st, const char *context, char *name,
return true;
}
-/* Assign an integer value to a variable, creating it if need be */-/* Returns false on failure (bad name) */+/*+ * Assign an integer value to a variable, creating it if need be.+ * On failure (bad name): if this is a client run returns false; exits the+ * program otherwise.+ */
static bool
-putVariableInt(CState *st, const char *context, char *name, int64 value)+putVariableInt(CState *st, const char *context, char *name, int64 value,+ bool client)
{
PgBenchValue val;
setIntValue(&val, value);
- return putVariableValue(st, context, name, &val);+ return putVariableValue(st, context, name, &val, client);
}
/*
@@ -1593,7 +1637,11 @@ coerceToBool(PgBenchValue *pval, bool *bval)
}
else /* NULL, INT or DOUBLE */
{
- fprintf(stderr, "cannot coerce %s to boolean\n", valueTypeName(pval));+ /* we are sure that the function valueTypeName only is always called */+ Assert(LOG >= log_min_messages);++ pgbench_error(LOG, "cannot coerce %s to boolean\n",+ valueTypeName(pval));
*bval = false; /* suppress uninitialized-variable warnings */
return false;
}
@@ -1638,7 +1686,7 @@ coerceToInt(PgBenchValue *pval, int64 *ival)
if (dval < PG_INT64_MIN || PG_INT64_MAX < dval)
{
- fprintf(stderr, "double to int overflow for %f\n", dval);+ pgbench_error(LOG, "double to int overflow for %f\n", dval);
return false;
}
*ival = (int64) dval;
@@ -1646,7 +1694,10 @@ coerceToInt(PgBenchValue *pval, int64 *ival)
}
else /* BOOLEAN or NULL */
{
- fprintf(stderr, "cannot coerce %s to int\n", valueTypeName(pval));+ /* we are sure that the function valueTypeName is always called */+ Assert(LOG >= log_min_messages);++ pgbench_error(LOG, "cannot coerce %s to int\n", valueTypeName(pval));
return false;
}
}
@@ -1667,7 +1718,10 @@ coerceToDouble(PgBenchValue *pval, double *dval)
}
else /* BOOLEAN or NULL */
{
- fprintf(stderr, "cannot coerce %s to double\n", valueTypeName(pval));+ /* we are sure that the function valueTypeName is always called */+ Assert(LOG >= log_min_messages);++ pgbench_error(LOG, "cannot coerce %s to double\n", valueTypeName(pval));
return false;
}
}
@@ -1848,8 +1902,8 @@ evalStandardFunc(TState *thread, CState *st,
if (l != NULL)
{
- fprintf(stderr,- "too many function arguments, maximum is %d\n", MAX_FARGS);+ pgbench_error(LOG, "too many function arguments, maximum is %d\n",+ MAX_FARGS);
return false;
}
@@ -1972,7 +2026,7 @@ evalStandardFunc(TState *thread, CState *st,
case PGBENCH_MOD:
if (ri == 0)
{
- fprintf(stderr, "division by zero\n");+ pgbench_error(LOG, "division by zero\n");
return false;
}
/* special handling of -1 divisor */
@@ -1983,7 +2037,8 @@ evalStandardFunc(TState *thread, CState *st,
/* overflow check (needed for INT64_MIN) */
if (li == PG_INT64_MIN)
{
- fprintf(stderr, "bigint out of range\n");+ pgbench_error(LOG,+ "bigint out of range\n");
return false;
}
else
@@ -2084,22 +2139,48 @@ evalStandardFunc(TState *thread, CState *st,
case PGBENCH_DEBUG:
{
PgBenchValue *varg = &vargs[0];
+ PQExpBufferData errmsg_buf;
Assert(nargs == 1);
- fprintf(stderr, "debug(script=%d,command=%d): ",- st->use_file, st->command + 1);+ /*+ * We are sure that the allocated memory for the message is+ * always used.+ */+ Assert(LOG >= log_min_messages);++ initPQExpBuffer(&errmsg_buf);+ printfPQExpBuffer(&errmsg_buf,+ "debug(script=%d,command=%d): ",+ st->use_file, st->command + 1);
if (varg->type == PGBT_NULL)
- fprintf(stderr, "null\n");+ {+ appendPQExpBuffer(&errmsg_buf, "null\n");+ }
else if (varg->type == PGBT_BOOLEAN)
- fprintf(stderr, "boolean %s\n", varg->u.bval ? "true" : "false");+ {+ appendPQExpBuffer(&errmsg_buf,+ "boolean %s\n",+ varg->u.bval ? "true" : "false");+ }
else if (varg->type == PGBT_INT)
- fprintf(stderr, "int " INT64_FORMAT "\n", varg->u.ival);+ {+ appendPQExpBuffer(&errmsg_buf,+ "int " INT64_FORMAT "\n", varg->u.ival);+ }
else if (varg->type == PGBT_DOUBLE)
- fprintf(stderr, "double %.*g\n", DBL_DIG, varg->u.dval);+ {+ appendPQExpBuffer(&errmsg_buf,+ "double %.*g\n", DBL_DIG, varg->u.dval);+ }
else /* internal error, unexpected type */
+ {
Assert(0);
+ }++ pgbench_error(LOG, "%s", errmsg_buf.data);+ termPQExpBuffer(&errmsg_buf);
*retval = *varg;
@@ -2223,13 +2304,13 @@ evalStandardFunc(TState *thread, CState *st,
/* check random range */
if (imin > imax)
{
- fprintf(stderr, "empty range given to random\n");+ pgbench_error(LOG, "empty range given to random\n");
return false;
}
else if (imax - imin < 0 || (imax - imin) + 1 < 0)
{
/* prevent int overflows in random functions */
- fprintf(stderr, "random range is too large\n");+ pgbench_error(LOG, "random range is too large\n");
return false;
}
@@ -2251,9 +2332,9 @@ evalStandardFunc(TState *thread, CState *st,
{
if (param < MIN_GAUSSIAN_PARAM)
{
- fprintf(stderr,- "gaussian parameter must be at least %f "- "(not %f)\n", MIN_GAUSSIAN_PARAM, param);+ pgbench_error(LOG,+ "gaussian parameter must be at least %f (not %f)\n",+ MIN_GAUSSIAN_PARAM, param);
return false;
}
@@ -2265,9 +2346,9 @@ evalStandardFunc(TState *thread, CState *st,
{
if (param <= 0.0 || param == 1.0 || param > MAX_ZIPFIAN_PARAM)
{
- fprintf(stderr,- "zipfian parameter must be in range (0, 1) U (1, %d]"- " (got %f)\n", MAX_ZIPFIAN_PARAM, param);+ pgbench_error(LOG,+ "zipfian parameter must be in range (0, 1) U (1, %d] (got %f)\n",+ MAX_ZIPFIAN_PARAM, param);
return false;
}
setIntValue(retval,
@@ -2279,9 +2360,9 @@ evalStandardFunc(TState *thread, CState *st,
{
if (param <= 0.0)
{
- fprintf(stderr,- "exponential parameter must be greater than zero"- " (got %f)\n", param);+ pgbench_error(LOG,+ "exponential parameter must be greater than zero (got %f)\n",+ param);
return false;
}
@@ -2392,8 +2473,8 @@ evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr, PgBenchValue *retval
if ((var = lookupVariable(st, expr->u.variable.varname)) == NULL)
{
- fprintf(stderr, "undefined variable \"%s\"\n",- expr->u.variable.varname);+ pgbench_error(LOG, "undefined variable \"%s\"\n",+ expr->u.variable.varname);
return false;
}
@@ -2411,10 +2492,15 @@ evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr, PgBenchValue *retval
retval);
default:
- /* internal error which should never occur */- fprintf(stderr, "unexpected enode type in evaluation: %d\n",- expr->etype);- exit(1);+ {+ /* internal error which should never occur */+ pgbench_error(ERROR,+ "unexpected enode type in evaluation: %d\n",+ expr->etype);++ /* keep compiler quiet */+ return false;+ }
}
}
@@ -2487,15 +2573,15 @@ runShellCommand(CState *st, char *variable, char **argv, int argc)
}
else if ((arg = getVariable(st, argv[i] + 1)) == NULL)
{
- fprintf(stderr, "%s: undefined variable \"%s\"\n",- argv[0], argv[i]);+ pgbench_error(LOG, "%s: undefined variable \"%s\"\n",+ argv[0], argv[i]);
return false;
}
arglen = strlen(arg);
if (len + arglen + (i > 0 ? 1 : 0) >= SHELL_COMMAND_SIZE - 1)
{
- fprintf(stderr, "%s: shell command is too long\n", argv[0]);+ pgbench_error(LOG, "%s: shell command is too long\n", argv[0]);
return false;
}
@@ -2513,7 +2599,10 @@ runShellCommand(CState *st, char *variable, char **argv, int argc)
if (system(command))
{
if (!timer_exceeded)
- fprintf(stderr, "%s: could not launch shell command\n", argv[0]);+ {+ pgbench_error(LOG, "%s: could not launch shell command\n",+ argv[0]);+ }
return false;
}
return true;
@@ -2522,19 +2611,22 @@ runShellCommand(CState *st, char *variable, char **argv, int argc)
/* Execute the command with pipe and read the standard output. */
if ((fp = popen(command, "r")) == NULL)
{
- fprintf(stderr, "%s: could not launch shell command\n", argv[0]);+ pgbench_error(LOG, "%s: could not launch shell command\n", argv[0]);
return false;
}
if (fgets(res, sizeof(res), fp) == NULL)
{
if (!timer_exceeded)
- fprintf(stderr, "%s: could not read result of shell command\n", argv[0]);+ {+ pgbench_error(LOG, "%s: could not read result of shell command\n",+ argv[0]);+ }
(void) pclose(fp);
return false;
}
if (pclose(fp) < 0)
{
- fprintf(stderr, "%s: could not close shell command\n", argv[0]);+ pgbench_error(LOG, "%s: could not close shell command\n", argv[0]);
return false;
}
@@ -2544,11 +2636,12 @@ runShellCommand(CState *st, char *variable, char **argv, int argc)
endptr++;
if (*res == '\0' || *endptr != '\0')
{
- fprintf(stderr, "%s: shell command must return an integer (not \"%s\")\n",- argv[0], res);+ pgbench_error(LOG,+ "%s: shell command must return an integer (not \"%s\")\n",+ argv[0], res);
return false;
}
- if (!putVariableInt(st, "setshell", variable, retval))+ if (!putVariableInt(st, "setshell", variable, retval, true))
return false;
#ifdef DEBUG
@@ -2567,9 +2660,9 @@ preparedStatementName(char *buffer, int file, int state)
static void
commandFailed(CState *st, const char *cmd, const char *message)
{
- fprintf(stderr,- "client %d aborted in command %d (%s) of script %d; %s\n",- st->id, st->command, cmd, st->use_file, message);+ pgbench_error(LOG,+ "client %d aborted in command %d (%s) of script %d; %s\n",+ st->id, st->command, cmd, st->use_file, message);
}
/* return a script number with a weighted choice. */
@@ -2604,8 +2697,7 @@ sendCommand(CState *st, Command *command)
sql = pg_strdup(command->argv[0]);
sql = assignVariables(st, sql);
- if (debug)- fprintf(stderr, "client %d sending %s\n", st->id, sql);+ pgbench_error(DEBUG, "client %d sending %s\n", st->id, sql);
r = PQsendQuery(st->con, sql);
free(sql);
}
@@ -2616,8 +2708,7 @@ sendCommand(CState *st, Command *command)
getQueryParams(st, command, params);
- if (debug)- fprintf(stderr, "client %d sending %s\n", st->id, sql);+ pgbench_error(DEBUG, "client %d sending %s\n", st->id, sql);
r = PQsendQueryParams(st->con, sql, command->argc - 1,
NULL, params, NULL, NULL, 0);
}
@@ -2642,7 +2733,15 @@ sendCommand(CState *st, Command *command)
res = PQprepare(st->con, name,
commands[j]->argv[0], commands[j]->argc - 1, NULL);
if (PQresultStatus(res) != PGRES_COMMAND_OK)
- fprintf(stderr, "%s", PQerrorMessage(st->con));+ {+ /*+ * We are sure that the function PQerrorMessage is always+ * called.+ */+ Assert(LOG >= log_min_messages);++ pgbench_error(LOG, "%s", PQerrorMessage(st->con));+ }
PQclear(res);
}
st->prepared[st->use_file] = true;
@@ -2651,8 +2750,7 @@ sendCommand(CState *st, Command *command)
getQueryParams(st, command, params);
preparedStatementName(name, st->use_file, st->command);
- if (debug)- fprintf(stderr, "client %d sending %s\n", st->id, name);+ pgbench_error(DEBUG, "client %d sending %s\n", st->id, name);
r = PQsendQueryPrepared(st->con, name, command->argc - 1,
params, NULL, NULL, 0);
}
@@ -2661,9 +2759,8 @@ sendCommand(CState *st, Command *command)
if (r == 0)
{
- if (debug)- fprintf(stderr, "client %d could not send %s\n",- st->id, command->argv[0]);+ pgbench_error(DEBUG, "client %d could not send %s\n",+ st->id, command->argv[0]);
st->ecnt++;
return false;
}
@@ -2685,8 +2782,8 @@ evaluateSleep(CState *st, int argc, char **argv, int *usecs)
{
if ((var = getVariable(st, argv[1] + 1)) == NULL)
{
- fprintf(stderr, "%s: undefined variable \"%s\"\n",- argv[0], argv[1]);+ pgbench_error(LOG, "%s: undefined variable \"%s\"\n",+ argv[0], argv[1]);
return false;
}
usec = atoi(var);
@@ -2749,9 +2846,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
st->use_file = chooseScript(thread);
- if (debug)- fprintf(stderr, "client %d executing script \"%s\"\n", st->id,- sql_script[st->use_file].desc);+ pgbench_error(DEBUG, "client %d executing script \"%s\"\n",+ st->id, sql_script[st->use_file].desc);
if (throttle_delay > 0)
st->state = CSTATE_START_THROTTLE;
@@ -2824,9 +2920,9 @@ doCustom(TState *thread, CState *st, StatsData *agg)
}
st->state = CSTATE_THROTTLE;
- if (debug)- fprintf(stderr, "client %d throttling " INT64_FORMAT " us\n",- st->id, wait);+ pgbench_error(DEBUG,+ "client %d throttling " INT64_FORMAT " us\n",+ st->id, wait);
break;
/*
@@ -2858,8 +2954,9 @@ doCustom(TState *thread, CState *st, StatsData *agg)
start = now;
if ((st->con = doConnect()) == NULL)
{
- fprintf(stderr, "client %d aborted while establishing connection\n",- st->id);+ pgbench_error(LOG,+ "client %d aborted while establishing connection\n",+ st->id);
st->state = CSTATE_ABORTED;
break;
}
@@ -2937,12 +3034,19 @@ doCustom(TState *thread, CState *st, StatsData *agg)
i;
char **argv = command->argv;
- if (debug)+ /* allocate memory for the message only if necessary */+ if (DEBUG >= log_min_messages)
{
- fprintf(stderr, "client %d executing \\%s", st->id, argv[0]);+ PQExpBufferData errmsg_buf;++ initPQExpBuffer(&errmsg_buf);+ printfPQExpBuffer(&errmsg_buf, "client %d executing \\%s",+ st->id, argv[0]);
for (i = 1; i < argc; i++)
- fprintf(stderr, " %s", argv[i]);- fprintf(stderr, "\n");+ appendPQExpBuffer(&errmsg_buf, " %s", argv[i]);+ appendPQExpBufferChar(&errmsg_buf, '\n');+ pgbench_error(DEBUG, "%s", errmsg_buf.data);+ termPQExpBuffer(&errmsg_buf);
}
if (command->meta == META_SLEEP)
@@ -2997,7 +3101,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
if (command->meta == META_SET)
{
- if (!putVariableValue(st, argv[0], argv[1], &result))+ if (!putVariableValue(st, argv[0], argv[1], &result,+ true))
{
commandFailed(st, "set", "assignment of meta-command failed");
st->state = CSTATE_ABORTED;
@@ -3197,8 +3302,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
*/
case CSTATE_WAIT_RESULT:
command = sql_script[st->use_file].commands[st->command];
- if (debug)- fprintf(stderr, "client %d receiving\n", st->id);+ pgbench_error(DEBUG, "client %d receiving\n", st->id);
if (!PQconsumeInput(st->con))
{ /* there's something wrong */
commandFailed(st, "SQL", "perhaps the backend died while processing");
@@ -3284,8 +3388,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
/* conditional stack must be empty */
if (!conditional_stack_empty(st->cstack))
{
- fprintf(stderr, "end of script reached within a conditional, missing \\endif\n");- exit(1);+ pgbench_error(ERROR,+ "end of script reached within a conditional, missing \\endif\n");
}
if (is_connect)
@@ -3484,7 +3588,7 @@ disconnect_all(CState *state, int length)
static void
initDropTables(PGconn *con)
{
- fprintf(stderr, "dropping old tables...\n");+ pgbench_error(LOG, "dropping old tables...\n");
/*
* We drop all the tables in one command, so that whether there are
@@ -3559,7 +3663,7 @@ initCreateTables(PGconn *con)
};
int i;
- fprintf(stderr, "creating tables...\n");+ pgbench_error(LOG, "creating tables...\n");
for (i = 0; i < lengthof(DDLs); i++)
{
@@ -3612,7 +3716,7 @@ initGenerateData(PGconn *con)
remaining_sec;
int log_interval = 1;
- fprintf(stderr, "generating data...\n");+ pgbench_error(LOG, "generating data...\n");
/*
* we do all of this in one transaction to enable the backend's
@@ -3658,8 +3762,10 @@ initGenerateData(PGconn *con)
res = PQexec(con, "copy pgbench_accounts from stdin");
if (PQresultStatus(res) != PGRES_COPY_IN)
{
- fprintf(stderr, "%s", PQerrorMessage(con));- exit(1);+ /* we are sure that the function PQerrorMessage is always called */+ Assert(ERROR >= log_min_messages);++ pgbench_error(ERROR, "%s", PQerrorMessage(con));
}
PQclear(res);
@@ -3674,10 +3780,7 @@ initGenerateData(PGconn *con)
INT64_FORMAT "\t" INT64_FORMAT "\t%d\t\n",
j, k / naccounts + 1, 0);
if (PQputline(con, sql))
- {- fprintf(stderr, "PQputline failed\n");- exit(1);- }+ pgbench_error(ERROR, "PQputline failed\n");
/*
* If we want to stick with the original logging, print a message each
@@ -3691,10 +3794,12 @@ initGenerateData(PGconn *con)
elapsed_sec = INSTR_TIME_GET_DOUBLE(diff);
remaining_sec = ((double) scale * naccounts - j) * elapsed_sec / j;
- fprintf(stderr, INT64_FORMAT " of " INT64_FORMAT " tuples (%d%%) done (elapsed %.2f s, remaining %.2f s)\n",- j, (int64) naccounts * scale,- (int) (((int64) j * 100) / (naccounts * (int64) scale)),- elapsed_sec, remaining_sec);+ pgbench_error(LOG,+ INT64_FORMAT " of " INT64_FORMAT " tuples (%d%%) done (elapsed %.2f s, remaining %.2f s)\n",+ j, (int64) naccounts * scale,+ (int) (((int64) j * 100) /+ (naccounts * (int64) scale)),+ elapsed_sec, remaining_sec);
}
/* let's not call the timing for each row, but only each 100 rows */
else if (use_quiet && (j % 100 == 0))
@@ -3708,9 +3813,12 @@ initGenerateData(PGconn *con)
/* have we reached the next interval (or end)? */
if ((j == scale * naccounts) || (elapsed_sec >= log_interval * LOG_STEP_SECONDS))
{
- fprintf(stderr, INT64_FORMAT " of " INT64_FORMAT " tuples (%d%%) done (elapsed %.2f s, remaining %.2f s)\n",- j, (int64) naccounts * scale,- (int) (((int64) j * 100) / (naccounts * (int64) scale)), elapsed_sec, remaining_sec);+ pgbench_error(LOG,+ INT64_FORMAT " of " INT64_FORMAT " tuples (%d%%) done (elapsed %.2f s, remaining %.2f s)\n",+ j, (int64) naccounts * scale,+ (int) (((int64) j * 100) /+ (naccounts * (int64) scale)),+ elapsed_sec, remaining_sec);
/* skip to the next interval */
log_interval = (int) ceil(elapsed_sec / LOG_STEP_SECONDS);
@@ -3719,15 +3827,9 @@ initGenerateData(PGconn *con)
}
if (PQputline(con, "\\.\n"))
- {- fprintf(stderr, "very last PQputline failed\n");- exit(1);- }+ pgbench_error(ERROR, "very last PQputline failed\n");
if (PQendcopy(con))
- {- fprintf(stderr, "PQendcopy failed\n");- exit(1);- }+ pgbench_error(ERROR, "PQendcopy failed\n");
executeStatement(con, "commit");
}
@@ -3738,7 +3840,7 @@ initGenerateData(PGconn *con)
static void
initVacuum(PGconn *con)
{
- fprintf(stderr, "vacuuming...\n");+ pgbench_error(LOG, "vacuuming...\n");
executeStatement(con, "vacuum analyze pgbench_branches");
executeStatement(con, "vacuum analyze pgbench_tellers");
executeStatement(con, "vacuum analyze pgbench_accounts");
@@ -3758,7 +3860,7 @@ initCreatePKeys(PGconn *con)
};
int i;
- fprintf(stderr, "creating primary keys...\n");+ pgbench_error(LOG, "creating primary keys...\n");
for (i = 0; i < lengthof(DDLINDEXes); i++)
{
char buffer[256];
@@ -3795,7 +3897,7 @@ initCreateFKeys(PGconn *con)
};
int i;
- fprintf(stderr, "creating foreign keys...\n");+ pgbench_error(LOG, "creating foreign keys...\n");
for (i = 0; i < lengthof(DDLKEYs); i++)
{
executeStatement(con, DDLKEYs[i]);
@@ -3815,19 +3917,16 @@ checkInitSteps(const char *initialize_steps)
const char *step;
if (initialize_steps[0] == '\0')
- {- fprintf(stderr, "no initialization steps specified\n");- exit(1);- }+ pgbench_error(ERROR, "no initialization steps specified\n");
for (step = initialize_steps; *step != '\0'; step++)
{
if (strchr("dtgvpf ", *step) == NULL)
{
- fprintf(stderr, "unrecognized initialization step \"%c\"\n",- *step);- fprintf(stderr, "allowed steps are: \"d\", \"t\", \"g\", \"v\", \"p\", \"f\"\n");- exit(1);+ pgbench_error(ERROR,+ "unrecognized initialization step \"%c\"\n"+ "allowed steps are: \"d\", \"t\", \"g\", \"v\", \"p\", \"f\"\n",+ *step);
}
}
}
@@ -3869,14 +3968,14 @@ runInitSteps(const char *initialize_steps)
case ' ':
break; /* ignore */
default:
- fprintf(stderr, "unrecognized initialization step \"%c\"\n",- *step);+ pgbench_error(LOG, "unrecognized initialization step \"%c\"\n",+ *step);
PQfinish(con);
exit(1);
}
}
- fprintf(stderr, "done.\n");+ pgbench_error(LOG, "done.\n");
PQfinish(con);
}
@@ -3914,8 +4013,9 @@ parseQuery(Command *cmd)
if (cmd->argc >= MAX_ARGS)
{
- fprintf(stderr, "statement has too many arguments (maximum is %d): %s\n",- MAX_ARGS - 1, cmd->argv[0]);+ pgbench_error(LOG,+ "statement has too many arguments (maximum is %d): %s\n",+ MAX_ARGS - 1, cmd->argv[0]);
pg_free(name);
return false;
}
@@ -3936,14 +4036,28 @@ parseQuery(Command *cmd)
* Simple error-printing function, might be needed by lexer
*/
static void
-pgbench_error(const char *fmt,...)+pgbench_simple_error(const char *fmt,...)
{
va_list ap;
+ PQExpBufferData errmsg_buf;+ bool done;++ /* We are sure that the allocated memory for the message is always used. */+ Assert(LOG >= log_min_messages);
fflush(stdout);
- va_start(ap, fmt);- vfprintf(stderr, _(fmt), ap);- va_end(ap);+ initPQExpBuffer(&errmsg_buf);++ /* Loop in case we have to retry after enlarging the buffer. */+ do+ {+ va_start(ap, fmt);+ done = appendPQExpBufferVA(&errmsg_buf, fmt, ap);+ va_end(ap);+ } while (!done);++ pgbench_error(LOG, "%s", errmsg_buf.data);+ termPQExpBuffer(&errmsg_buf);
}
/*
@@ -3963,26 +4077,35 @@ syntax_error(const char *source, int lineno,
const char *line, const char *command,
const char *msg, const char *more, int column)
{
- fprintf(stderr, "%s:%d: %s", source, lineno, msg);+ PQExpBufferData errmsg_buf;++ /* we are sure that the allocated memory for the message is always used */+ Assert(LOG >= log_min_messages);++ initPQExpBuffer(&errmsg_buf);+ printfPQExpBuffer(&errmsg_buf, "%s:%d: %s", source, lineno, msg);
if (more != NULL)
- fprintf(stderr, " (%s)", more);+ appendPQExpBuffer(&errmsg_buf, " (%s)", more);
if (column >= 0 && line == NULL)
- fprintf(stderr, " at column %d", column + 1);+ appendPQExpBuffer(&errmsg_buf, " at column %d", column + 1);
if (command != NULL)
- fprintf(stderr, " in command \"%s\"", command);- fprintf(stderr, "\n");+ appendPQExpBuffer(&errmsg_buf, " in command \"%s\"", command);+ appendPQExpBufferChar(&errmsg_buf, '\n');
if (line != NULL)
{
- fprintf(stderr, "%s\n", line);+ appendPQExpBuffer(&errmsg_buf, "%s\n", line);
if (column >= 0)
{
int i;
for (i = 0; i < column; i++)
- fprintf(stderr, " ");- fprintf(stderr, "^ error found here\n");+ appendPQExpBufferChar(&errmsg_buf, ' ');+ appendPQExpBufferStr(&errmsg_buf, "^ error found here\n");
}
}
++ pgbench_error(LOG, "%s", errmsg_buf.data);+ termPQExpBuffer(&errmsg_buf);
exit(1);
}
@@ -4232,10 +4355,8 @@ process_backslash_command(PsqlScanState sstate, const char *source)
static void
ConditionError(const char *desc, int cmdn, const char *msg)
{
- fprintf(stderr,- "condition error in script \"%s\" command %d: %s\n",- desc, cmdn, msg);- exit(1);+ pgbench_error(ERROR, "condition error in script \"%s\" command %d: %s\n",+ desc, cmdn, msg);
}
/*
@@ -4434,18 +4555,22 @@ process_file(const char *filename, int weight)
fd = stdin;
else if ((fd = fopen(filename, "r")) == NULL)
{
- fprintf(stderr, "could not open file \"%s\": %s\n",- filename, strerror(errno));- exit(1);+ /* we are sure that the function strerror is always called */+ Assert(ERROR >= log_min_messages);++ pgbench_error(ERROR, "could not open file \"%s\": %s\n",+ filename, strerror(errno));
}
buf = read_file_contents(fd);
if (ferror(fd))
{
- fprintf(stderr, "could not read file \"%s\": %s\n",- filename, strerror(errno));- exit(1);+ /* we are sure that the function strerror is always called */+ Assert(ERROR >= log_min_messages);++ pgbench_error(ERROR, "could not read file \"%s\": %s\n",+ filename, strerror(errno));
}
if (fd != stdin)
@@ -4468,11 +4593,19 @@ static void
listAvailableScripts(void)
{
int i;
+ PQExpBufferData errmsg_buf;- fprintf(stderr, "Available builtin scripts:\n");+ /* we are sure that the allocated memory for the message is always used */+ Assert(LOG >= log_min_messages);++ initPQExpBuffer(&errmsg_buf);+ printfPQExpBuffer(&errmsg_buf, "Available builtin scripts:\n");
for (i = 0; i < lengthof(builtin_script); i++)
- fprintf(stderr, "\t%s\n", builtin_script[i].name);- fprintf(stderr, "\n");+ appendPQExpBuffer(&errmsg_buf, "\t%s\n", builtin_script[i].name);+ appendPQExpBufferChar(&errmsg_buf, '\n');++ pgbench_error(LOG, "%s", errmsg_buf.data);+ termPQExpBuffer(&errmsg_buf);
}
/* return builtin script "name" if unambiguous, fails if not found */
@@ -4499,10 +4632,11 @@ findBuiltin(const char *name)
/* error cases */
if (found == 0)
- fprintf(stderr, "no builtin script found for name \"%s\"\n", name);+ pgbench_error(LOG, "no builtin script found for name \"%s\"\n", name);
else /* found > 1 */
- fprintf(stderr,- "ambiguous builtin name: %d builtin scripts found for prefix \"%s\"\n", found, name);+ pgbench_error(LOG,+ "ambiguous builtin name: %d builtin scripts found for prefix \"%s\"\n",+ found, name);
listAvailableScripts();
exit(1);
@@ -4534,16 +4668,12 @@ parseScriptWeight(const char *option, char **script)
errno = 0;
wtmp = strtol(sep + 1, &badp, 10);
if (errno != 0 || badp == sep + 1 || *badp != '\0')
- {- fprintf(stderr, "invalid weight specification: %s\n", sep);- exit(1);- }+ pgbench_error(ERROR, "invalid weight specification: %s\n", sep);
if (wtmp > INT_MAX || wtmp < 0)
{
- fprintf(stderr,- "weight specification out of range (0 .. %u): " INT64_FORMAT "\n",- INT_MAX, (int64) wtmp);- exit(1);+ pgbench_error(ERROR,+ "weight specification out of range (0 .. %u): " INT64_FORMAT "\n",+ INT_MAX, (int64) wtmp);
}
weight = wtmp;
}
@@ -4562,14 +4692,14 @@ addScript(ParsedScript script)
{
if (script.commands == NULL || script.commands[0] == NULL)
{
- fprintf(stderr, "empty command list for script \"%s\"\n", script.desc);- exit(1);+ pgbench_error(ERROR, "empty command list for script \"%s\"\n",+ script.desc);
}
if (num_scripts >= MAX_SCRIPTS)
{
- fprintf(stderr, "at most %d SQL scripts are allowed\n", MAX_SCRIPTS);- exit(1);+ pgbench_error(ERROR, "at most %d SQL scripts are allowed\n",+ MAX_SCRIPTS);
}
CheckConditional(script);
@@ -4754,9 +4884,8 @@ set_random_seed(const char *seed)
if (!pg_strong_random(&iseed, sizeof(iseed)))
#endif
{
- fprintf(stderr,- "cannot seed random from a strong source, none available: "- "use \"time\" or an unsigned integer value.\n");+ pgbench_error(LOG,+ "cannot seed random from a strong source, none available: use \"time\" or an unsigned integer value.\n");
return false;
}
}
@@ -4767,15 +4896,15 @@ set_random_seed(const char *seed)
if (sscanf(seed, "%u%c", &iseed, &garbage) != 1)
{
- fprintf(stderr,- "unrecognized random seed option \"%s\": expecting an unsigned integer, \"time\" or \"rand\"\n",- seed);+ pgbench_error(LOG,+ "unrecognized random seed option \"%s\": expecting an unsigned integer, \"time\" or \"rand\"\n",+ seed);
return false;
}
}
if (seed != NULL)
- fprintf(stderr, "setting random seed to %u\n", iseed);+ pgbench_error(LOG, "setting random seed to %u\n", iseed);
srandom(iseed);
/* no precision loss: 32 bit unsigned int cast to 64 bit int */
random_seed = iseed;
@@ -4907,8 +5036,8 @@ main(int argc, char **argv)
/* set random seed early, because it may be used while parsing scripts. */
if (!set_random_seed(getenv("PGBENCH_RANDOM_SEED")))
{
- fprintf(stderr, "error while setting random seed from PGBENCH_RANDOM_SEED environment variable\n");- exit(1);+ pgbench_error(ERROR,+ "error while setting random seed from PGBENCH_RANDOM_SEED environment variable\n");
}
while ((c = getopt_long(argc, argv, "iI:h:nvp:dqb:SNc:j:Crs:t:T:U:lf:D:F:M:P:R:L:", long_options, &optindex)) != -1)
@@ -4941,16 +5070,15 @@ main(int argc, char **argv)
pgport = pg_strdup(optarg);
break;
case 'd':
- debug++;+ log_min_messages = DEBUG;
break;
case 'c':
benchmarking_option_set = true;
nclients = atoi(optarg);
if (nclients <= 0 || nclients > MAXCLIENTS)
{
- fprintf(stderr, "invalid number of clients: \"%s\"\n",- optarg);- exit(1);+ pgbench_error(ERROR, "invalid number of clients: \"%s\"\n",+ optarg);
}
#ifdef HAVE_GETRLIMIT
#ifdef RLIMIT_NOFILE /* most platforms use RLIMIT_NOFILE */
@@ -4959,15 +5087,20 @@ main(int argc, char **argv)
if (getrlimit(RLIMIT_OFILE, &rlim) == -1)
#endif /* RLIMIT_NOFILE */
{
- fprintf(stderr, "getrlimit failed: %s\n", strerror(errno));- exit(1);+ /*+ * We are sure that the function strerror is always called.+ */+ Assert(ERROR >= log_min_messages);++ pgbench_error(ERROR, "getrlimit failed: %s\n",+ strerror(errno));
}
if (rlim.rlim_cur < nclients + 3)
{
- fprintf(stderr, "need at least %d open files, but system limit is %ld\n",- nclients + 3, (long) rlim.rlim_cur);- fprintf(stderr, "Reduce number of clients, or use limit/ulimit to increase the system limit.\n");- exit(1);+ pgbench_error(ERROR,+ "need at least %d open files, but system limit is %ld\n"+ "Reduce number of clients, or use limit/ulimit to increase the system limit.\n",+ nclients + 3, (long) rlim.rlim_cur);
}
#endif /* HAVE_GETRLIMIT */
break;
@@ -4976,15 +5109,14 @@ main(int argc, char **argv)
nthreads = atoi(optarg);
if (nthreads <= 0)
{
- fprintf(stderr, "invalid number of threads: \"%s\"\n",- optarg);- exit(1);+ pgbench_error(ERROR, "invalid number of threads: \"%s\"\n",+ optarg);
}
#ifndef ENABLE_THREAD_SAFETY
if (nthreads != 1)
{
- fprintf(stderr, "threads are not supported on this platform; use -j1\n");- exit(1);+ pgbench_error(ERROR,+ "threads are not supported on this platform; use -j1\n");
}
#endif /* !ENABLE_THREAD_SAFETY */
break;
@@ -5001,8 +5133,8 @@ main(int argc, char **argv)
scale = atoi(optarg);
if (scale <= 0)
{
- fprintf(stderr, "invalid scaling factor: \"%s\"\n", optarg);- exit(1);+ pgbench_error(ERROR, "invalid scaling factor: \"%s\"\n",+ optarg);
}
break;
case 't':
@@ -5010,19 +5142,16 @@ main(int argc, char **argv)
nxacts = atoi(optarg);
if (nxacts <= 0)
{
- fprintf(stderr, "invalid number of transactions: \"%s\"\n",- optarg);- exit(1);+ pgbench_error(ERROR,+ "invalid number of transactions: \"%s\"\n",+ optarg);
}
break;
case 'T':
benchmarking_option_set = true;
duration = atoi(optarg);
if (duration <= 0)
- {- fprintf(stderr, "invalid duration: \"%s\"\n", optarg);- exit(1);- }+ pgbench_error(ERROR, "invalid duration: \"%s\"\n", optarg);
break;
case 'U':
login = pg_strdup(optarg);
@@ -5069,14 +5198,13 @@ main(int argc, char **argv)
if ((p = strchr(optarg, '=')) == NULL || p == optarg || *(p + 1) == '\0')
{
- fprintf(stderr, "invalid variable definition: \"%s\"\n",- optarg);- exit(1);+ pgbench_error(ERROR,+ "invalid variable definition: \"%s\"\n",+ optarg);
}
*p++ = '\0';
- if (!putVariable(&state[0], "option", optarg, p))- exit(1);+ putVariable(&state[0], "option", optarg, p);
}
break;
case 'F':
@@ -5084,8 +5212,8 @@ main(int argc, char **argv)
fillfactor = atoi(optarg);
if (fillfactor < 10 || fillfactor > 100)
{
- fprintf(stderr, "invalid fillfactor: \"%s\"\n", optarg);- exit(1);+ pgbench_error(ERROR, "invalid fillfactor: \"%s\"\n",+ optarg);
}
break;
case 'M':
@@ -5095,9 +5223,8 @@ main(int argc, char **argv)
break;
if (querymode >= NUM_QUERYMODE)
{
- fprintf(stderr, "invalid query mode (-M): \"%s\"\n",- optarg);- exit(1);+ pgbench_error(ERROR, "invalid query mode (-M): \"%s\"\n",+ optarg);
}
break;
case 'P':
@@ -5105,9 +5232,9 @@ main(int argc, char **argv)
progress = atoi(optarg);
if (progress <= 0)
{
- fprintf(stderr, "invalid thread progress delay: \"%s\"\n",- optarg);- exit(1);+ pgbench_error(ERROR,+ "invalid thread progress delay: \"%s\"\n",+ optarg);
}
break;
case 'R':
@@ -5119,8 +5246,8 @@ main(int argc, char **argv)
if (throttle_value <= 0.0)
{
- fprintf(stderr, "invalid rate limit: \"%s\"\n", optarg);- exit(1);+ pgbench_error(ERROR, "invalid rate limit: \"%s\"\n",+ optarg);
}
/* Invert rate limit into a time offset */
throttle_delay = (int64) (1000000.0 / throttle_value);
@@ -5132,9 +5259,8 @@ main(int argc, char **argv)
if (limit_ms <= 0.0)
{
- fprintf(stderr, "invalid latency limit: \"%s\"\n",- optarg);- exit(1);+ pgbench_error(ERROR, "invalid latency limit: \"%s\"\n",+ optarg);
}
benchmarking_option_set = true;
latency_limit = (int64) (limit_ms * 1000);
@@ -5157,8 +5283,8 @@ main(int argc, char **argv)
sample_rate = atof(optarg);
if (sample_rate <= 0.0 || sample_rate > 1.0)
{
- fprintf(stderr, "invalid sampling rate: \"%s\"\n", optarg);- exit(1);+ pgbench_error(ERROR, "invalid sampling rate: \"%s\"\n",+ optarg);
}
break;
case 5: /* aggregate-interval */
@@ -5166,9 +5292,9 @@ main(int argc, char **argv)
agg_interval = atoi(optarg);
if (agg_interval <= 0)
{
- fprintf(stderr, "invalid number of seconds for aggregation: \"%s\"\n",- optarg);- exit(1);+ pgbench_error(ERROR,+ "invalid number of seconds for aggregation: \"%s\"\n",+ optarg);
}
break;
case 6: /* progress-timestamp */
@@ -5187,13 +5313,14 @@ main(int argc, char **argv)
benchmarking_option_set = true;
if (!set_random_seed(optarg))
{
- fprintf(stderr, "error while setting random seed from --random-seed option\n");- exit(1);+ pgbench_error(ERROR,+ "error while setting random seed from --random-seed option\n");
}
break;
default:
- fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);- exit(1);+ pgbench_error(ERROR,+ _("Try \"%s --help\" for more information.\n"),+ progname);
break;
}
}
@@ -5230,10 +5357,7 @@ main(int argc, char **argv)
total_weight += sql_script[i].weight;
if (total_weight == 0 && !is_init_mode)
- {- fprintf(stderr, "total script weight must not be zero\n");- exit(1);- }+ pgbench_error(ERROR, "total script weight must not be zero\n");
/* show per script stats if several scripts are used */
if (num_scripts > 1)
@@ -5266,8 +5390,8 @@ main(int argc, char **argv)
{
if (benchmarking_option_set)
{
- fprintf(stderr, "some of the specified options cannot be used in initialization (-i) mode\n");- exit(1);+ pgbench_error(ERROR,+ "some of the specified options cannot be used in initialization (-i) mode\n");
}
if (initialize_steps == NULL)
@@ -5301,15 +5425,15 @@ main(int argc, char **argv)
{
if (initialization_option_set)
{
- fprintf(stderr, "some of the specified options cannot be used in benchmarking mode\n");- exit(1);+ pgbench_error(ERROR,+ "some of the specified options cannot be used in benchmarking mode\n");
}
}
if (nxacts > 0 && duration > 0)
{
- fprintf(stderr, "specify either a number of transactions (-t) or a duration (-T), not both\n");- exit(1);+ pgbench_error(ERROR,+ "specify either a number of transactions (-t) or a duration (-T), not both\n");
}
/* Use DEFAULT_NXACTS if neither nxacts nor duration is specified. */
@@ -5319,45 +5443,47 @@ main(int argc, char **argv)
/* --sampling-rate may be used only with -l */
if (sample_rate > 0.0 && !use_log)
{
- fprintf(stderr, "log sampling (--sampling-rate) is allowed only when logging transactions (-l)\n");- exit(1);+ pgbench_error(ERROR,+ "log sampling (--sampling-rate) is allowed only when logging transactions (-l)\n");
}
/* --sampling-rate may not be used with --aggregate-interval */
if (sample_rate > 0.0 && agg_interval > 0)
{
- fprintf(stderr, "log sampling (--sampling-rate) and aggregation (--aggregate-interval) cannot be used at the same time\n");- exit(1);+ pgbench_error(ERROR,+ "log sampling (--sampling-rate) and aggregation (--aggregate-interval) cannot be used at the same time\n");
}
if (agg_interval > 0 && !use_log)
{
- fprintf(stderr, "log aggregation is allowed only when actually logging transactions\n");- exit(1);+ pgbench_error(ERROR,+ "log aggregation is allowed only when actually logging transactions\n");
}
if (!use_log && logfile_prefix)
{
- fprintf(stderr, "log file prefix (--log-prefix) is allowed only when logging transactions (-l)\n");- exit(1);+ pgbench_error(ERROR,+ "log file prefix (--log-prefix) is allowed only when logging transactions (-l)\n");
}
if (duration > 0 && agg_interval > duration)
{
- fprintf(stderr, "number of seconds for aggregation (%d) must not be higher than test duration (%d)\n", agg_interval, duration);- exit(1);+ pgbench_error(ERROR,+ "number of seconds for aggregation (%d) must not be higher than test duration (%d)\n",+ agg_interval, duration);
}
if (duration > 0 && agg_interval > 0 && duration % agg_interval != 0)
{
- fprintf(stderr, "duration (%d) must be a multiple of aggregation interval (%d)\n", duration, agg_interval);- exit(1);+ pgbench_error(ERROR,+ "duration (%d) must be a multiple of aggregation interval (%d)\n",+ duration, agg_interval);
}
if (progress_timestamp && progress == 0)
{
- fprintf(stderr, "--progress-timestamp is allowed only under --progress\n");- exit(1);+ pgbench_error(ERROR,+ "--progress-timestamp is allowed only under --progress\n");
}
/*
@@ -5383,15 +5509,12 @@ main(int argc, char **argv)
if (var->value.type != PGBT_NO_VALUE)
{
- if (!putVariableValue(&state[i], "startup",- var->name, &var->value))- exit(1);+ putVariableValue(&state[i], "startup",+ var->name, &var->value, false);
}
else
{
- if (!putVariable(&state[i], "startup",- var->name, var->svalue))- exit(1);+ putVariable(&state[i], "startup", var->name, var->svalue);
}
}
}
@@ -5404,7 +5527,7 @@ main(int argc, char **argv)
initRandomState(&state[i].random_state);
}
- if (debug)+ if (DEBUG >= log_min_messages)
{
if (duration <= 0)
printf("pghost: %s pgport: %s nclients: %d nxacts: %d dbName: %s\n",
@@ -5421,9 +5544,11 @@ main(int argc, char **argv)
if (PQstatus(con) == CONNECTION_BAD)
{
- fprintf(stderr, "connection to database \"%s\" failed\n", dbName);- fprintf(stderr, "%s", PQerrorMessage(con));- exit(1);+ /* we are sure that the function PQerrorMessage is always called */+ Assert(ERROR >= log_min_messages);++ pgbench_error(ERROR, "connection to database \"%s\" failed\n%s",+ dbName, PQerrorMessage(con));
}
if (internal_script_used)
@@ -5436,29 +5561,44 @@ main(int argc, char **argv)
if (PQresultStatus(res) != PGRES_TUPLES_OK)
{
char *sqlState = PQresultErrorField(res, PG_DIAG_SQLSTATE);
+ PQExpBufferData errmsg_buf;- fprintf(stderr, "%s", PQerrorMessage(con));+ /*+ * we are sure that the allocated memory for the message is always+ * used+ */+ Assert(LOG >= log_min_messages);++ initPQExpBuffer(&errmsg_buf);+ printfPQExpBuffer(&errmsg_buf, "%s", PQerrorMessage(con));
if (sqlState && strcmp(sqlState, ERRCODE_UNDEFINED_TABLE) == 0)
{
- fprintf(stderr, "Perhaps you need to do initialization (\"pgbench -i\") in database \"%s\"\n", PQdb(con));+ appendPQExpBuffer(&errmsg_buf,+ "Perhaps you need to do initialization (\"pgbench -i\") in database \"%s\"\n",+ PQdb(con));
}
+ pgbench_error(LOG, "%s", errmsg_buf.data);+ termPQExpBuffer(&errmsg_buf);
exit(1);
}
scale = atoi(PQgetvalue(res, 0, 0));
if (scale < 0)
{
- fprintf(stderr, "invalid count(*) from pgbench_branches: \"%s\"\n",- PQgetvalue(res, 0, 0));- exit(1);+ /* we are sure that the function PQgetvalue is always called */+ Assert(ERROR >= log_min_messages);++ pgbench_error(ERROR,+ "invalid count(*) from pgbench_branches: \"%s\"\n",+ PQgetvalue(res, 0, 0));
}
PQclear(res);
/* warn if we override user-given -s switch */
if (scale_given)
- fprintf(stderr,- "scale option ignored, using count from pgbench_branches table (%d)\n",- scale);+ pgbench_error(LOG,+ "scale option ignored, using count from pgbench_branches table (%d)\n",+ scale);
}
/*
@@ -5468,10 +5608,7 @@ main(int argc, char **argv)
if (lookupVariable(&state[0], "scale") == NULL)
{
for (i = 0; i < nclients; i++)
- {- if (!putVariableInt(&state[i], "startup", "scale", scale))- exit(1);- }+ putVariableInt(&state[i], "startup", "scale", scale, false);
}
/*
@@ -5481,8 +5618,7 @@ main(int argc, char **argv)
if (lookupVariable(&state[0], "client_id") == NULL)
{
for (i = 0; i < nclients; i++)
- if (!putVariableInt(&state[i], "startup", "client_id", i))- exit(1);+ putVariableInt(&state[i], "startup", "client_id", i, false);
}
/* set default seed for hash functions */
@@ -5494,31 +5630,35 @@ main(int argc, char **argv)
(uint64) (random() & 0xFFFF);
for (i = 0; i < nclients; i++)
- if (!putVariableInt(&state[i], "startup", "default_seed", (int64) seed))- exit(1);+ {+ putVariableInt(&state[i], "startup", "default_seed", (int64) seed,+ false);+ }
}
/* set random seed unless overwritten */
if (lookupVariable(&state[0], "random_seed") == NULL)
{
for (i = 0; i < nclients; i++)
- if (!putVariableInt(&state[i], "startup", "random_seed", random_seed))- exit(1);+ {+ putVariableInt(&state[i], "startup", "random_seed", random_seed,+ false);+ }
}
if (!is_no_vacuum)
{
- fprintf(stderr, "starting vacuum...");+ pgbench_error(LOG, "starting vacuum...");
tryExecuteStatement(con, "vacuum pgbench_branches");
tryExecuteStatement(con, "vacuum pgbench_tellers");
tryExecuteStatement(con, "truncate pgbench_history");
- fprintf(stderr, "end.\n");+ pgbench_error(LOG, "end.\n");
if (do_vacuum_accounts)
{
- fprintf(stderr, "starting vacuum pgbench_accounts...");+ pgbench_error(LOG, "starting vacuum pgbench_accounts...");
tryExecuteStatement(con, "vacuum analyze pgbench_accounts");
- fprintf(stderr, "end.\n");+ pgbench_error(LOG, "end.\n");
}
}
PQfinish(con);
@@ -5578,8 +5718,11 @@ main(int argc, char **argv)
if (err != 0 || thread->thread == INVALID_THREAD)
{
- fprintf(stderr, "could not create thread: %s\n", strerror(err));- exit(1);+ /* we are sure that the function strerror is always called */+ Assert(ERROR >= log_min_messages);++ pgbench_error(ERROR, "could not create thread: %s\n",+ strerror(err));
}
}
else
@@ -5688,8 +5831,11 @@ threadRun(void *arg)
if (thread->logfile == NULL)
{
- fprintf(stderr, "could not open logfile \"%s\": %s\n",- logpath, strerror(errno));+ /* we are sure that the function strerror is always called */+ Assert(LOG >= log_min_messages);++ pgbench_error(LOG, "could not open logfile \"%s\": %s\n",+ logpath, strerror(errno));
goto done;
}
}
@@ -5767,8 +5913,14 @@ threadRun(void *arg)
if (sock < 0)
{
- fprintf(stderr, "invalid socket: %s",- PQerrorMessage(st->con));+ /*+ * We are sure that the function PQerrorMessage is always+ * called.+ */+ Assert(LOG >= log_min_messages);++ pgbench_error(LOG, "invalid socket: %s",+ PQerrorMessage(st->con));
goto done;
}
@@ -5844,7 +5996,11 @@ threadRun(void *arg)
continue;
}
/* must be something wrong */
- fprintf(stderr, "select() failed: %s\n", strerror(errno));++ /* we are sure that the function strerror is always called */+ Assert(LOG >= log_min_messages);++ pgbench_error(LOG, "select() failed: %s\n", strerror(errno));
goto done;
}
}
@@ -5868,8 +6024,14 @@ threadRun(void *arg)
if (sock < 0)
{
- fprintf(stderr, "invalid socket: %s",- PQerrorMessage(st->con));+ /*+ * We are sure that the function PQerrorMessage is always+ * called.+ */+ Assert(LOG >= log_min_messages);++ pgbench_error(LOG, "invalid socket: %s",+ PQerrorMessage(st->con));
goto done;
}
@@ -5911,6 +6073,7 @@ threadRun(void *arg)
lag,
stdev;
char tbuf[315];
+ PQExpBufferData progress_buf;
/*
* Add up the statistics of all threads.
@@ -5968,18 +6131,29 @@ threadRun(void *arg)
snprintf(tbuf, sizeof(tbuf), "%.1f s", total_run);
}
- fprintf(stderr,- "progress: %s, %.1f tps, lat %.3f ms stddev %.3f",- tbuf, tps, latency, stdev);+ /*+ * We are sure that the allocated memory for the message is+ * always used.+ */+ Assert(LOG >= log_min_messages);++ initPQExpBuffer(&progress_buf);+ printfPQExpBuffer(&progress_buf,+ "progress: %s, %.1f tps, lat %.3f ms stddev %.3f",+ tbuf, tps, latency, stdev);
if (throttle_delay)
{
- fprintf(stderr, ", lag %.3f ms", lag);+ appendPQExpBuffer(&progress_buf, ", lag %.3f ms", lag);
if (latency_limit)
- fprintf(stderr, ", " INT64_FORMAT " skipped",- cur.skipped - last.skipped);+ appendPQExpBuffer(&progress_buf,+ ", " INT64_FORMAT " skipped",+ cur.skipped - last.skipped);
}
- fprintf(stderr, "\n");+ appendPQExpBufferChar(&progress_buf, '\n');++ pgbench_error(LOG, "%s", progress_buf.data);+ termPQExpBuffer(&progress_buf);
last = cur;
last_report = now;
@@ -6063,10 +6237,7 @@ setalarm(int seconds)
!CreateTimerQueueTimer(&timer, queue,
win32_timer_callback, NULL, seconds * 1000, 0,
WT_EXECUTEINTIMERTHREAD | WT_EXECUTEONLYONCE))
- {- fprintf(stderr, "failed to set timer\n");- exit(1);- }+ pgbench_error(ERROR, "failed to set timer\n");
}
/* partial pthread implementation for Windows */
@@ -6136,3 +6307,26 @@ pthread_join(pthread_t th, void **thread_return)
}
#endif /* WIN32 */
++static void+pgbench_error(ErrorLevel elevel, const char *fmt,...)+{+ va_list ap;++ /* Determine whether message is enabled for log output */+ if (elevel < log_min_messages)+ return;++ if (!fmt || !fmt[0])+ {+ /* internal error which should never occur */+ pgbench_error(ERROR, "empty error message cannot be reported\n");+ }++ va_start(ap, fmt);+ vfprintf(stderr, _(fmt), ap);+ va_end(ap);++ if (elevel >= ERROR)+ exit(1);+}diff --git a/src/interfaces/libpq/exports.txt b/src/interfaces/libpq/exports.txtindex d6a38d0..e983abc 100644--- a/src/interfaces/libpq/exports.txt+++ b/src/interfaces/libpq/exports.txt@@ -172,3 +172,4 @@ PQsslAttribute 169
PQsetErrorContextVisibility 170
PQresultVerboseErrorMessage 171
PQencryptPasswordConn 172
+appendPQExpBufferVA 173diff --git a/src/interfaces/libpq/pqexpbuffer.c b/src/interfaces/libpq/pqexpbuffer.cindex 86b16e6..3db2d4c 100644--- a/src/interfaces/libpq/pqexpbuffer.c+++ b/src/interfaces/libpq/pqexpbuffer.c@@ -37,8 +37,6 @@
/* All "broken" PQExpBuffers point to this string. */
static const char oom_buffer[1] = "";
-static bool appendPQExpBufferVA(PQExpBuffer str, const char *fmt, va_list args) pg_attribute_printf(2, 0);-
/*
* markPQExpBufferBroken
@@ -282,7 +280,7 @@ appendPQExpBuffer(PQExpBuffer str, const char *fmt,...)
* Attempt to format data and append it to str. Returns true if done
* (either successful or hard failure), false if need to retry.
*/
-static bool+bool
appendPQExpBufferVA(PQExpBuffer str, const char *fmt, va_list args)
{
size_t avail;
diff --git a/src/interfaces/libpq/pqexpbuffer.h b/src/interfaces/libpq/pqexpbuffer.hindex 771602a..b70b868 100644--- a/src/interfaces/libpq/pqexpbuffer.h+++ b/src/interfaces/libpq/pqexpbuffer.h@@ -158,6 +158,14 @@ extern void printfPQExpBuffer(PQExpBuffer str, const char *fmt,...) pg_attribute
extern void appendPQExpBuffer(PQExpBuffer str, const char *fmt,...) pg_attribute_printf(2, 3);
/*------------------------
+ * appendPQExpBufferVA+ * Shared guts of printfPQExpBuffer/appendPQExpBuffer.+ * Attempt to format data and append it to str. Returns true if done+ * (either successful or hard failure), false if need to retry.+ */+extern bool appendPQExpBufferVA(PQExpBuffer str, const char *fmt, va_list args) pg_attribute_printf(2, 0);++/*------------------------
* appendPQExpBufferStr
* Append the given string to a PQExpBuffer, allocating more space
* if necessary.
--
2.7.4
v10-0003-Pgbench-errors-use-the-Variables-structure-for-c.patch (text/x-diff, 17.1K) download
From 9a00415b91bcae2a0ee1cce4b9593a374b17b83b Mon Sep 17 00:00:00 2001
From: Marina Polyakova <m.polyakova@postgrespro.ru>
Date: Tue, 7 Aug 2018 13:29:38 +0300
Subject: [PATCH v10 3/4] Pgbench errors: use the Variables structure for
client variables
This is most important when it is used to reset client variables during the
repeating of transactions after serialization/deadlock failures.
Don't allocate Variable structs one by one. Instead, first time allocate 8
variables and then enlarge by duplicating size.
---
src/bin/pgbench/pgbench.c | 243 ++++++++++++++++++++++++++++++++--------------
1 file changed, 171 insertions(+), 72 deletions(-)
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.cindex c45cd44..4f8700b 100644--- a/src/bin/pgbench/pgbench.c+++ b/src/bin/pgbench/pgbench.c@@ -202,6 +202,12 @@ const char *progname;
volatile bool timer_exceeded = false; /* flag from signal handler */
/*
+ * The number of varaibles for which the array is allocated for the first time.+ * If necessary, every next time the array size just doubles.+ */+#define DEFAULT_MAX_VARIABLES 8++/*
* Variable definitions.
*
* If a variable only has a string value, "svalue" is that value, and value is
@@ -218,6 +224,24 @@ typedef struct
PgBenchValue value; /* actual variable's value */
} Variable;
+/*+ * Data structure for client variables.+ */+typedef struct+{+ Variable *vars; /* array of variable definitions */+ int nvars; /* number of variables */++ /*+ * The maximum number of variables that we can currently store in 'vars'+ * without having to reallocate more space. We must always have max_vars >=+ * nvars.+ */+ int max_vars;++ bool vars_sorted; /* are variables sorted by name? */+} Variables;+
#define MAX_SCRIPTS 128 /* max number of SQL scripts allowed */
#define SHELL_COMMAND_SIZE 256 /* maximum size allowed for shell command */
@@ -349,9 +373,7 @@ typedef struct
int command; /* command number in script */
/* client variables */
- Variable *variables; /* array of variable definitions */- int nvariables; /* number of variables */- bool vars_sorted; /* are variables sorted by name? */+ Variables variables;
/* various times about current transaction */
int64 txn_scheduled; /* scheduled start time of transaction (usec) */
@@ -1248,39 +1270,39 @@ compareVariableNames(const void *v1, const void *v2)
/* Locate a variable by name; returns NULL if unknown */
static Variable *
-lookupVariable(CState *st, char *name)+lookupVariable(Variables *variables, char *name)
{
Variable key;
/* On some versions of Solaris, bsearch of zero items dumps core */
- if (st->nvariables <= 0)+ if (variables->nvars <= 0)
return NULL;
/* Sort if we have to */
- if (!st->vars_sorted)+ if (!variables->vars_sorted)
{
- qsort((void *) st->variables, st->nvariables, sizeof(Variable),+ qsort((void *) variables->vars, variables->nvars, sizeof(Variable),
compareVariableNames);
- st->vars_sorted = true;+ variables->vars_sorted = true;
}
/* Now we can search */
key.name = name;
return (Variable *) bsearch((void *) &key,
- (void *) st->variables,- st->nvariables,+ (void *) variables->vars,+ variables->nvars,
sizeof(Variable),
compareVariableNames);
}
/* Get the value of a variable, in string form; returns NULL if unknown */
static char *
-getVariable(CState *st, char *name)+getVariable(Variables *variables, char *name)
{
Variable *var;
char stringform[64];
- var = lookupVariable(st, name);+ var = lookupVariable(variables, name);
if (var == NULL)
return NULL; /* not found */
@@ -1399,54 +1421,119 @@ valid_variable_name(const char *name)
}
/*
+ * Make sure there is enough space for 'needed' more variable in the variables+ * array.+ * On failure (too many variables are requested): if elevel < ERROR returns+ * false; exits the program otherwise.+ */+static bool+enlargeVariables(Variables *variables, const char *context, int needed,+ ErrorLevel elevel)+{+ size_t new_max_vars;+ Variable *new_vars;++ if ((size_t) variables->nvars + needed > INT_MAX)+ {+ if (elevel >= log_min_messages)+ {+ PQExpBufferData errmsg_buf;++ initPQExpBuffer(&errmsg_buf);+ if (context)+ appendPQExpBuffer(&errmsg_buf, "%s: ", context);+ appendPQExpBuffer(&errmsg_buf,+ "too many variables are used (limit is %d)\n",+ INT_MAX);+ pgbench_error(elevel, "%s", errmsg_buf.data);+ termPQExpBuffer(&errmsg_buf);+ }++ return false;+ }++ /* total number of variables required now */+ needed += variables->nvars;++ /* Because of the above test, we now have needed <= INT_MAX */++ if (needed <= variables->max_vars)+ return true; /* got enough space already */++ /*+ * We don't want to allocate just a little more space with each addition;+ * for efficiency, double the array size each time it overflows.+ * Actually, we might need to more than double it if 'needed' is big...+ */++ if (variables->max_vars > 0)+ new_max_vars = 2 * ((size_t) variables->max_vars);+ else+ new_max_vars = DEFAULT_MAX_VARIABLES;++ while ((size_t) needed > new_max_vars)+ new_max_vars = 2 * new_max_vars;++ /*+ * Clamp to INT_MAX in case we went past it. Note we are assuming here+ * that INT_MAX <= UINT_MAX/2, else the above loop could overflow. We+ * will still have new_max_vars >= needed_vars.+ */+ if (new_max_vars > (size_t) INT_MAX)+ new_max_vars = (size_t) INT_MAX;++ new_vars = (Variable *) pg_realloc(variables->vars,+ new_max_vars * sizeof(Variable));+ variables->vars = new_vars;+ variables->max_vars = new_max_vars;+ return true;+}++/*
* Lookup a variable by name, creating it if need be.
* Caller is expected to assign a value to the variable.
* On failure (bad name): if this is a client run returns NULL; exits the
* program otherwise.
*/
static Variable *
-lookupCreateVariable(CState *st, const char *context, char *name, bool client)+lookupCreateVariable(Variables *variables, const char *context, char *name,+ bool client)
{
Variable *var;
- var = lookupVariable(st, name);+ /*+ * About the error level used: if we process client commands, it a normal+ * failure; otherwise it is not and we exit the program.+ */+ ErrorLevel elevel = client ? LOG : ERROR;++ var = lookupVariable(variables, name);
if (var == NULL)
{
- Variable *newvars;-
/*
* Check for the name only when declaring a new variable to avoid
* overhead.
*/
if (!valid_variable_name(name))
{
- /*- * About the error level used: if we process client commands, it a- * normal failure; otherwise it is not and we exit the program.- */- pgbench_error(client ? LOG : ERROR,- "%s: invalid variable name: \"%s\"\n", context, name);+ pgbench_error(elevel, "%s: invalid variable name: \"%s\"\n",+ context, name);
return NULL;
}
/* Create variable at the end of the array */
- if (st->variables)- newvars = (Variable *) pg_realloc(st->variables,- (st->nvariables + 1) * sizeof(Variable));- else- newvars = (Variable *) pg_malloc(sizeof(Variable));-- st->variables = newvars;+ if (!enlargeVariables(variables, context, 1, elevel))+ return NULL;- var = &newvars[st->nvariables];+ var = &(variables->vars[variables->nvars]);
var->name = pg_strdup(name);
var->svalue = NULL;
/* caller is expected to initialize remaining fields */
- st->nvariables++;+ variables->nvars++;
/* we don't re-sort the array till we have to */
- st->vars_sorted = false;+ variables->vars_sorted = false;
}
return var;
@@ -1455,12 +1542,13 @@ lookupCreateVariable(CState *st, const char *context, char *name, bool client)
/* Assign a string value to a variable, creating it if need be */
/* Exits on failure (bad name) */
static void
-putVariable(CState *st, const char *context, char *name, const char *value)+putVariable(Variables *variables, const char *context, char *name,+ const char *value)
{
Variable *var;
char *val;
- var = lookupCreateVariable(st, context, name, false);+ var = lookupCreateVariable(variables, context, name, false);
/* dup then free, in case value is pointing at this variable */
val = pg_strdup(value);
@@ -1477,12 +1565,12 @@ putVariable(CState *st, const char *context, char *name, const char *value)
* program otherwise.
*/
static bool
-putVariableValue(CState *st, const char *context, char *name,+putVariableValue(Variables *variables, const char *context, char *name,
const PgBenchValue *value, bool client)
{
Variable *var;
- var = lookupCreateVariable(st, context, name, client);+ var = lookupCreateVariable(variables, context, name, client);
if (!var)
return false;
@@ -1500,13 +1588,13 @@ putVariableValue(CState *st, const char *context, char *name,
* program otherwise.
*/
static bool
-putVariableInt(CState *st, const char *context, char *name, int64 value,- bool client)+putVariableInt(Variables *variables, const char *context, char *name,+ int64 value, bool client)
{
PgBenchValue val;
setIntValue(&val, value);
- return putVariableValue(st, context, name, &val, client);+ return putVariableValue(variables, context, name, &val, client);
}
/*
@@ -1561,7 +1649,7 @@ replaceVariable(char **sql, char *param, int len, char *value)
}
static char *
-assignVariables(CState *st, char *sql)+assignVariables(Variables *variables, char *sql)
{
char *p,
*name,
@@ -1582,7 +1670,7 @@ assignVariables(CState *st, char *sql)
continue;
}
- val = getVariable(st, name);+ val = getVariable(variables, name);
free(name);
if (val == NULL)
{
@@ -1597,12 +1685,13 @@ assignVariables(CState *st, char *sql)
}
static void
-getQueryParams(CState *st, const Command *command, const char **params)+getQueryParams(Variables *variables, const Command *command,+ const char **params)
{
int i;
for (i = 0; i < command->argc - 1; i++)
- params[i] = getVariable(st, command->argv[i + 1]);+ params[i] = getVariable(variables, command->argv[i + 1]);
}
static char *
@@ -2471,7 +2560,7 @@ evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr, PgBenchValue *retval
{
Variable *var;
- if ((var = lookupVariable(st, expr->u.variable.varname)) == NULL)+ if ((var = lookupVariable(&st->variables, expr->u.variable.varname)) == NULL)
{
pgbench_error(LOG, "undefined variable \"%s\"\n",
expr->u.variable.varname);
@@ -2540,7 +2629,7 @@ getMetaCommand(const char *cmd)
* Return true if succeeded, or false on error.
*/
static bool
-runShellCommand(CState *st, char *variable, char **argv, int argc)+runShellCommand(Variables *variables, char *variable, char **argv, int argc)
{
char command[SHELL_COMMAND_SIZE];
int i,
@@ -2571,7 +2660,7 @@ runShellCommand(CState *st, char *variable, char **argv, int argc)
{
arg = argv[i] + 1; /* a string literal starting with colons */
}
- else if ((arg = getVariable(st, argv[i] + 1)) == NULL)+ else if ((arg = getVariable(variables, argv[i] + 1)) == NULL)
{
pgbench_error(LOG, "%s: undefined variable \"%s\"\n",
argv[0], argv[i]);
@@ -2641,7 +2730,7 @@ runShellCommand(CState *st, char *variable, char **argv, int argc)
argv[0], res);
return false;
}
- if (!putVariableInt(st, "setshell", variable, retval, true))+ if (!putVariableInt(variables, "setshell", variable, retval, true))
return false;
#ifdef DEBUG
@@ -2695,7 +2784,7 @@ sendCommand(CState *st, Command *command)
char *sql;
sql = pg_strdup(command->argv[0]);
- sql = assignVariables(st, sql);+ sql = assignVariables(&st->variables, sql);
pgbench_error(DEBUG, "client %d sending %s\n", st->id, sql);
r = PQsendQuery(st->con, sql);
@@ -2706,7 +2795,7 @@ sendCommand(CState *st, Command *command)
const char *sql = command->argv[0];
const char *params[MAX_ARGS];
- getQueryParams(st, command, params);+ getQueryParams(&st->variables, command, params);
pgbench_error(DEBUG, "client %d sending %s\n", st->id, sql);
r = PQsendQueryParams(st->con, sql, command->argc - 1,
@@ -2747,7 +2836,7 @@ sendCommand(CState *st, Command *command)
st->prepared[st->use_file] = true;
}
- getQueryParams(st, command, params);+ getQueryParams(&st->variables, command, params);
preparedStatementName(name, st->use_file, st->command);
pgbench_error(DEBUG, "client %d sending %s\n", st->id, name);
@@ -2773,14 +2862,14 @@ sendCommand(CState *st, Command *command)
* of delay, in microseconds. Returns true on success, false on error.
*/
static bool
-evaluateSleep(CState *st, int argc, char **argv, int *usecs)+evaluateSleep(Variables *variables, int argc, char **argv, int *usecs)
{
char *var;
int usec;
if (*argv[1] == ':')
{
- if ((var = getVariable(st, argv[1] + 1)) == NULL)+ if ((var = getVariable(variables, argv[1] + 1)) == NULL)
{
pgbench_error(LOG, "%s: undefined variable \"%s\"\n",
argv[0], argv[1]);
@@ -3060,7 +3149,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
*/
int usec;
- if (!evaluateSleep(st, argc, argv, &usec))+ if (!evaluateSleep(&st->variables, argc, argv, &usec))
{
commandFailed(st, "sleep", "execution of meta-command failed");
st->state = CSTATE_ABORTED;
@@ -3101,8 +3190,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
if (command->meta == META_SET)
{
- if (!putVariableValue(st, argv[0], argv[1], &result,- true))+ if (!putVariableValue(&st->variables, argv[0],+ argv[1], &result, true))
{
commandFailed(st, "set", "assignment of meta-command failed");
st->state = CSTATE_ABORTED;
@@ -3155,7 +3244,9 @@ doCustom(TState *thread, CState *st, StatsData *agg)
}
else if (command->meta == META_SETSHELL)
{
- bool ret = runShellCommand(st, argv[1], argv + 2, argc - 2);+ bool ret = runShellCommand(&st->variables,+ argv[1], argv + 2,+ argc - 2);
if (timer_exceeded) /* timeout */
{
@@ -3175,7 +3266,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
}
else if (command->meta == META_SHELL)
{
- bool ret = runShellCommand(st, NULL, argv + 1, argc - 1);+ bool ret = runShellCommand(&st->variables, NULL,+ argv + 1, argc - 1);
if (timer_exceeded) /* timeout */
{
@@ -5204,7 +5296,7 @@ main(int argc, char **argv)
}
*p++ = '\0';
- putVariable(&state[0], "option", optarg, p);+ putVariable(&state[0].variables, "option", optarg, p);
}
break;
case 'F':
@@ -5503,18 +5595,19 @@ main(int argc, char **argv)
int j;
state[i].id = i;
- for (j = 0; j < state[0].nvariables; j++)+ for (j = 0; j < state[0].variables.nvars; j++)
{
- Variable *var = &state[0].variables[j];+ Variable *var = &state[0].variables.vars[j];
if (var->value.type != PGBT_NO_VALUE)
{
- putVariableValue(&state[i], "startup",+ putVariableValue(&state[i].variables, "startup",
var->name, &var->value, false);
}
else
{
- putVariable(&state[i], "startup", var->name, var->svalue);+ putVariable(&state[i].variables, "startup", var->name,+ var->svalue);
}
}
}
@@ -5605,24 +5698,30 @@ main(int argc, char **argv)
* :scale variables normally get -s or database scale, but don't override
* an explicit -D switch
*/
- if (lookupVariable(&state[0], "scale") == NULL)+ if (lookupVariable(&state[0].variables, "scale") == NULL)
{
for (i = 0; i < nclients; i++)
- putVariableInt(&state[i], "startup", "scale", scale, false);+ {+ putVariableInt(&state[i].variables, "startup", "scale", scale,+ false);+ }
}
/*
* Define a :client_id variable that is unique per connection. But don't
* override an explicit -D switch.
*/
- if (lookupVariable(&state[0], "client_id") == NULL)+ if (lookupVariable(&state[0].variables, "client_id") == NULL)
{
for (i = 0; i < nclients; i++)
- putVariableInt(&state[i], "startup", "client_id", i, false);+ {+ putVariableInt(&state[i].variables, "startup", "client_id", i,+ false);+ }
}
/* set default seed for hash functions */
- if (lookupVariable(&state[0], "default_seed") == NULL)+ if (lookupVariable(&state[0].variables, "default_seed") == NULL)
{
uint64 seed = ((uint64) (random() & 0xFFFF) << 48) |
((uint64) (random() & 0xFFFF) << 32) |
@@ -5631,18 +5730,18 @@ main(int argc, char **argv)
for (i = 0; i < nclients; i++)
{
- putVariableInt(&state[i], "startup", "default_seed", (int64) seed,- false);+ putVariableInt(&state[i].variables, "startup", "default_seed",+ (int64) seed, false);
}
}
/* set random seed unless overwritten */
- if (lookupVariable(&state[0], "random_seed") == NULL)+ if (lookupVariable(&state[0].variables, "random_seed") == NULL)
{
for (i = 0; i < nclients; i++)
{
- putVariableInt(&state[i], "startup", "random_seed", random_seed,- false);+ putVariableInt(&state[i].variables, "startup", "random_seed",+ random_seed, false);
}
}
--
2.7.4
v10-0004-Pgbench-errors-and-serialization-deadlock-retrie.patch (text/x-diff, 102.1K) download
From 3200b96bd42cc279634575153ab8a94020ac37e2 Mon Sep 17 00:00:00 2001
From: Marina Polyakova <m.polyakova@postgrespro.ru>
Date: Tue, 7 Aug 2018 13:30:13 +0300
Subject: [PATCH v10 4/4] Pgbench errors and serialization/deadlock retries
Client's run is aborted only in case of a serious error, for example, the
connection with the backend was lost. Otherwise if the execution of SQL or meta
command fails, the client's run continues normally until the end of the current
script execution (it is assumed that one transaction script contains only one
transaction).
Transactions with serialization or deadlock failures are rolled back and
repeated until they complete successfully or reach the maximum number of tries
(specified by the --max-tries option) / the maximum time of tries (specified by
the --latency-limit option). These options can be combined together; but if
none of them are used, the default value for the option --max-tries is set to 1
and failed transactions are not retried at all. If the last transaction run
fails, this transaction will be reported as failed, and the client variables
will be set as they were before the first run of this transaction.
If there're retries and/or errors their statistics are printed in the progress,
in the transaction / aggregation logs and in the end with other results (all and
for each script). A transaction error is reported here only if the last try of
this transaction fails. Also retries and errors are printed per-command with
average latencies if you use the appropriate benchmarking option
(--report-per-command, -r). If you want to group errors by basic types
(serialization errors / deadlock errors / other SQL errors / errors in meta
commands), use the option --errors-detailed.
If you want to distinguish between failures or errors by type (including which
limit for retries was violated and how far it was exceeded for the
serialization/deadlock errors), use the pgbench debugging output created with
the option --debug-fails or --debug. The first option is recommended for this
purpose because with the second option the debugging output can be very large.
---
doc/src/sgml/ref/pgbench.sgml | 421 +++++++++-
src/bin/pgbench/pgbench.c | 1160 +++++++++++++++++++++++---
src/bin/pgbench/t/001_pgbench_with_server.pl | 372 ++++++++-
src/bin/pgbench/t/002_pgbench_no_server.pl | 5 +
src/fe_utils/conditional.c | 16 +-
src/include/fe_utils/conditional.h | 2 +
6 files changed, 1756 insertions(+), 220 deletions(-)
diff --git a/doc/src/sgml/ref/pgbench.sgml b/doc/src/sgml/ref/pgbench.sgmlindex 88cf8b3..12d1120 100644--- a/doc/src/sgml/ref/pgbench.sgml+++ b/doc/src/sgml/ref/pgbench.sgml@@ -55,16 +55,20 @@ number of clients: 10
number of threads: 1
number of transactions per client: 1000
number of transactions actually processed: 10000/10000
+maximum number of tries: 1
tps = 85.184871 (including connections establishing)
tps = 85.296346 (excluding connections establishing)
</screen>
The first six lines report some of the most important parameter
- settings. The next line reports the number of transactions completed+ settings. The seventh line reports the number of transactions completed
and intended (the latter being just the product of number of clients
and number of transactions per client); these will be equal unless the run
- failed before completion. (In <option>-T</option> mode, only the actual- number of transactions is printed.)+ failed before completion or some SQL/meta command(s) failed. (In+ <option>-T</option> mode, only the actual number of transactions is printed.)+ The next line reports the maximum number of tries for transactions with+ serialization and/or deadlock failures (see <xref linkend="errors-and-retries"+ endterm="errors-and-retries-title"/> for more information)
The last two lines report the number of transactions per second,
figured with and without counting the time to start database sessions.
</para>
@@ -453,6 +457,17 @@ pgbench <optional> <replaceable>options</replaceable> </optional> <replaceable>d
at all. They are counted and reported separately as
<firstterm>skipped</firstterm>.
</para>
+ <para>+ The transaction with serialization or deadlock failure can be retried if+ the total time of all its tries is less than+ <replaceable>limit</replaceable> ms. This option can be combined with+ the option <option>--max-tries</option> which limits the total number of+ transaction tries. If none of them is used, the default value for the+ option <option>--max-tries</option> is set to 1 and failed transactions+ are not retried at all. See <xref linkend="errors-and-retries"+ endterm="errors-and-retries-title"/> for more information about retrying+ failed transactions.+ </para>
</listitem>
</varlistentry>
@@ -513,22 +528,34 @@ pgbench <optional> <replaceable>options</replaceable> </optional> <replaceable>d
Show progress report every <replaceable>sec</replaceable> seconds. The report
includes the time since the beginning of the run, the TPS since the
last report, and the transaction latency average and standard
- deviation since the last report. Under throttling (<option>-R</option>),- the latency is computed with respect to the transaction scheduled- start time, not the actual transaction beginning time, thus it also- includes the average schedule lag time.+ deviation since the last report. If any transactions have received an+ error in the SQL or meta command since the last report, they are also+ reported as failed. Under throttling (<option>-R</option>), the latency+ is computed with respect to the transaction scheduled start time, not+ the actual transaction beginning time, thus it also includes the average+ schedule lag time. If any transactions have been rolled back and+ retried after a serialization/deadlock failure since the last report,+ the report includes the number of such transactions and the sum of all+ retries. Use the options <option>--max-tries</option> and/or+ <option>--latency-limit</option> to enable transactions retries after+ serialization/deadlock failures.
</para>
</listitem>
</varlistentry>
<varlistentry>
<term><option>-r</option></term>
- <term><option>--report-latencies</option></term>+ <term><option>--report-per-command</option></term>
<listitem>
<para>
- Report the average per-statement latency (execution time from the- perspective of the client) of each command after the benchmark- finishes. See below for details.+ Report the following statistics for each command after the benchmark+ finishes: the average per-statement latency (execution time from the+ perspective of the client), the number of errors and the number of+ retries after serialization or deadlock failures in this command. The+ report displays retry statistics only if the maximum number of tries for+ transactions is more than 1 (<option>--max-tries</option>) and/or the+ maximum time of tries for transactions is used+ (<option>--latency-limit</option>). See below for details.
</para>
</listitem>
</varlistentry>
@@ -657,6 +684,49 @@ pgbench <optional> <replaceable>options</replaceable> </optional> <replaceable>d
</varlistentry>
<varlistentry>
+ <term><option>--errors-detailed</option></term>+ <listitem>+ <para>+ Report errors in per-transaction and aggregation logs, as well as in the+ main and per-script reports, grouped by the following types:+ <itemizedlist>+ <listitem>+ <para>+ serialization errors;+ </para>+ </listitem>+ <listitem>+ <para>+ deadlock errors;+ </para>+ </listitem>+ <listitem>+ <para>+ other SQL errors;+ </para>+ </listitem>+ <listitem>+ <para>+ errors in meta commands.+ </para>+ </listitem>+ </itemizedlist>+ </para>+ </listitem>+ </varlistentry>++ <varlistentry>+ <term><option>--debug-fails</option></term>+ <listitem>+ <para>+ Print debugging output only for errors, serialization/deadlock failures+ and retries. See <xref linkend="errors-and-retries"+ endterm="errors-and-retries-title"/> for more information.+ </para>+ </listitem>+ </varlistentry>++ <varlistentry>
<term><option>--log-prefix=<replaceable>prefix</replaceable></option></term>
<listitem>
<para>
@@ -667,6 +737,22 @@ pgbench <optional> <replaceable>options</replaceable> </optional> <replaceable>d
</varlistentry>
<varlistentry>
+ <term><option>--max-tries=<replaceable>number_of_tries</replaceable></option></term>+ <listitem>+ <para>+ Set the maximum number of tries for transactions with+ serialization/deadlock failures. This option can be combined with the+ option <option>--latency-limit</option> which limits the total time of+ transaction tries. If none of them is used, the default value for the+ option <option>--max-tries</option> is set to 1 and failed transactions+ are not retried at all. See <xref linkend="errors-and-retries"+ endterm="errors-and-retries-title"/> for more information about retrying+ failed transactions.+ </para>+ </listitem>+ </varlistentry>++ <varlistentry>
<term><option>--progress-timestamp</option></term>
<listitem>
<para>
@@ -807,8 +893,8 @@ pgbench <optional> <replaceable>options</replaceable> </optional> <replaceable>d
<refsect1>
<title>Notes</title>
- <refsect2>- <title>What is the <quote>Transaction</quote> Actually Performed in <application>pgbench</application>?</title>+ <refsect2 id="transactions-and-scripts">+ <title id="transactions-and-scripts-title">What is the <quote>Transaction</quote> Actually Performed in <application>pgbench</application>?</title>
<para>
<application>pgbench</application> executes test scripts chosen randomly
@@ -1583,7 +1669,7 @@ END;
The format of the log is:
<synopsis>
-<replaceable>client_id</replaceable> <replaceable>transaction_no</replaceable> <replaceable>time</replaceable> <replaceable>script_no</replaceable> <replaceable>time_epoch</replaceable> <replaceable>time_us</replaceable> <optional> <replaceable>schedule_lag</replaceable> </optional>+<replaceable>client_id</replaceable> <replaceable>transaction_no</replaceable> <replaceable>time</replaceable> <replaceable>script_no</replaceable> <replaceable>time_epoch</replaceable> <replaceable>time_us</replaceable> <optional> <replaceable>schedule_lag</replaceable> </optional> <optional> <replaceable>retries</replaceable> </optional>
</synopsis>
where
@@ -1604,6 +1690,19 @@ END;
When both <option>--rate</option> and <option>--latency-limit</option> are used,
the <replaceable>time</replaceable> for a skipped transaction will be reported as
<literal>skipped</literal>.
+ <replaceable>retries</replaceable> is the sum of all the retries after the+ serialization or deadlock failures during the current script execution. It is+ only present when the maximum number of tries for transactions is more than 1+ (<option>--max-tries</option>) and/or the maximum time of tries for+ transactions is used (<option>--latency-limit</option>). If the transaction+ ended with an error, its <replaceable>time</replaceable> will be reported as+ <literal>failed</literal>. If you use the option+ <option>--errors-detailed</option> the <replaceable>time</replaceable> of the+ failed transaction will be reported as+ <literal>serialization_error</literal> / <literal>deadlock_error</literal> /+ <literal>another_sql_error</literal> / <literal>meta_command_error</literal>+ depending on the type of error (see <xref linkend="errors-and-retries"+ endterm="errors-and-retries-title"/> for more information).
</para>
<para>
@@ -1633,6 +1732,24 @@ END;
</para>
<para>
+ The following example shows a snippet of a log file with errors and retries,+ with the maximum number of tries set to 10 (note the additional+ <replaceable>retries</replaceable> column):+<screen>+3 0 47423 0 1499414498 34501 4+3 1 8333 0 1499414498 42848 1+3 2 8358 0 1499414498 51219 1+4 0 72345 0 1499414498 59433 7+1 3 41718 0 1499414498 67879 5+1 4 8416 0 1499414498 76311 1+3 3 33235 0 1499414498 84469 4+0 0 failed 0 1499414498 84905 10+2 0 failed 0 1499414498 86248 10+3 4 8307 0 1499414498 92788 1+</screen>+ </para>++ <para>
When running a long test on hardware that can handle a lot of transactions,
the log files can become very large. The <option>--sampling-rate</option> option
can be used to log only a random sample of transactions.
@@ -1647,7 +1764,7 @@ END;
format is used for the log files:
<synopsis>
-<replaceable>interval_start</replaceable> <replaceable>num_transactions</replaceable> <replaceable>sum_latency</replaceable> <replaceable>sum_latency_2</replaceable> <replaceable>min_latency</replaceable> <replaceable>max_latency</replaceable> <optional> <replaceable>sum_lag</replaceable> <replaceable>sum_lag_2</replaceable> <replaceable>min_lag</replaceable> <replaceable>max_lag</replaceable> <optional> <replaceable>skipped</replaceable> </optional> </optional>+<replaceable>interval_start</replaceable> <replaceable>num_transactions</replaceable> <replaceable>sum_latency</replaceable> <replaceable>sum_latency_2</replaceable> <replaceable>min_latency</replaceable> <replaceable>max_latency</replaceable> { <replaceable>failed_tx</replaceable> <optional> | <replaceable>serialization_errors</replaceable> <replaceable>deadlock_errors</replaceable> <replaceable>other_sql_errors</replaceable> <replaceable>meta_command_errors</replaceable> </optional> } <optional> <replaceable>sum_lag</replaceable> <replaceable>sum_lag_2</replaceable> <replaceable>min_lag</replaceable> <replaceable>max_lag</replaceable> <optional> <replaceable>skipped</replaceable> </optional> </optional> <optional> <replaceable>retried_tx</replaceable> <replaceable>retries</replaceable> </optional>
</synopsis>
where
@@ -1661,7 +1778,20 @@ END;
transaction latencies within the interval,
<replaceable>min_latency</replaceable> is the minimum latency within the interval,
and
- <replaceable>max_latency</replaceable> is the maximum latency within the interval.+ <replaceable>max_latency</replaceable> is the maximum latency within the interval,+ <replaceable>failed_tx</replaceable> is the number of transactions that ended+ with a failed SQL or meta command within the interval. If you use the option+ <option>--errors-detailed</option>, instead of the sum of all failed+ transactions you will get more detailed statistics for the failed+ transactions grouped by the following types:+ <replaceable>serialization_errors</replaceable> is the number of transactions+ that got a serialization failure and were not retried after this,+ <replaceable>deadlock_errors</replaceable> is the number of transactions that+ got a deadlock failure and were not retried after this,+ <replaceable>other_sql_errors</replaceable> is the number of transactions+ that got a different error in the SQL command,+ <replaceable>meta_command_errors</replaceable> is the number of transactions+ that got an error in the meta command.
The next fields,
<replaceable>sum_lag</replaceable>, <replaceable>sum_lag_2</replaceable>, <replaceable>min_lag</replaceable>,
and <replaceable>max_lag</replaceable>, are only present if the <option>--rate</option>
@@ -1669,21 +1799,28 @@ END;
They provide statistics about the time each transaction had to wait for the
previous one to finish, i.e. the difference between each transaction's
scheduled start time and the time it actually started.
- The very last field, <replaceable>skipped</replaceable>,+ The next field, <replaceable>skipped</replaceable>,
is only present if the <option>--latency-limit</option> option is used, too.
It counts the number of transactions skipped because they would have
started too late.
+ The <replaceable>retried_tx</replaceable> and+ <replaceable>retries</replaceable> fields are only present if the maximum+ number of tries for transactions is more than 1+ (<option>--max-tries</option>) and/or the maximum time of tries for+ transactions is used (<option>--latency-limit</option>). They report the+ number of retried transactions and the sum of all the retries after+ serialization or deadlock failures within the interval.
Each transaction is counted in the interval when it was committed.
</para>
<para>
Here is some example output:
<screen>
-1345828501 5601 1542744 483552416 61 2573-1345828503 7884 1979812 565806736 60 1479-1345828505 7208 1979422 567277552 59 1391-1345828507 7685 1980268 569784714 60 1398-1345828509 7073 1979779 573489941 236 1411+1345828501 5601 1542744 483552416 61 2573 0+1345828503 7884 1979812 565806736 60 1479 0+1345828505 7208 1979422 567277552 59 1391 0+1345828507 7685 1980268 569784714 60 1398 0+1345828509 7073 1979779 573489941 236 1411 0
</screen></para>
<para>
@@ -1695,13 +1832,45 @@ END;
</refsect2>
<refsect2>
- <title>Per-Statement Latencies</title>+ <title>Per-Statement Report</title>++ <para>+ With the <option>-r</option> option, <application>pgbench</application>+ collects the following statistics for each statement:+ <itemizedlist>+ <listitem>+ <para>+ <literal>latency</literal> — elapsed transaction time for each+ statement. <application>pgbench</application> reports an average value+ of all successful runs of the statement.+ </para>+ </listitem>+ <listitem>+ <para>+ The number of errors in this statement. See+ <xref linkend="errors-and-retries" endterm="errors-and-retries-title"/>+ for more information.+ </para>+ </listitem>+ <listitem>+ <para>+ The number of retries after a serialization or a deadlock failure in+ this statement. See <xref linkend="errors-and-retries"+ endterm="errors-and-retries-title"/> for more information.+ </para>+ </listitem>+ </itemizedlist>+ </para>++ <para>+ The report displays retry statistics only if the maximum number of tries for+ transactions is more than 1 (<option>--max-tries</option>) and/or the maximum+ time of tries for transactions is used (<option>--latency-limit</option>).+ </para>
<para>
- With the <option>-r</option> option, <application>pgbench</application> collects- the elapsed transaction time of each statement executed by every- client. It then reports an average of those values, referred to- as the latency for each statement, after the benchmark has finished.+ All values are computed for each statement executed by every client and are+ reported after the benchmark has finished.
</para>
<para>
@@ -1715,27 +1884,69 @@ number of clients: 10
number of threads: 1
number of transactions per client: 1000
number of transactions actually processed: 10000/10000
+maximum number of tries: 1
latency average = 15.844 ms
latency stddev = 2.715 ms
tps = 618.764555 (including connections establishing)
tps = 622.977698 (excluding connections establishing)
-statement latencies in milliseconds:- 0.002 \set aid random(1, 100000 * :scale)- 0.005 \set bid random(1, 1 * :scale)- 0.002 \set tid random(1, 10 * :scale)- 0.001 \set delta random(-5000, 5000)- 0.326 BEGIN;- 0.603 UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;- 0.454 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;- 5.528 UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;- 7.335 UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;- 0.371 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);- 1.212 END;+statement latencies in milliseconds and errors:+ 0.002 0 \set aid random(1, 100000 * :scale)+ 0.005 0 \set bid random(1, 1 * :scale)+ 0.002 0 \set tid random(1, 10 * :scale)+ 0.001 0 \set delta random(-5000, 5000)+ 0.326 0 BEGIN;+ 0.603 0 UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;+ 0.454 0 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;+ 5.528 0 UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;+ 7.335 0 UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;+ 0.371 0 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);+ 1.212 0 END;+</screen>++ Another example of output for the default script using serializable default+ transaction isolation level (<command>PGOPTIONS='-c+ default_transaction_isolation=serializable' pgbench ...</command>):+<screen>+starting vacuum...end.+transaction type: <builtin: TPC-B (sort of)>+scaling factor: 1+query mode: simple+number of clients: 10+number of threads: 1+number of transactions per client: 1000+number of transactions actually processed: 4473/10000+number of errors: 5527 (55.270%)+number of serialization errors: 5527 (55.270%)+number of retried: 7467 (74.670%)+number of retries: 257244+maximum number of tries: 100+number of transactions above the 100.0 ms latency limit: 5766/10000 (57.660 %) (including errors)+latency average = 41.169 ms+latency stddev = 51.783 ms+tps = 50.322494 (including connections establishing)+tps = 50.324595 (excluding connections establishing)+statement latencies in milliseconds, errors and retries:+ 0.004 0 0 \set aid random(1, 100000 * :scale)+ 0.000 0 0 \set bid random(1, 1 * :scale)+ 0.000 0 0 \set tid random(1, 10 * :scale)+ 0.000 0 0 \set delta random(-5000, 5000)+ 0.213 0 0 BEGIN;+ 0.393 0 0 UPDATE pgbench_accounts+ SET abalance = abalance + :delta WHERE aid = :aid;+ 0.332 0 0 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;+ 0.409 4971 250265 UPDATE pgbench_tellers+ SET tbalance = tbalance + :delta WHERE tid = :tid;+ 0.311 556 6975 UPDATE pgbench_branches+ SET bbalance = bbalance + :delta WHERE bid = :bid;+ 0.299 0 0 INSERT INTO pgbench_history+ (tid, bid, aid, delta, mtime)+ VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);+ 0.520 0 4 END;
</screen>
</para>
<para>
- If multiple script files are specified, the averages are reported+ If multiple script files are specified, all statistics are reported
separately for each script file.
</para>
@@ -1749,6 +1960,136 @@ statement latencies in milliseconds:
</para>
</refsect2>
+ <refsect2 id="errors-and-retries">+ <title id="errors-and-retries-title">Errors and Serialization/Deadlock Retries</title>++ <para>+ When executing <application>pgbench</application>, there're three main types of+ errors:+ <itemizedlist>+ <listitem>+ <para>+ Errors of the main program. They are the most serious and always result+ in an immediate exit from the <application>pgbench</application> with+ the corresponding error message. They include:+ <itemizedlist>+ <listitem>+ <para>+ errors at the beginning of the <application>pgbench</application>+ (e.g. an invalid option value);+ </para>+ </listitem>+ <listitem>+ <para>+ errors in the initialization mode (e.g. the query to create+ tables for built-in scripts fails);+ </para>+ </listitem>+ <listitem>+ <para>+ errors before starting threads (e.g. we could not connect to the+ database server / the syntax error in the meta command / thread+ creation failure);+ </para>+ </listitem>+ <listitem>+ <para>+ internal <application>pgbench</application> errors (which are+ supposed to never occur..).+ </para>+ </listitem>+ </itemizedlist>+ </para>+ </listitem>+ <listitem>+ <para>+ Errors when the thread manages its clients (e.g. the client could not+ start a connection to the database server / the socket for connecting+ the client to the database server has become invalid). In such cases+ all clients of this thread stop while other threads continue to work.+ </para>+ </listitem>+ <listitem>+ <para>+ Directly client errors. They lead to immediate exit from the+ <application>pgbench</application> with the corresponding error message+ only in the case of an internal <application>pgbench</application>+ error (which are supposed to never occur..). Otherwise in the worst+ case they only lead to the abortion of the failed client while other+ clients continue their run (but most client errors are handled without+ an abortion of the client and reported separately, see below). Later in+ this section it is assumed that the discussed failures and errors are+ only the directly client errors and they are not internal+ <application>pgbench</application> errors.+ </para>+ </listitem>+ </itemizedlist>+ </para>++ <para>+ Client's run is aborted only in case of a serious error, for example, the+ connection with the database server was lost. Otherwise if the execution of+ SQL or meta command fails, the failed transaction is always rolled back which+ also includes setting the client variables as they were before the run of+ this transaction (it is assumed that one transaction script contains only one+ transaction; see <xref linkend="transactions-and-scripts"+ endterm="transactions-and-scripts-title"/> for more information).+ Transactions with serialization or deadlock failures are repeated after+ rollbacks until they complete successfully or reach the maximum number of+ tries (specified by the <option>--max-tries</option> option) / the maximum+ time of tries (specified by the <option>--latency-limit</option> option). If+ the last transaction run fails, this transaction will be reported as failed.+ </para>++ <note>+ <para>+ Be careful when repeating scripts that contain multiple transactions: the+ script is always retried completely, so the successful transactions can be+ performed several times.+ </para>+ <para>+ Be careful when repeating scripts that continue the transaction block from+ the previous script: the command used to start this transaction block like+ all the commands from previous scripts is never used on a retry.+ </para>+ <para>+ Be careful when repeating transactions with shell commands. Unlike the+ results of SQL commands, the results of shell commands are not rolled back,+ except for the variable value of the <command>\setshell</command> command.+ </para>+ </note>++ <para>+ The latency of a successful transaction includes the entire time of+ transaction execution with rollbacks and retries. The latency for failed+ transactions and commands is not computed separately.+ </para>++ <para>+ The main report contains the number of failed transactions if it is non-zero+ (to group them into basic types, use the option+ <option>--errors-detailed</option>). If the total number of retried+ transactions is non-zero, the main report also contains the statistics+ related to retries: the total number of retried transactions and total number+ of retries. The per-script report inherits all these fields from the main+ report. The per-statement report displays retry statistics only if the+ maximum number of tries for transactions is more than 1+ (<option>--max-tries</option>) and/or the maximum time of tries for+ transactions is used (<option>--latency-limit</option>). A retry is reported+ for the command where the failure occured during the current script+ execution.+ </para>++ <para>+ If you want to distinguish between failures or errors by type (including+ which limit for retries was violated and how far it was exceeded for the+ serialization/deadlock errors), use the <application>pgbench</application>+ debugging output created with the option <option>--debug-fails</option> or+ <option>--debug</option>. The first option is recommended for this purpose+ because with the second option the debugging output can be very large.+ </para>+ </refsect2>+
<refsect2>
<title>Good Practices</title>
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.cindex 4f8700b..1ed24fd 100644--- a/src/bin/pgbench/pgbench.c+++ b/src/bin/pgbench/pgbench.c@@ -59,6 +59,8 @@
#include "pgbench.h"
+#define ERRCODE_T_R_SERIALIZATION_FAILURE "40001"+#define ERRCODE_T_R_DEADLOCK_DETECTED "40P01"
#define ERRCODE_UNDEFINED_TABLE "42P01"
/*
@@ -187,9 +189,30 @@ bool progress_timestamp = false; /* progress report with Unix time */
int nclients = 1; /* number of clients */
int nthreads = 1; /* number of threads */
bool is_connect; /* establish connection for each transaction */
-bool is_latencies; /* report per-command latencies */+bool report_per_command = false; /* report per-command latencies, retries+ * after the failures and errors+ * (failures without retrying) */
int main_pid; /* main process id used in log filename */
+/*+ * There're different types of restrictions for deciding that the current failed+ * transaction can no longer be retried and should be reported as failed:+ * - max_tries can be used to limit the number of tries;+ * - latency_limit can be used to limit the total time of tries.+ *+ * They can be combined together, and you need to use at least one of them to+ * retry the failed transactions. If none of them is used, the default value of+ * max_tries is set to 1 and failed transactions are not retried at all.+ */+uint32 max_tries = 0; /* we cannot retry a failed transaction if its+ * number of tries reaches this maximum; if its+ * value is zero, it is not used */++#define RETRIES_ENABLED (max_tries > 1 || latency_limit)++bool errors_detailed = false; /* whether to group errors in reports or+ * logs by basic types */+
char *pghost = "";
char *pgport = "";
char *login = NULL;
@@ -267,9 +290,58 @@ typedef struct SimpleStats
typedef struct StatsData
{
time_t start_time; /* interval start time, for aggregates */
- int64 cnt; /* number of transactions, including skipped */++ /*+ * All the transactions fall into 2 main types: is there any command that+ * got a failure during the last execution of the transaction script or not?+ * Thus+ *+ * the number of all transactions =+ * cnt (the number of successful ones) ++ * ecnt (the number of failed transactions).+ *+ * A successful transaction can be one of several types:+ *+ * cnt (the number of successful transactions) =+ * skipped (it was to late to execute them) ++ * retried (they got a serialization or a deadlock failure(s), but were+ * successfully retried from the very beginning) ++ * number of other transactions.+ *+ * A failed transaction can be one of several types:+ *+ * ecnt (the number of failed transactions) =+ * serialization_errors (they got a serialization failure and were not+ * retried) ++ * deadlock_errors (they got a deadlock failure and were not retried) ++ * other_sql_errors (they got a different error in the SQL command) ++ * meta_command_errors (they got an error in the meta command).+ *+ * If the transaction was retried after a serialization or a deadlock+ * failure this does not guarantee that this retry was successfull. Thus+ *+ * number of retries =+ * number of retries in (retried + serialization_errors + deadlock_errors)+ * transactions.+ */+ int64 cnt; /* number of sucessfull transactions, including+ * skipped */
int64 skipped; /* number of transactions skipped under --rate
* and --latency-limit */
+ int64 retries; /* number of retries after a serialization or a+ * deadlock failure in all the transactions */+ int64 retried; /* number of transactions that were retried+ * after a serialization or a deadlock+ * failure */+ int64 serialization_errors; /* number of transactions that were not+ * retried after a serialization+ * failure */+ int64 deadlock_errors; /* number of transactions that were not+ * retried after a deadlock failure */+ int64 other_sql_errors; /* number of transactions with a different+ * error in the SQL command */+ int64 meta_command_errors; /* number of transactions with an error+ * in the meta command */
SimpleStats latency;
SimpleStats lag;
} StatsData;
@@ -283,6 +355,29 @@ typedef struct
} RandomState;
/*
+ * Data structure for repeating a transaction from the beginnning with the same+ * parameters.+ */+typedef struct+{+ RandomState random_state; /* random seed */+ Variables variables; /* client variables */+} RetryState;++/*+ * For the failures during script execution.+ */+typedef enum FailureStatus+{+ NO_FAILURE = 0,+ META_COMMAND_FAILURE,+ ANOTHER_SQL_FAILURE, /* other failures in SQL commands that are not+ * listed by themselves below */+ SERIALIZATION_FAILURE,+ DEADLOCK_FAILURE+} FailureStatus;++/*
* Connection state machine states.
*/
typedef enum
@@ -337,6 +432,23 @@ typedef enum
CSTATE_END_COMMAND,
/*
+ * States for failed commands.+ *+ * If the SQL/meta command fails, in CSTATE_FAILURE abort the current+ * transaction execution, roll back the failed transaction block if any and+ * clear the conditional stack. Then go to CSTATE_RETRY. If this is a+ * serialization or deadlock failure and we can re-execute the transaction+ * from the very beginning, report this as a failure, set the same+ * parameters for the transaction execution as in the previous tries and+ * process the first transaction command in CSTATE_START_COMMAND. Otherwise,+ * report this as an error, set the parameters for the transaction execution+ * as they were before the first run of this transaction (except for a+ * random state) and go to CSTATE_END_TX to complete this transaction.+ */+ CSTATE_FAILURE,+ CSTATE_RETRY,++ /*
* CSTATE_END_TX performs end-of-transaction processing. Calculates
* latency, and logs the transaction. In --connect mode, closes the
* current connection. Chooses the next script to execute and starts over
@@ -383,6 +495,18 @@ typedef struct
bool prepared[MAX_SCRIPTS]; /* whether client prepared the script */
+ /*+ * For processing errors and repeating transactions with serialization or+ * deadlock failures:+ */+ FailureStatus failure_status; /* the failure status of the current+ * transaction execution; this is NO_FAILURE+ * if there were no failures */+ RetryState retry_state;+ uint32 retries; /* how many times have we already retried the+ * current transaction after a serialization or+ * a deadlock failure? */+
/* per client collected stats */
int64 cnt; /* client transaction count, for -t */
int ecnt; /* error count */
@@ -445,7 +569,8 @@ typedef struct
instr_time start_time; /* thread start time */
instr_time conn_time;
StatsData stats;
- int64 latency_late; /* executed but late transactions */+ int64 latency_late; /* executed but late transactions (including+ * errors) */
} TState;
#define INVALID_THREAD ((pthread_t) 0)
@@ -491,6 +616,9 @@ typedef struct
char *argv[MAX_ARGS]; /* command word list */
PgBenchExpr *expr; /* parsed expression, if needed */
SimpleStats stats; /* time spent in this command */
+ int64 retries; /* number of retries after a serialization or a+ * deadlock failure */+ int64 ecnt; /* number of failures that were not retried */
} Command;
typedef struct ParsedScript
@@ -560,9 +688,15 @@ typedef enum ErrorLevel
DEBUG,
/*
+ * Normal failure of the SQL/meta command, or processing of the failed+ * transaction (its end/retry).+ */+ DEBUG_FAIL,++ /*
* To report:
- * - abortion of the client (something bad e.g. the SQL/meta command failed- * or the connection with the backend was lost);+ * - abortion of the client (something serious e.g. connection with the+ * backend was lost);
* - the log messages of the main program;
* - PGBENCH_DEBUG messages.
*/
@@ -596,7 +730,6 @@ static void finishCon(CState *st);
static void pgbench_error(ErrorLevel elevel,
const char *fmt,...) pg_attribute_printf(2, 3);
-
/* callback functions for our flex lexer */
static const PsqlScanCallbacks pgbench_callbacks = {
NULL, /* don't need get_variable functionality */
@@ -643,15 +776,18 @@ usage(void)
" protocol for submitting queries (default: simple)\n"
" -n, --no-vacuum do not run VACUUM before tests\n"
" -P, --progress=NUM show thread progress report every NUM seconds\n"
- " -r, --report-latencies report average latency per command\n"+ " -r, --report-per-command report latencies, errors and retries per command\n"
" -R, --rate=NUM target rate in transactions per second\n"
" -s, --scale=NUM report this scale factor in output\n"
" -t, --transactions=NUM number of transactions each client runs (default: 10)\n"
" -T, --time=NUM duration of benchmark test in seconds\n"
" -v, --vacuum-all vacuum all four standard tables before tests\n"
" --aggregate-interval=NUM aggregate data over NUM seconds\n"
+ " --debug-fails print debugging output only for failures and errors\n"+ " --errors-detailed report the errors grouped by basic types\n"
" --log-prefix=PREFIX prefix for transaction time log file\n"
" (default: \"pgbench_log\")\n"
+ " --max-tries=NUM max number of tries to run transaction\n"
" --progress-timestamp use Unix epoch timestamps for progress\n"
" --random-seed=SEED set random seed (\"time\", \"rand\", integer)\n"
" --sampling-rate=NUM fraction of transactions to log (e.g., 0.01 for 1%%)\n"
@@ -1112,6 +1248,12 @@ initStats(StatsData *sd, time_t start_time)
sd->start_time = start_time;
sd->cnt = 0;
sd->skipped = 0;
+ sd->retries = 0;+ sd->retried = 0;+ sd->serialization_errors = 0;+ sd->deadlock_errors = 0;+ sd->other_sql_errors = 0;+ sd->meta_command_errors = 0;
initSimpleStats(&sd->latency);
initSimpleStats(&sd->lag);
}
@@ -1120,10 +1262,47 @@ initStats(StatsData *sd, time_t start_time)
* Accumulate one additional item into the given stats object.
*/
static void
-accumStats(StatsData *stats, bool skipped, double lat, double lag)+accumStats(StatsData *stats, bool skipped, double lat, double lag,+ FailureStatus failure_status, int64 retries)
{
- stats->cnt++;+ /*+ * Record the number of retries regardless of whether the transaction was+ * successful or failed.+ */+ stats->retries += retries;+ if (retries > 0)+ stats->retried++;++ /* Record the failed transaction */+ if (failure_status != NO_FAILURE)+ {+ if (failure_status == SERIALIZATION_FAILURE)+ {+ stats->serialization_errors++;+ }+ else if (failure_status == DEADLOCK_FAILURE)+ {+ stats->deadlock_errors++;+ }+ else if (failure_status == ANOTHER_SQL_FAILURE)+ {+ stats->other_sql_errors++;+ }+ else if (failure_status == META_COMMAND_FAILURE)+ {+ stats->meta_command_errors++;+ }+ else+ {+ /* internal error which should never occur */+ pgbench_error(ERROR, "unexpected failure status: %d\n",+ failure_status);+ }+ return;+ }+ /* Record the successful transaction */+ stats->cnt++;
if (skipped)
{
/* no latency to record on skipped transactions */
@@ -1376,7 +1555,7 @@ makeVariableValue(Variable *var)
if (sscanf(var->svalue, "%lf%c", &dv, &xs) != 1)
{
- pgbench_error(LOG,+ pgbench_error(DEBUG_FAIL,
"malformed variable \"%s\" value: \"%s\"\n",
var->name, var->svalue);
return false;
@@ -1505,7 +1684,7 @@ lookupCreateVariable(Variables *variables, const char *context, char *name,
* About the error level used: if we process client commands, it a normal
* failure; otherwise it is not and we exit the program.
*/
- ErrorLevel elevel = client ? LOG : ERROR;+ ErrorLevel elevel = client ? DEBUG_FAIL : ERROR;
var = lookupVariable(variables, name);
if (var == NULL)
@@ -1726,11 +1905,12 @@ coerceToBool(PgBenchValue *pval, bool *bval)
}
else /* NULL, INT or DOUBLE */
{
- /* we are sure that the function valueTypeName only is always called */- Assert(LOG >= log_min_messages);-- pgbench_error(LOG, "cannot coerce %s to boolean\n",- valueTypeName(pval));+ /* call the function valueTypeName only if necessary */+ if (DEBUG_FAIL >= log_min_messages)+ {+ pgbench_error(DEBUG_FAIL, "cannot coerce %s to boolean\n",+ valueTypeName(pval));+ }
*bval = false; /* suppress uninitialized-variable warnings */
return false;
}
@@ -1775,7 +1955,7 @@ coerceToInt(PgBenchValue *pval, int64 *ival)
if (dval < PG_INT64_MIN || PG_INT64_MAX < dval)
{
- pgbench_error(LOG, "double to int overflow for %f\n", dval);+ pgbench_error(DEBUG_FAIL, "double to int overflow for %f\n", dval);
return false;
}
*ival = (int64) dval;
@@ -1783,10 +1963,12 @@ coerceToInt(PgBenchValue *pval, int64 *ival)
}
else /* BOOLEAN or NULL */
{
- /* we are sure that the function valueTypeName is always called */- Assert(LOG >= log_min_messages);-- pgbench_error(LOG, "cannot coerce %s to int\n", valueTypeName(pval));+ /* call the function valueTypeName only if necessary */+ if (DEBUG_FAIL >= log_min_messages)+ {+ pgbench_error(DEBUG_FAIL, "cannot coerce %s to int\n",+ valueTypeName(pval));+ }
return false;
}
}
@@ -1807,10 +1989,12 @@ coerceToDouble(PgBenchValue *pval, double *dval)
}
else /* BOOLEAN or NULL */
{
- /* we are sure that the function valueTypeName is always called */- Assert(LOG >= log_min_messages);-- pgbench_error(LOG, "cannot coerce %s to double\n", valueTypeName(pval));+ /* call the function valueTypeName only if necessary */+ if (DEBUG_FAIL >= log_min_messages)+ {+ pgbench_error(DEBUG_FAIL, "cannot coerce %s to double\n",+ valueTypeName(pval));+ }
return false;
}
}
@@ -1991,7 +2175,8 @@ evalStandardFunc(TState *thread, CState *st,
if (l != NULL)
{
- pgbench_error(LOG, "too many function arguments, maximum is %d\n",+ pgbench_error(DEBUG_FAIL,+ "too many function arguments, maximum is %d\n",
MAX_FARGS);
return false;
}
@@ -2115,7 +2300,7 @@ evalStandardFunc(TState *thread, CState *st,
case PGBENCH_MOD:
if (ri == 0)
{
- pgbench_error(LOG, "division by zero\n");+ pgbench_error(DEBUG_FAIL, "division by zero\n");
return false;
}
/* special handling of -1 divisor */
@@ -2126,7 +2311,7 @@ evalStandardFunc(TState *thread, CState *st,
/* overflow check (needed for INT64_MIN) */
if (li == PG_INT64_MIN)
{
- pgbench_error(LOG,+ pgbench_error(DEBUG_FAIL,
"bigint out of range\n");
return false;
}
@@ -2393,13 +2578,13 @@ evalStandardFunc(TState *thread, CState *st,
/* check random range */
if (imin > imax)
{
- pgbench_error(LOG, "empty range given to random\n");+ pgbench_error(DEBUG_FAIL, "empty range given to random\n");
return false;
}
else if (imax - imin < 0 || (imax - imin) + 1 < 0)
{
/* prevent int overflows in random functions */
- pgbench_error(LOG, "random range is too large\n");+ pgbench_error(DEBUG_FAIL, "random range is too large\n");
return false;
}
@@ -2421,7 +2606,7 @@ evalStandardFunc(TState *thread, CState *st,
{
if (param < MIN_GAUSSIAN_PARAM)
{
- pgbench_error(LOG,+ pgbench_error(DEBUG_FAIL,
"gaussian parameter must be at least %f (not %f)\n",
MIN_GAUSSIAN_PARAM, param);
return false;
@@ -2435,7 +2620,7 @@ evalStandardFunc(TState *thread, CState *st,
{
if (param <= 0.0 || param == 1.0 || param > MAX_ZIPFIAN_PARAM)
{
- pgbench_error(LOG,+ pgbench_error(DEBUG_FAIL,
"zipfian parameter must be in range (0, 1) U (1, %d] (got %f)\n",
MAX_ZIPFIAN_PARAM, param);
return false;
@@ -2449,7 +2634,7 @@ evalStandardFunc(TState *thread, CState *st,
{
if (param <= 0.0)
{
- pgbench_error(LOG,+ pgbench_error(DEBUG_FAIL,
"exponential parameter must be greater than zero (got %f)\n",
param);
return false;
@@ -2562,7 +2747,7 @@ evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr, PgBenchValue *retval
if ((var = lookupVariable(&st->variables, expr->u.variable.varname)) == NULL)
{
- pgbench_error(LOG, "undefined variable \"%s\"\n",+ pgbench_error(DEBUG_FAIL, "undefined variable \"%s\"\n",
expr->u.variable.varname);
return false;
}
@@ -2662,7 +2847,7 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc)
}
else if ((arg = getVariable(variables, argv[i] + 1)) == NULL)
{
- pgbench_error(LOG, "%s: undefined variable \"%s\"\n",+ pgbench_error(DEBUG_FAIL, "%s: undefined variable \"%s\"\n",
argv[0], argv[i]);
return false;
}
@@ -2670,7 +2855,8 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc)
arglen = strlen(arg);
if (len + arglen + (i > 0 ? 1 : 0) >= SHELL_COMMAND_SIZE - 1)
{
- pgbench_error(LOG, "%s: shell command is too long\n", argv[0]);+ pgbench_error(DEBUG_FAIL, "%s: shell command is too long\n",+ argv[0]);
return false;
}
@@ -2689,8 +2875,8 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc)
{
if (!timer_exceeded)
{
- pgbench_error(LOG, "%s: could not launch shell command\n",- argv[0]);+ pgbench_error(DEBUG_FAIL,+ "%s: could not launch shell command\n", argv[0]);
}
return false;
}
@@ -2700,14 +2886,16 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc)
/* Execute the command with pipe and read the standard output. */
if ((fp = popen(command, "r")) == NULL)
{
- pgbench_error(LOG, "%s: could not launch shell command\n", argv[0]);+ pgbench_error(DEBUG_FAIL, "%s: could not launch shell command\n",+ argv[0]);
return false;
}
if (fgets(res, sizeof(res), fp) == NULL)
{
if (!timer_exceeded)
{
- pgbench_error(LOG, "%s: could not read result of shell command\n",+ pgbench_error(DEBUG_FAIL,+ "%s: could not read result of shell command\n",
argv[0]);
}
(void) pclose(fp);
@@ -2715,7 +2903,8 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc)
}
if (pclose(fp) < 0)
{
- pgbench_error(LOG, "%s: could not close shell command\n", argv[0]);+ pgbench_error(DEBUG_FAIL, "%s: could not close shell command\n",+ argv[0]);
return false;
}
@@ -2725,7 +2914,7 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc)
endptr++;
if (*res == '\0' || *endptr != '\0')
{
- pgbench_error(LOG,+ pgbench_error(DEBUG_FAIL,
"%s: shell command must return an integer (not \"%s\")\n",
argv[0], res);
return false;
@@ -2747,11 +2936,20 @@ preparedStatementName(char *buffer, int file, int state)
}
static void
-commandFailed(CState *st, const char *cmd, const char *message)+commandFailed(CState *st, const char *cmd, const char *message, bool aborted)
{
- pgbench_error(LOG,- "client %d aborted in command %d (%s) of script %d; %s\n",- st->id, st->command, cmd, st->use_file, message);+ if (aborted)+ {+ pgbench_error(LOG,+ "client %d aborted in command %d (%s) of script %d; %s\n",+ st->id, st->command, cmd, st->use_file, message);+ }+ else+ {+ pgbench_error(DEBUG_FAIL,+ "client %d got a failure in command %d (%s) of script %d; %s\n",+ st->id, st->command, cmd, st->use_file, message);+ }
}
/* return a script number with a weighted choice. */
@@ -2850,7 +3048,6 @@ sendCommand(CState *st, Command *command)
{
pgbench_error(DEBUG, "client %d could not send %s\n",
st->id, command->argv[0]);
- st->ecnt++;
return false;
}
else
@@ -2871,7 +3068,7 @@ evaluateSleep(Variables *variables, int argc, char **argv, int *usecs)
{
if ((var = getVariable(variables, argv[1] + 1)) == NULL)
{
- pgbench_error(LOG, "%s: undefined variable \"%s\"\n",+ pgbench_error(DEBUG_FAIL, "%s: undefined variable \"%s\"\n",
argv[0], argv[1]);
return false;
}
@@ -2895,6 +3092,225 @@ evaluateSleep(Variables *variables, int argc, char **argv, int *usecs)
}
/*
+ * Get the number of all processed transactions including skipped ones and+ * errors.+ */+static int64+getTotalCnt(const CState *st)+{+ return st->cnt + st->ecnt;+}++static int64+getEcnt(const StatsData *stats)+{+ return (stats->serialization_errors ++ stats->deadlock_errors ++ stats->other_sql_errors ++ stats->meta_command_errors);+}++/*+ * Clear the variables in the array. The array itself is not freed.+ */+static void+clearVariables(Variables *variables)+{+ Variable *vars,+ *var;+ int nvars;++ if (!variables)+ return; /* nothing to do here */++ vars = variables->vars;+ nvars = variables->nvars;+ for (var = vars; var - vars < nvars; ++var)+ {+ pg_free(var->name);+ pg_free(var->svalue);+ }++ variables->nvars = 0;+}++/*+ * Make a deep copy of variables array.+ * Before copying the function frees the string fields of the destination+ * variables and if necessary enlarges their array.+ * On failure (too many variables are used in the source) returns false.+ */+static bool+copyVariables(Variables *dest, const Variables *source)+{+ Variable *dest_var;+ const Variable *source_vars,+ *source_var;+ int nvars;++ if (!dest || !source || dest == source)+ return true; /* nothing to do here */++ source_vars = source->vars;+ nvars = source->nvars;++ /*+ * Clear the original variables and make sure that we have enough space for+ * the new variables.+ */++ clearVariables(dest);++ /*+ * In case of an error the client will be aborted so always print an error+ * message.+ */+ if (!enlargeVariables(dest, NULL, nvars, LOG))+ return false;++ /* Make a deep copy of variables array */+ for (source_var = source_vars, dest_var = dest->vars;+ source_var - source_vars < nvars;+ ++source_var, ++dest_var)+ {+ dest_var->name = pg_strdup(source_var->name);+ if (source_var->svalue == NULL)+ dest_var->svalue = NULL;+ else+ dest_var->svalue = pg_strdup(source_var->svalue);+ dest_var->value = source_var->value;+ }+ dest->nvars = nvars;+ dest->vars_sorted = source->vars_sorted;+ return true;+}++/*+ * Returns true if this type of failure can be retried.+ */+static bool+canRetryFailure(FailureStatus failure_status)+{+ return (failure_status == SERIALIZATION_FAILURE ||+ failure_status == DEADLOCK_FAILURE);+}++/*+ * Returns true if the failure can be retried.+ */+static bool+canRetry(CState *st, instr_time *now)+{+ FailureStatus failure_status = st->failure_status;++ Assert(failure_status != NO_FAILURE);++ /* We can only retry serialization or deadlock failures. */+ if (!canRetryFailure(failure_status))+ return false;++ /*+ * We must have at least one option to limit the retrying of failed+ * transactions.+ */+ Assert(max_tries || latency_limit);++ /*+ * We cannot retry the failure if we have reached the maximum number of+ * tries.+ */+ if (max_tries && st->retries + 1 >= max_tries)+ return false;++ /*+ * We cannot retry the failure if we spent too much time on this+ * transaction.+ */+ if (latency_limit)+ {+ if (INSTR_TIME_IS_ZERO(*now))+ INSTR_TIME_SET_CURRENT(*now);++ if (INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled >= latency_limit)+ return false;+ }++ /* OK */+ return true;+}++/*+ * Get the failure status from the error code.+ */+static FailureStatus+getSQLFailureStatus(char *sqlState)+{+ if (sqlState)+ {+ if (strcmp(sqlState, ERRCODE_T_R_SERIALIZATION_FAILURE) == 0)+ return SERIALIZATION_FAILURE;+ else if (strcmp(sqlState, ERRCODE_T_R_DEADLOCK_DETECTED) == 0)+ return DEADLOCK_FAILURE;+ }++ return ANOTHER_SQL_FAILURE;+}++static bool+inTransactionBlock(CState *st)+{+ PGTransactionStatusType tx_status;++ tx_status = PQtransactionStatus(st->con);+ switch (tx_status)+ {+ case PQTRANS_IDLE:+ return false;+ case PQTRANS_INTRANS:+ case PQTRANS_INERROR:+ return true;+ case PQTRANS_UNKNOWN:+ /* PQTRANS_UNKNOWN is expected given a broken connection */+ if (PQstatus(st->con) == CONNECTION_BAD)+ { /* there's something wrong */+ pgbench_error(LOG,+ "client %d aborted while receiving the transaction status; perhaps the backend died while processing\n",+ st->id);+ st->state = CSTATE_ABORTED;+ return false; /* return value does not matter */+ }+ case PQTRANS_ACTIVE:+ default:+ /*+ * We cannot find out whether we are in a transaction block or not.+ * Internal error which should never occur.+ */+ pgbench_error(LOG,+ "client %d aborted while receiving the transaction status; unexpected transaction status %d\n",+ st->id, tx_status);+ st->state = CSTATE_ABORTED;+ return false; /* return value does not matter */+ }+}++/*+ * If the latency limit is used, return a percentage of the current transaction+ * latency from the latency limit. Otherwise return zero.+ */+static double+getLatencyUsed(CState *st, instr_time *now)+{+ if (!latency_limit)+ return 0.0;++ if (INSTR_TIME_IS_ZERO(*now))+ INSTR_TIME_SET_CURRENT(*now);++ return (100.0 * (INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled) /+ latency_limit);+}++/*
* Advance the state machine of a connection, if possible.
*/
static void
@@ -2944,6 +3360,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
st->state = CSTATE_START_TX;
/* check consistency */
Assert(conditional_stack_empty(st->cstack));
++ /* reset transaction variables to default values */+ st->failure_status = NO_FAILURE;+ st->retries = 0;+
break;
/*
@@ -2991,7 +3412,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
INSTR_TIME_SET_CURRENT(now);
now_us = INSTR_TIME_GET_MICROSEC(now);
while (thread->throttle_trigger < now_us - latency_limit &&
- (nxacts <= 0 || st->cnt < nxacts))+ (nxacts <= 0 || getTotalCnt(st) < nxacts))
{
processXactStats(thread, st, &now, true, agg);
/* next rendez-vous */
@@ -3001,7 +3422,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
st->txn_scheduled = thread->throttle_trigger;
}
/* stop client if -t exceeded */
- if (nxacts > 0 && st->cnt >= nxacts)+ if (nxacts > 0 && getTotalCnt(st) >= nxacts)
{
st->state = CSTATE_FINISHED;
break;
@@ -3057,6 +3478,22 @@ doCustom(TState *thread, CState *st, StatsData *agg)
}
/*
+ * It is the first try to run this transaction. Remember its+ * parameters just in case if it fails or we should repeat it in+ * future.+ */+ memcpy(&(st->retry_state.random_state), &(st->random_state),+ sizeof(RandomState));+ if (!copyVariables(&st->retry_state.variables, &st->variables))+ {+ pgbench_error(LOG,+ "client %d aborted when preparing to execute a transaction\n",+ st->id);+ st->state = CSTATE_ABORTED;+ break;+ }++ /*
* Record transaction start time under logging, progress or
* throttling.
*/
@@ -3100,7 +3537,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
* Record statement start time if per-command latencies are
* requested
*/
- if (is_latencies)+ if (report_per_command)
{
if (INSTR_TIME_IS_ZERO(now))
INSTR_TIME_SET_CURRENT(now);
@@ -3111,7 +3548,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
{
if (!sendCommand(st, command))
{
- commandFailed(st, "SQL", "SQL command send failed");+ commandFailed(st, "SQL", "SQL command send failed",+ true);
st->state = CSTATE_ABORTED;
}
else
@@ -3151,8 +3589,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
if (!evaluateSleep(&st->variables, argc, argv, &usec))
{
- commandFailed(st, "sleep", "execution of meta-command failed");- st->state = CSTATE_ABORTED;+ commandFailed(st, "sleep",+ "execution of meta-command failed",+ false);+ st->failure_status = META_COMMAND_FAILURE;+ st->state = CSTATE_FAILURE;
break;
}
@@ -3183,18 +3624,24 @@ doCustom(TState *thread, CState *st, StatsData *agg)
if (!evaluateExpr(thread, st, expr, &result))
{
- commandFailed(st, argv[0], "evaluation of meta-command failed");- st->state = CSTATE_ABORTED;+ commandFailed(st, argv[0],+ "evaluation of meta-command failed",+ false);+ st->failure_status = META_COMMAND_FAILURE;+ st->state = CSTATE_FAILURE;
break;
}
if (command->meta == META_SET)
{
- if (!putVariableValue(&st->variables, argv[0],- argv[1], &result, true))+ if (!putVariableValue(&st->variables, argv[0],+ argv[1], &result, true))
{
- commandFailed(st, "set", "assignment of meta-command failed");- st->state = CSTATE_ABORTED;+ commandFailed(st, "set",+ "assignment of meta-command failed",+ false);+ st->failure_status = META_COMMAND_FAILURE;+ st->state = CSTATE_FAILURE;
break;
}
}
@@ -3255,8 +3702,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
}
else if (!ret) /* on error */
{
- commandFailed(st, "setshell", "execution of meta-command failed");- st->state = CSTATE_ABORTED;+ commandFailed(st, "setshell",+ "execution of meta-command failed",+ false);+ st->failure_status = META_COMMAND_FAILURE;+ st->state = CSTATE_FAILURE;
break;
}
else
@@ -3276,8 +3726,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
}
else if (!ret) /* on error */
{
- commandFailed(st, "shell", "execution of meta-command failed");- st->state = CSTATE_ABORTED;+ commandFailed(st, "shell",+ "execution of meta-command failed",+ false);+ st->failure_status = META_COMMAND_FAILURE;+ st->state = CSTATE_FAILURE;
break;
}
else
@@ -3393,36 +3846,54 @@ doCustom(TState *thread, CState *st, StatsData *agg)
* Wait for the current SQL command to complete
*/
case CSTATE_WAIT_RESULT:
- command = sql_script[st->use_file].commands[st->command];- pgbench_error(DEBUG, "client %d receiving\n", st->id);- if (!PQconsumeInput(st->con))- { /* there's something wrong */- commandFailed(st, "SQL", "perhaps the backend died while processing");- st->state = CSTATE_ABORTED;- break;- }- if (PQisBusy(st->con))- return; /* don't have the whole result yet */-- /*- * Read and discard the query result;- */- res = PQgetResult(st->con);- switch (PQresultStatus(res))
{
- case PGRES_COMMAND_OK:- case PGRES_TUPLES_OK:- case PGRES_EMPTY_QUERY:- /* OK */- PQclear(res);- discard_response(st);- st->state = CSTATE_END_COMMAND;- break;- default:- commandFailed(st, "SQL", PQerrorMessage(st->con));- PQclear(res);+ char *sqlState;++ command = sql_script[st->use_file].commands[st->command];+ pgbench_error(DEBUG, "client %d receiving\n", st->id);+ if (!PQconsumeInput(st->con))+ { /* there's something wrong */+ commandFailed(st, "SQL",+ "perhaps the backend died while processing",+ true);
st->state = CSTATE_ABORTED;
break;
+ }+ if (PQisBusy(st->con))+ return; /* don't have the whole result yet */++ /*+ * Read and discard the query result;+ */+ res = PQgetResult(st->con);+ sqlState = PQresultErrorField(res, PG_DIAG_SQLSTATE);+ switch (PQresultStatus(res))+ {+ case PGRES_COMMAND_OK:+ case PGRES_TUPLES_OK:+ case PGRES_EMPTY_QUERY:+ /* OK */+ st->failure_status = NO_FAILURE;+ PQclear(res);+ discard_response(st);+ st->state = CSTATE_END_COMMAND;+ break;+ case PGRES_NONFATAL_ERROR:+ case PGRES_FATAL_ERROR:+ st->failure_status = getSQLFailureStatus(sqlState);+ commandFailed(st, "SQL", PQerrorMessage(st->con),+ false);+ PQclear(res);+ discard_response(st);+ st->state = CSTATE_FAILURE;+ break;+ default:+ commandFailed(st, "SQL", PQerrorMessage(st->con),+ true);+ PQclear(res);+ st->state = CSTATE_ABORTED;+ break;+ }
}
break;
@@ -3451,7 +3922,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
* in thread-local data structure, if per-command latencies
* are requested.
*/
- if (is_latencies)+ if (report_per_command)
{
if (INSTR_TIME_IS_ZERO(now))
INSTR_TIME_SET_CURRENT(now);
@@ -3469,6 +3940,169 @@ doCustom(TState *thread, CState *st, StatsData *agg)
CSTATE_START_COMMAND : CSTATE_SKIP_COMMAND;
break;
+ /*+ * Clean up after a failed transaction.+ */+ case CSTATE_FAILURE:+ {+ bool in_tx_block;++ Assert(st->failure_status != NO_FAILURE);++ /*+ * Check if we have a failed transaction block or not, and+ * roll it back if any.+ */+ in_tx_block = inTransactionBlock(st);+ if (st->state == CSTATE_ABORTED)+ break; /* there's something wrong */+ if (in_tx_block)+ {+ PGresult *res;++ res = PQexec(st->con, "ROLLBACK");+ if (PQresultStatus(res) != PGRES_COMMAND_OK)+ {+ /*+ * We are sure that the function PQerrorMessage is+ * always called.+ */+ Assert(LOG >= log_min_messages);++ pgbench_error(LOG,+ "client %d aborted during the termination of the failed transaction block; %s\n",+ st->id, PQerrorMessage(st->con));+ PQclear(res);+ st->state = CSTATE_ABORTED;+ break;+ }+ PQclear(res);+ }++ /* Clear the conditional stack */+ conditional_stack_reset(st->cstack);++ /* Check if we can retry the failure */+ st->state = CSTATE_RETRY;+ }+ break;++ /*+ * Retry the failed transaction if possible.+ */+ case CSTATE_RETRY:+ command = sql_script[st->use_file].commands[st->command];++ if (canRetry(st, &now))+ {+ /*+ * The failed transaction will be retried. So accumulate+ * the retry.+ */+ st->retries++;+ command->retries++;++ /*+ * Inform that the failed transaction will be retried.+ * Allocate memory for the message only if necessary.+ */+ if (DEBUG_FAIL >= log_min_messages)+ {+ PQExpBufferData errmsg_buf;++ initPQExpBuffer(&errmsg_buf);+ printfPQExpBuffer(&errmsg_buf,+ "client %d repeats the failed transaction (try %d",+ st->id, st->retries + 1);+ if (max_tries)+ appendPQExpBuffer(&errmsg_buf, "/%d", max_tries);+ if (latency_limit)+ {+ appendPQExpBuffer(&errmsg_buf,+ ", %.3f%% of the maximum time of tries was used",+ getLatencyUsed(st, &now));+ }+ appendPQExpBufferStr(&errmsg_buf, ")\n");+ pgbench_error(DEBUG_FAIL, "%s", errmsg_buf.data);+ termPQExpBuffer(&errmsg_buf);+ }++ /*+ * Reset the execution parameters as they were at the+ * beginning of the transaction.+ */+ memcpy(&(st->random_state), &(st->retry_state.random_state),+ sizeof(RandomState));+ if (!copyVariables(&st->variables,+ &st->retry_state.variables))+ {+ pgbench_error(LOG,+ "client %d aborted when preparing to retry the failed transaction\n",+ st->id);+ st->state = CSTATE_ABORTED;+ break;+ }++ /* Process the first transaction command */+ st->command = 0;+ st->failure_status = NO_FAILURE;+ st->state = CSTATE_START_COMMAND;+ }+ else+ {+ /*+ * We will not be able to retry this failed transaction.+ * So accumulate the error.+ */+ command->ecnt++;++ /*+ * If this is a serialization or deadlock failure, inform+ * that the failed transaction will not be retried. Allocate+ * memory for the message only if necessary.+ */+ if (DEBUG_FAIL >= log_min_messages &&+ canRetryFailure(st->failure_status))+ {+ PQExpBufferData errmsg_buf;++ initPQExpBuffer(&errmsg_buf);+ printfPQExpBuffer(&errmsg_buf,+ "client %d ends the failed transaction (try %d",+ st->id, st->retries + 1);+ if (max_tries)+ appendPQExpBuffer(&errmsg_buf, "/%d", max_tries);+ if (latency_limit)+ {+ appendPQExpBuffer(&errmsg_buf,+ ", %.3f%% of the maximum time of tries was used",+ getLatencyUsed(st, &now));+ }+ appendPQExpBufferStr(&errmsg_buf, ")\n");+ pgbench_error(DEBUG_FAIL, "%s", errmsg_buf.data);+ termPQExpBuffer(&errmsg_buf);+ }++ /*+ * Reset the execution parameters as they were at the+ * beginning of the transaction except for a random+ * state.+ */+ if (!copyVariables(&st->variables,+ &st->retry_state.variables))+ {+ pgbench_error(LOG,+ "client %d aborted when ending the failed transaction\n",+ st->id);+ st->state = CSTATE_ABORTED;+ break;+ }++ /* End the failed transaction */+ st->state = CSTATE_END_TX;+ }+ break;+
/*
* End of transaction.
*/
@@ -3490,7 +4124,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
INSTR_TIME_SET_ZERO(now);
}
- if ((st->cnt >= nxacts && duration <= 0) || timer_exceeded)+ if ((getTotalCnt(st) >= nxacts && duration <= 0) ||+ timer_exceeded)
{
/* exit success */
st->state = CSTATE_FINISHED;
@@ -3573,6 +4208,20 @@ doLog(TState *thread, CState *st,
agg->latency.sum2,
agg->latency.min,
agg->latency.max);
++ if (errors_detailed)+ {+ fprintf(logfile, " " INT64_FORMAT " " INT64_FORMAT " " INT64_FORMAT " " INT64_FORMAT,+ agg->serialization_errors,+ agg->deadlock_errors,+ agg->other_sql_errors,+ agg->meta_command_errors);+ }+ else+ {+ fprintf(logfile, " " INT64_FORMAT, getEcnt(agg));+ }+
if (throttle_delay)
{
fprintf(logfile, " %.0f %.0f %.0f %.0f",
@@ -3583,6 +4232,10 @@ doLog(TState *thread, CState *st,
if (latency_limit)
fprintf(logfile, " " INT64_FORMAT, agg->skipped);
}
+ if (RETRIES_ENABLED)+ fprintf(logfile, " " INT64_FORMAT " " INT64_FORMAT,+ agg->retried,+ agg->retries);
fputc('\n', logfile);
/* reset data and move to next interval */
@@ -3590,7 +4243,7 @@ doLog(TState *thread, CState *st,
}
/* accumulate the current transaction */
- accumStats(agg, skipped, latency, lag);+ accumStats(agg, skipped, latency, lag, st->failure_status, st->retries);
}
else
{
@@ -3600,14 +4253,46 @@ doLog(TState *thread, CState *st,
gettimeofday(&tv, NULL);
if (skipped)
fprintf(logfile, "%d " INT64_FORMAT " skipped %d %ld %ld",
- st->id, st->cnt, st->use_file,+ st->id, getTotalCnt(st), st->use_file,
(long) tv.tv_sec, (long) tv.tv_usec);
- else+ else if (st->failure_status == NO_FAILURE)
fprintf(logfile, "%d " INT64_FORMAT " %.0f %d %ld %ld",
- st->id, st->cnt, latency, st->use_file,+ st->id, getTotalCnt(st), latency, st->use_file,+ (long) tv.tv_sec, (long) tv.tv_usec);+ else if (errors_detailed)+ {+ if (st->failure_status == SERIALIZATION_FAILURE)+ fprintf(logfile, "%d " INT64_FORMAT " serialization_error %d %ld %ld",+ st->id, getTotalCnt(st), st->use_file,+ (long) tv.tv_sec, (long) tv.tv_usec);+ else if (st->failure_status == DEADLOCK_FAILURE)+ fprintf(logfile, "%d " INT64_FORMAT " deadlock_error %d %ld %ld",+ st->id, getTotalCnt(st), st->use_file,+ (long) tv.tv_sec, (long) tv.tv_usec);+ else if (st->failure_status == ANOTHER_SQL_FAILURE)+ fprintf(logfile, "%d " INT64_FORMAT " another_sql_error %d %ld %ld",+ st->id, getTotalCnt(st), st->use_file,+ (long) tv.tv_sec, (long) tv.tv_usec);+ else if (st->failure_status == META_COMMAND_FAILURE)+ fprintf(logfile, "%d " INT64_FORMAT " meta_command_error %d %ld %ld",+ st->id, getTotalCnt(st), st->use_file,+ (long) tv.tv_sec, (long) tv.tv_usec);+ else+ {+ /* internal error which should never occur */+ pgbench_error(ERROR, "unexpected failure status: %d",+ st->failure_status);+ }+ }+ else+ fprintf(logfile, "%d " INT64_FORMAT " failed %d %ld %ld",+ st->id, getTotalCnt(st), st->use_file,
(long) tv.tv_sec, (long) tv.tv_usec);
+
if (throttle_delay)
fprintf(logfile, " %.0f", lag);
+ if (RETRIES_ENABLED)+ fprintf(logfile, " %d", st->retries);
fputc('\n', logfile);
}
}
@@ -3624,10 +4309,11 @@ processXactStats(TState *thread, CState *st, instr_time *now,
{
double latency = 0.0,
lag = 0.0;
- bool thread_details = progress || throttle_delay || latency_limit,- detailed = thread_details || use_log || per_script_stats;+ bool detailed = progress || throttle_delay || latency_limit ||+ use_log || per_script_stats;- if (detailed && !skipped)+ if (detailed && !skipped &&+ (st->failure_status == NO_FAILURE || latency_limit))
{
if (INSTR_TIME_IS_ZERO(*now))
INSTR_TIME_SET_CURRENT(*now);
@@ -3637,30 +4323,29 @@ processXactStats(TState *thread, CState *st, instr_time *now,
lag = INSTR_TIME_GET_MICROSEC(st->txn_begin) - st->txn_scheduled;
}
- if (thread_details)- {- /* keep detailed thread stats */- accumStats(&thread->stats, skipped, latency, lag);+ /* keep detailed thread stats */+ accumStats(&thread->stats, skipped, latency, lag, st->failure_status,+ st->retries);- /* count transactions over the latency limit, if needed */- if (latency_limit && latency > latency_limit)- thread->latency_late++;- }- else- {- /* no detailed stats, just count */- thread->stats.cnt++;- }+ /* count transactions over the latency limit, if needed */+ if (latency_limit && latency > latency_limit)+ thread->latency_late++;
/* client stat is just counting */
- st->cnt++;+ if (st->failure_status == NO_FAILURE)+ st->cnt++;+ else+ st->ecnt++;
if (use_log)
doLog(thread, st, agg, skipped, latency, lag);
/* XXX could use a mutex here, but we choose not to */
if (per_script_stats)
- accumStats(&sql_script[st->use_file].stats, skipped, latency, lag);+ {+ accumStats(&sql_script[st->use_file].stats, skipped, latency, lag,+ st->failure_status, st->retries);+ }
}
@@ -4821,7 +5506,9 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
double time_include,
tps_include,
tps_exclude;
- int64 ntx = total->cnt - total->skipped;+ int64 ecnt = getEcnt(total);+ int64 ntx = total->cnt - total->skipped,+ total_ntx = total->cnt + ecnt;
int i,
totalCacheOverflows = 0;
@@ -4842,8 +5529,8 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
if (duration <= 0)
{
printf("number of transactions per client: %d\n", nxacts);
- printf("number of transactions actually processed: " INT64_FORMAT "/%d\n",- ntx, nxacts * nclients);+ printf("number of transactions actually processed: " INT64_FORMAT "/" INT64_FORMAT "\n",+ ntx, total_ntx);
}
else
{
@@ -4851,6 +5538,67 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
printf("number of transactions actually processed: " INT64_FORMAT "\n",
ntx);
}
++ if (ecnt > 0)+ {+ printf("number of errors: " INT64_FORMAT " (%.3f%%)\n",+ ecnt, 100.0 * ecnt / total_ntx);++ if (errors_detailed)+ {+ /* SQL errors */+ if (total->serialization_errors || total->other_sql_errors)+ {+ printf("number of serialization errors: " INT64_FORMAT " (%.3f%%)\n",+ total->serialization_errors,+ 100.0 * total->serialization_errors / total_ntx);+ }+ if (total->deadlock_errors || total->other_sql_errors)+ {+ printf("number of deadlock errors: " INT64_FORMAT " (%.3f%%)\n",+ total->deadlock_errors,+ 100.0 * total->deadlock_errors / total_ntx);+ }+ if (total->other_sql_errors)+ {+ printf("number of other SQL errors: " INT64_FORMAT " (%.3f%%)\n",+ total->other_sql_errors,+ 100.0 * total->other_sql_errors / total_ntx);+ }++ /* errors in meta commands */+ if (total->meta_command_errors > 0)+ {+ printf("number of errors in meta-commands: " INT64_FORMAT " (%.3f%%)\n",+ total->meta_command_errors,+ 100.0 * total->meta_command_errors / total_ntx);+ }+ }+ }++ /*+ * It can be non-zero only if max_tries is greater than one or+ * latency_limit is used.+ */+ if (total->retried > 0)+ {+ printf("number of retried: " INT64_FORMAT " (%.3f%%)\n",+ total->retried, 100.0 * total->retried / total_ntx);+ printf("number of retries: " INT64_FORMAT "\n", total->retries);+ }++ if (max_tries)+ printf("maximum number of tries: %d\n", max_tries);++ if (latency_limit)+ {+ /* this statistics includes both successful and failed transactions */+ printf("number of transactions above the %.1f ms latency limit: " INT64_FORMAT "/" INT64_FORMAT " (%.3f %%)%s\n",+ latency_limit / 1000.0, latency_late, total_ntx,+ (total_ntx > 0) ? 100.0 * latency_late / total_ntx : 0.0,+ ecnt > 0 ? " (including errors)" : "");+ }+
/* Report zipfian cache overflow */
for (i = 0; i < nthreads; i++)
{
@@ -4870,18 +5618,14 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
total->skipped,
100.0 * total->skipped / total->cnt);
- if (latency_limit)- printf("number of transactions above the %.1f ms latency limit: " INT64_FORMAT "/" INT64_FORMAT " (%.3f %%)\n",- latency_limit / 1000.0, latency_late, ntx,- (ntx > 0) ? 100.0 * latency_late / ntx : 0.0);-
if (throttle_delay || progress || latency_limit)
printSimpleStats("latency", &total->latency);
else
{
/* no measurement, show average latency computed from run time */
- printf("latency average = %.3f ms\n",- 1000.0 * time_include * nclients / total->cnt);+ printf("latency average = %.3f ms%s\n",+ 1000.0 * time_include * nclients / total_ntx,+ ecnt > 0 ? " (including errors)" : "");
}
if (throttle_delay)
@@ -4900,7 +5644,7 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
printf("tps = %f (excluding connections establishing)\n", tps_exclude);
/* Report per-script/command statistics */
- if (per_script_stats || is_latencies)+ if (per_script_stats || report_per_command)
{
int i;
@@ -4909,6 +5653,8 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
if (per_script_stats)
{
StatsData *sstats = &sql_script[i].stats;
+ int64 script_ecnt = getEcnt(sstats);+ int64 script_total_ntx = sstats->cnt + script_ecnt;
printf("SQL script %d: %s\n"
" - weight: %d (targets %.1f%% of total)\n"
@@ -4920,6 +5666,62 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
100.0 * sstats->cnt / total->cnt,
(sstats->cnt - sstats->skipped) / time_include);
+ if (ecnt > 0)+ {+ printf(" - number of errors: " INT64_FORMAT " (%.3f%%)\n",+ script_ecnt, 100.0 * script_ecnt / script_total_ntx);++ if (errors_detailed)+ {+ /* SQL errors */+ if (total->serialization_errors ||+ total->other_sql_errors)+ {+ printf(" - number of serialization errors: " INT64_FORMAT " (%.3f%%)\n",+ sstats->serialization_errors,+ (100.0 * sstats->serialization_errors /+ script_total_ntx));+ }+ if (total->deadlock_errors ||+ total->other_sql_errors)+ {+ printf(" - number of deadlock errors: " INT64_FORMAT " (%.3f%%)\n",+ sstats->deadlock_errors,+ (100.0 * sstats->deadlock_errors /+ script_total_ntx));+ }+ if (total->other_sql_errors)+ {+ printf(" - number of other SQL errors: " INT64_FORMAT " (%.3f%%)\n",+ sstats->other_sql_errors,+ (100.0 * sstats->other_sql_errors /+ script_total_ntx));+ }++ /* errors in meta commands */+ if (total->meta_command_errors > 0)+ {+ printf(" - number of errors in meta-commands: " INT64_FORMAT " (%.3f%%)\n",+ sstats->meta_command_errors,+ (100.0 * sstats->meta_command_errors /+ script_total_ntx));+ }+ }+ }++ /*+ * It can be non-zero only if max_tries is greater than one or+ * latency_limit is used.+ */+ if (total->retried > 0)+ {+ printf(" - number of retried: " INT64_FORMAT " (%.3f%%)\n",+ sstats->retried,+ 100.0 * sstats->retried / script_total_ntx);+ printf(" - number of retries: " INT64_FORMAT "\n",+ sstats->retries);+ }+
if (throttle_delay && latency_limit && sstats->cnt > 0)
printf(" - number of transactions skipped: " INT64_FORMAT " (%.3f%%)\n",
sstats->skipped,
@@ -4928,15 +5730,16 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
printSimpleStats(" - latency", &sstats->latency);
}
- /* Report per-command latencies */- if (is_latencies)+ /* Report per-command latencies and errors */+ if (report_per_command)
{
Command **commands;
- if (per_script_stats)- printf(" - statement latencies in milliseconds:\n");- else- printf("statement latencies in milliseconds:\n");+ printf("%sstatement latencies in milliseconds%s:\n",+ per_script_stats ? " - " : "",+ (RETRIES_ENABLED ?+ ", errors and retries" :+ " and errors"));
for (commands = sql_script[i].commands;
*commands != NULL;
@@ -4944,10 +5747,23 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
{
SimpleStats *cstats = &(*commands)->stats;
- printf(" %11.3f %s\n",- (cstats->count > 0) ?- 1000.0 * cstats->sum / cstats->count : 0.0,- (*commands)->line);+ if (RETRIES_ENABLED)+ {+ printf(" %11.3f %10" INT64_MODIFIER "d %10" INT64_MODIFIER "d %s\n",+ (cstats->count > 0) ?+ 1000.0 * cstats->sum / cstats->count : 0.0,+ (*commands)->ecnt,+ (*commands)->retries,+ (*commands)->line);+ }+ else+ {+ printf(" %11.3f %10" INT64_MODIFIER "d %s\n",+ (cstats->count > 0) ?+ 1000.0 * cstats->sum / cstats->count : 0.0,+ (*commands)->ecnt,+ (*commands)->line);+ }
}
}
}
@@ -5038,7 +5854,7 @@ main(int argc, char **argv)
{"progress", required_argument, NULL, 'P'},
{"protocol", required_argument, NULL, 'M'},
{"quiet", no_argument, NULL, 'q'},
- {"report-latencies", no_argument, NULL, 'r'},+ {"report-per-command", no_argument, NULL, 'r'},
{"rate", required_argument, NULL, 'R'},
{"scale", required_argument, NULL, 's'},
{"select-only", no_argument, NULL, 'S'},
@@ -5057,6 +5873,9 @@ main(int argc, char **argv)
{"log-prefix", required_argument, NULL, 7},
{"foreign-keys", no_argument, NULL, 8},
{"random-seed", required_argument, NULL, 9},
+ {"debug-fails", no_argument, NULL, 10},+ {"errors-detailed", no_argument, NULL, 11},+ {"max-tries", required_argument, NULL, 12},
{NULL, 0, NULL, 0}
};
@@ -5218,7 +6037,7 @@ main(int argc, char **argv)
break;
case 'r':
benchmarking_option_set = true;
- is_latencies = true;+ report_per_command = true;
break;
case 's':
scale_given = true;
@@ -5409,6 +6228,28 @@ main(int argc, char **argv)
"error while setting random seed from --random-seed option\n");
}
break;
+ case 10: /* debug-fails */+ /* do not conflict with the option --debug */+ if (log_min_messages > DEBUG_FAIL)+ log_min_messages = DEBUG_FAIL;+ break;+ case 11: /* errors-detailed */+ errors_detailed = true;+ break;+ case 12: /* max-tries */+ {+ int32 max_tries_arg = atoi(optarg);++ if (max_tries_arg <= 0)+ {+ pgbench_error(ERROR,+ "invalid number of maximum tries: \"%s\"\n",+ optarg);+ }+ benchmarking_option_set = true;+ max_tries = (uint32) max_tries_arg;+ }+ break;
default:
pgbench_error(ERROR,
_("Try \"%s --help\" for more information.\n"),
@@ -5578,6 +6419,10 @@ main(int argc, char **argv)
"--progress-timestamp is allowed only under --progress\n");
}
+ /* If necessary set the default tries limit */+ if (!max_tries && !latency_limit)+ max_tries = 1;+
/*
* save main process id in the global variable because process id will be
* changed after fork.
@@ -5861,6 +6706,12 @@ main(int argc, char **argv)
mergeSimpleStats(&stats.lag, &thread->stats.lag);
stats.cnt += thread->stats.cnt;
stats.skipped += thread->stats.skipped;
+ stats.retries += thread->stats.retries;+ stats.retried += thread->stats.retried;+ stats.serialization_errors += thread->stats.serialization_errors;+ stats.deadlock_errors += thread->stats.deadlock_errors;+ stats.other_sql_errors += thread->stats.other_sql_errors;+ stats.meta_command_errors += thread->stats.meta_command_errors;
latency_late += thread->latency_late;
INSTR_TIME_ADD(conn_total_time, thread->conn_time);
}
@@ -6164,7 +7015,10 @@ threadRun(void *arg)
/* generate and show report */
StatsData cur;
int64 run = now - last_report,
- ntx;+ ntx,+ retries,+ retried,+ ecnt;
double tps,
total_run,
latency,
@@ -6192,6 +7046,14 @@ threadRun(void *arg)
mergeSimpleStats(&cur.lag, &thread[i].stats.lag);
cur.cnt += thread[i].stats.cnt;
cur.skipped += thread[i].stats.skipped;
+ cur.retries += thread[i].stats.retries;+ cur.retried += thread[i].stats.retried;+ cur.serialization_errors +=+ thread[i].stats.serialization_errors;+ cur.deadlock_errors += thread[i].stats.deadlock_errors;+ cur.other_sql_errors += thread[i].stats.other_sql_errors;+ cur.meta_command_errors +=+ thread[i].stats.meta_command_errors;
}
/* we count only actually executed transactions */
@@ -6209,6 +7071,9 @@ threadRun(void *arg)
{
latency = sqlat = stdev = lag = 0;
}
+ retries = cur.retries - last.retries;+ retried = cur.retried - last.retried;+ ecnt = getEcnt(&cur) - getEcnt(&last);
if (progress_timestamp)
{
@@ -6241,6 +7106,12 @@ threadRun(void *arg)
"progress: %s, %.1f tps, lat %.3f ms stddev %.3f",
tbuf, tps, latency, stdev);
+ if (ecnt > 0)+ {+ appendPQExpBuffer(&progress_buf,+ ", " INT64_FORMAT " failed", ecnt);+ }+
if (throttle_delay)
{
appendPQExpBuffer(&progress_buf, ", lag %.3f ms", lag);
@@ -6249,6 +7120,17 @@ threadRun(void *arg)
", " INT64_FORMAT " skipped",
cur.skipped - last.skipped);
}
++ /*+ * It can be non-zero only if max_tries is greater than one or+ * latency_limit is used.+ */+ if (retried > 0)+ {+ appendPQExpBuffer(&progress_buf,+ ", " INT64_FORMAT " retried, " INT64_FORMAT " retries",+ retried, retries);+ }
appendPQExpBufferChar(&progress_buf, '\n');
pgbench_error(LOG, "%s", progress_buf.data);
diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.plindex 2fc021d..2114329 100644--- a/src/bin/pgbench/t/001_pgbench_with_server.pl+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl@@ -5,9 +5,20 @@ use PostgresNode;
use TestLib;
use Test::More;
+use constant+{+ SQL_ERROR => 0,+ META_COMMAND_ERROR => 1,+ SYNTAX_ERROR => 2,+};+
# start a pgbench specific server
my $node = get_new_node('main');
-$node->init;++# Set to untranslated messages, to be able to compare program output with+# expected strings.+$node->init(extra => [ '--locale', 'C' ]);+
$node->start;
# invoke pgbench
@@ -136,7 +147,8 @@ pgbench(
qr{builtin: TPC-B},
qr{clients: 2\b},
qr{processed: 10/10},
- qr{mode: simple}+ qr{mode: simple},+ qr{maximum number of tries: 1}
],
[qr{^$}],
'pgbench tpcb-like');
@@ -530,11 +542,12 @@ pgbench(
# trigger many expression errors
my @errors = (
- # [ test name, expected status, expected stderr, script ]+ # [ test name, expected status, error type, expected stderr, script ]
# SQL
[
'sql syntax error',
0,
+ SQL_ERROR,
[
qr{ERROR: syntax error},
qr{prepared statement .* does not exist}
@@ -544,28 +557,36 @@ my @errors = (
}
],
[
- 'sql too many args', 1, [qr{statement has too many arguments.*\b9\b}],+ 'sql too many args', 1, SYNTAX_ERROR,+ [qr{statement has too many arguments.*\b9\b}],
q{-- MAX_ARGS=10 for prepared
\set i 0
SELECT LEAST(:i, :i, :i, :i, :i, :i, :i, :i, :i, :i, :i);
}
],
+ [ 'sql division by zero', 0, SQL_ERROR, [qr{ERROR: division by zero}],+ q{-- SQL division by zero+SELECT 1 / 0;+}+ ],
# SHELL
[
- 'shell bad command', 0,+ 'shell bad command', 0, META_COMMAND_ERROR,
[qr{\(shell\) .* meta-command failed}], q{\shell no-such-command}
],
[
- 'shell undefined variable', 0,+ 'shell undefined variable', 0, META_COMMAND_ERROR,
[qr{undefined variable ":nosuchvariable"}],
q{-- undefined variable in shell
\shell echo ::foo :nosuchvariable
}
],
- [ 'shell missing command', 1, [qr{missing command }], q{\shell} ],+ [ 'shell missing command', 1, SYNTAX_ERROR, [qr{missing command }],+ q{\shell} ],
[
- 'shell too many args', 1, [qr{too many arguments in command "shell"}],+ 'shell too many args', 1, SYNTAX_ERROR,+ [qr{too many arguments in command "shell"}],
q{-- 257 arguments to \shell
\shell echo \
0 1 2 3 4 5 6 7 8 9 A B C D E F \
@@ -589,162 +610,232 @@ SELECT LEAST(:i, :i, :i, :i, :i, :i, :i, :i, :i, :i, :i);
# SET
[
- 'set syntax error', 1,+ 'set syntax error', 1, SYNTAX_ERROR,
[qr{syntax error in command "set"}], q{\set i 1 +}
],
[
- 'set no such function', 1,+ 'set no such function', 1, SYNTAX_ERROR,
[qr{unexpected function name}], q{\set i noSuchFunction()}
],
[
- 'set invalid variable name', 0,+ 'set invalid variable name', 0, META_COMMAND_ERROR,
[qr{invalid variable name}], q{\set . 1}
],
[
- 'set int overflow', 0,+ 'set int overflow', 0, META_COMMAND_ERROR,
[qr{double to int overflow for 100}], q{\set i int(1E32)}
],
- [ 'set division by zero', 0, [qr{division by zero}], q{\set i 1/0} ],
[
- 'set bigint out of range', 0,+ 'set division by zero', 0, META_COMMAND_ERROR,+ [qr{division by zero}], q{\set i 1/0}+ ],+ [+ 'set bigint out of range', 0, META_COMMAND_ERROR,
[qr{bigint out of range}], q{\set i 9223372036854775808 / -1}
],
[
'set undefined variable',
0,
+ META_COMMAND_ERROR,
[qr{undefined variable "nosuchvariable"}],
q{\set i :nosuchvariable}
],
- [ 'set unexpected char', 1, [qr{unexpected character .;.}], q{\set i ;} ],+ [+ 'set unexpected char', 1, SYNTAX_ERROR,+ [qr{unexpected character .;.}], q{\set i ;}+ ],
[
'set too many args',
0,
+ META_COMMAND_ERROR,
[qr{too many function arguments}],
q{\set i least(0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16)}
],
[
- 'set empty random range', 0,+ 'set empty random range', 0, META_COMMAND_ERROR,
[qr{empty range given to random}], q{\set i random(5,3)}
],
[
'set random range too large',
0,
+ META_COMMAND_ERROR,
[qr{random range is too large}],
q{\set i random(-9223372036854775808, 9223372036854775807)}
],
[
'set gaussian param too small',
0,
+ META_COMMAND_ERROR,
[qr{gaussian param.* at least 2}],
q{\set i random_gaussian(0, 10, 1.0)}
],
[
'set exponential param greater 0',
0,
+ META_COMMAND_ERROR,
[qr{exponential parameter must be greater }],
q{\set i random_exponential(0, 10, 0.0)}
],
[
'set zipfian param to 1',
0,
+ META_COMMAND_ERROR,
[qr{zipfian parameter must be in range \(0, 1\) U \(1, \d+\]}],
q{\set i random_zipfian(0, 10, 1)}
],
[
'set zipfian param too large',
0,
+ META_COMMAND_ERROR,
[qr{zipfian parameter must be in range \(0, 1\) U \(1, \d+\]}],
q{\set i random_zipfian(0, 10, 1000000)}
],
[
- 'set non numeric value', 0,+ 'set non numeric value', 0, META_COMMAND_ERROR,
[qr{malformed variable "foo" value: "bla"}], q{\set i :foo + 1}
],
- [ 'set no expression', 1, [qr{syntax error}], q{\set i} ],- [ 'set missing argument', 1, [qr{missing argument}i], q{\set} ],+ [ 'set no expression', 1, SYNTAX_ERROR, [qr{syntax error}], q{\set i} ],
[
- 'set not a bool', 0,+ 'set missing argument', 1, SYNTAX_ERROR,+ [qr{missing argument}i], q{\set}+ ],+ [+ 'set not a bool', 0, META_COMMAND_ERROR,
[qr{cannot coerce double to boolean}], q{\set b NOT 0.0}
],
[
- 'set not an int', 0,+ 'set not an int', 0, META_COMMAND_ERROR,
[qr{cannot coerce boolean to int}], q{\set i TRUE + 2}
],
[
- 'set not a double', 0,+ 'set not a double', 0, META_COMMAND_ERROR,
[qr{cannot coerce boolean to double}], q{\set d ln(TRUE)}
],
[
'set case error',
1,
+ SYNTAX_ERROR,
[qr{syntax error in command "set"}],
q{\set i CASE TRUE THEN 1 ELSE 0 END}
],
[
- 'set random error', 0,+ 'set random error', 0, META_COMMAND_ERROR,
[qr{cannot coerce boolean to int}], q{\set b random(FALSE, TRUE)}
],
[
- 'set number of args mismatch', 1,+ 'set number of args mismatch', 1, SYNTAX_ERROR,
[qr{unexpected number of arguments}], q{\set d ln(1.0, 2.0))}
],
[
- 'set at least one arg', 1,+ 'set at least one arg', 1, SYNTAX_ERROR,
[qr{at least one argument expected}], q{\set i greatest())}
],
# SETSHELL
[
- 'setshell not an int', 0,+ 'setshell not an int', 0, META_COMMAND_ERROR,
[qr{command must return an integer}], q{\setshell i echo -n one}
],
- [ 'setshell missing arg', 1, [qr{missing argument }], q{\setshell var} ],
[
- 'setshell no such command', 0,+ 'setshell missing arg', 1, SYNTAX_ERROR,+ [qr{missing argument }], q{\setshell var}+ ],+ [+ 'setshell no such command', 0, META_COMMAND_ERROR,
[qr{could not read result }], q{\setshell var no-such-command}
],
# SLEEP
[
- 'sleep undefined variable', 0,+ 'sleep undefined variable', 0, META_COMMAND_ERROR,
[qr{sleep: undefined variable}], q{\sleep :nosuchvariable}
],
[
- 'sleep too many args', 1,+ 'sleep too many args', 1, SYNTAX_ERROR,
[qr{too many arguments}], q{\sleep too many args}
],
[
- 'sleep missing arg', 1,+ 'sleep missing arg', 1, SYNTAX_ERROR,
[ qr{missing argument}, qr{\\sleep} ], q{\sleep}
],
[
- 'sleep unknown unit', 1,+ 'sleep unknown unit', 1, SYNTAX_ERROR,
[qr{unrecognized time unit}], q{\sleep 1 week}
],
+ # CONDITIONAL BLOCKS+ [ 'error inside a conditional block', 0, SQL_ERROR,+ [qr{ERROR: division by zero}],+ q{-- error inside a conditional block+\if true+SELECT 1 / 0;+\endif+}+ ],+
# MISC
[
- 'misc invalid backslash command', 1,+ 'misc invalid backslash command', 1, SYNTAX_ERROR,
[qr{invalid command .* "nosuchcommand"}], q{\nosuchcommand}
],
- [ 'misc empty script', 1, [qr{empty command list for script}], q{} ],
[
- 'bad boolean', 0,+ 'misc empty script', 1, SYNTAX_ERROR,+ [qr{empty command list for script}], q{}+ ],+ [+ 'bad boolean', 0, META_COMMAND_ERROR,
[qr{malformed variable.*trueXXX}], q{\set b :badtrue or true}
],);
for my $e (@errors)
{
- my ($name, $status, $re, $script) = @$e;+ my ($name, $status, $error_type, $re, $script) = @$e;
my $n = '001_pgbench_error_' . $name;
$n =~ s/ /_/g;
+ my $test_name = 'pgbench script error: ' . $name;+ my $stdout_re;++ if ($status)+ {+ # only syntax errors get non-zero exit status+ # internal error which should never occur+ die $test_name . ": unexpected error type: " . $error_type . "\n"+ if ($error_type != SYNTAX_ERROR);++ $stdout_re = [ qr{^$} ];+ }+ else+ {+ $stdout_re =+ [ qr{processed: 0/1}, qr{number of errors: 1 \(100.000%\)},+ qr{^((?!number of retried)(.|\n))*$} ];++ if ($error_type == SQL_ERROR)+ {+ push @$stdout_re,+ qr{number of serialization errors: 0 \(0.000%\)},+ qr{number of deadlock errors: 0 \(0.000%\)},+ qr{number of other SQL errors: 1 \(100.000%\)};+ }+ elsif ($error_type == META_COMMAND_ERROR)+ {+ push @$stdout_re,+ qr{number of errors in meta-commands: 1 \(100.000%\)};+ }+ else+ {+ # internal error which should never occur+ die $test_name . ": unexpected error type: " . $error_type . "\n";+ }+ }+
pgbench(
- '-n -t 1 -Dfoo=bla -Dnull=null -Dtrue=true -Done=1 -Dzero=0.0 -Dbadtrue=trueXXX -M prepared',+ '-n -t 1 -Dfoo=bla -Dnull=null -Dtrue=true -Done=1 -Dzero=0.0 -Dbadtrue=trueXXX -M prepared --debug-fails --errors-detailed',
$status,
- [ $status ? qr{^$} : qr{processed: 0/1} ],+ $stdout_re,
$re,
- 'pgbench script error: ' . $name,+ $test_name,
{ $n => $script });
}
@@ -848,6 +939,209 @@ pgbench(
check_pgbench_logs("$bdir/001_pgbench_log_3", 1, 10, 10,
qr{^\d \d{1,2} \d+ \d \d+ \d+$});
+# Test the concurrent update in the table row and deadlocks.++$node->safe_psql('postgres',+ 'CREATE UNLOGGED TABLE first_client_table (value integer); '+ . 'CREATE UNLOGGED TABLE xy (x integer, y integer); '+ . 'INSERT INTO xy VALUES (1, 2);');++# Serialization failure and retry++local $ENV{PGOPTIONS} = "-c default_transaction_isolation=repeatable\\ read";++# Check that we have a serialization failure and the same random value of the+# delta variable in the next try+my $err_pattern =+ "(client (0|1) sending UPDATE xy SET y = y \\+ -?\\d+\\b).*"+ . "client \\g2 got a failure in command 3 \\(SQL\\) of script 0; "+ . "ERROR: could not serialize access due to concurrent update\\b.*"+ . "\\g1";++pgbench(+ "-n -c 2 -t 1 -d --max-tries 2",+ 0,+ [ qr{processed: 2/2\b}, qr{^((?!number of errors)(.|\n))*$},+ qr{number of retried: 1\b}, qr{number of retries: 1\b} ],+ [ qr/$err_pattern/s ],+ 'concurrent update with retrying',+ {+ '001_pgbench_serialization' => q{+-- What's happening:+-- The first client starts the transaction with the isolation level Repeatable+-- Read:+--+-- BEGIN;+-- UPDATE xy SET y = ... WHERE x = 1;+--+-- The second client starts a similar transaction with the same isolation level:+--+-- BEGIN;+-- UPDATE xy SET y = ... WHERE x = 1;+-- <waiting for the first client>+--+-- The first client commits its transaction, and the second client gets a+-- serialization failure.++\set delta random(-5000, 5000)++-- The second client will stop here+SELECT pg_advisory_lock(0);++-- Start transaction with concurrent update+BEGIN;+UPDATE xy SET y = y + :delta WHERE x = 1 AND pg_advisory_lock(1) IS NOT NULL;++-- Wait for the second client+DO $$+DECLARE+ exists boolean;+ waiters integer;+BEGIN+ -- The second client always comes in second, and the number of rows in the+ -- table first_client_table reflect this. Here the first client inserts a row,+ -- so the second client will see a non-empty table in the second try to run a+ -- previously failed transaction.+ SELECT EXISTS (SELECT * FROM first_client_table) INTO STRICT exists;+ IF NOT exists THEN+ -- Let the second client begin+ PERFORM pg_advisory_unlock(0);+ -- And wait until the second client tries to get the same lock+ LOOP+ SELECT COUNT(*) INTO STRICT waiters FROM pg_locks WHERE+ locktype = 'advisory' AND objsubid = 1 AND+ ((classid::bigint << 32) | objid::bigint = 1::bigint) AND NOT granted;+ IF waiters = 1 THEN+ INSERT INTO first_client_table VALUES (1);++ -- Exit loop+ EXIT;+ END IF;+ END LOOP;+ END IF;+END$$;++COMMIT;+SELECT pg_advisory_unlock_all();+}+ });++# Clean up++$node->safe_psql('postgres', 'DELETE FROM first_client_table;');++local $ENV{PGOPTIONS} = "-c default_transaction_isolation=read\\ committed";++# Deadlock failure and retry++# Check that we have a deadlock failure+$err_pattern =+ "client (0|1) got a failure in command (3|5) \\(SQL\\) of script 0; "+ . "ERROR: deadlock detected\\b";++pgbench(+ "-n -c 2 -t 1 --debug-fails --max-tries 2",+ 0,+ [ qr{processed: 2/2\b}, qr{^((?!number of errors)(.|\n))*$},+ qr{number of retried: 1\b}, qr{number of retries: 1\b} ],+ [ qr{$err_pattern} ],+ 'deadlock with retrying',+ {+ '001_pgbench_deadlock' => q{+-- What's happening:+-- The first client gets the lock 2.+-- The second client gets the lock 3 and tries to get the lock 2.+-- The first client tries to get the lock 3 and one of them gets a deadlock+-- falure.+--+-- A client who has received a deadlock failure is called a (future) failed+-- client although it will retry the failed transaction.+--+-- Also any successfull client must hold a lock at the transaction start so the+-- failed client will wait until the successfull one releases all of its locks+-- at the transaction end (we do not want any failures again).++-- Since the client in the failed transaction has not released the blocking+-- locks, let's do this here.+SELECT pg_advisory_unlock_all();++-- The second and future failed clients will stop here+SELECT pg_advisory_lock(0);+SELECT pg_advisory_lock(1);++-- The second and future failed clients always come after the first and the+-- number of rows in the table first_client_table reflect this. Here the first+-- client inserts a row, so the second and future failed clients will see a+-- non-empty table.+DO $$+DECLARE+ exists boolean;+BEGIN+ SELECT EXISTS (SELECT * FROM first_client_table) INTO STRICT exists;+ IF exists THEN+ -- We are the second or the failed client++ -- The first client will take care by itself of this lock (see below)+ PERFORM pg_advisory_unlock(0);++ PERFORM pg_advisory_lock(3);++ -- The second client can get a deadlock here+ PERFORM pg_advisory_lock(2);+ ELSE+ -- We are the first client++ -- This code should not be used in a new transaction after a failure+ INSERT INTO first_client_table VALUES (1);++ PERFORM pg_advisory_lock(2);+ END IF;+END$$;++DO $$+DECLARE+ num_rows integer;+ waiters integer;+BEGIN+ -- Check if we are the first client+ SELECT COUNT(*) FROM first_client_table INTO STRICT num_rows;+ IF num_rows = 1 THEN+ -- This code should not be used in a new transaction after a failure+ INSERT INTO first_client_table VALUES (2);++ -- Let the second client begin+ PERFORM pg_advisory_unlock(0);+ PERFORM pg_advisory_unlock(1);++ -- Make sure the second client is ready for deadlock+ LOOP+ SELECT COUNT(*) INTO STRICT waiters FROM pg_locks WHERE+ locktype = 'advisory' AND+ objsubid = 1 AND+ ((classid::bigint << 32) | objid::bigint = 2::bigint) AND+ NOT granted;++ IF waiters = 1 THEN+ -- Exit loop+ EXIT;+ END IF;+ END LOOP;++ PERFORM pg_advisory_lock(0);+ -- And the second client took care by itself of the lock 1+ END IF;+END$$;++-- The first client can get a deadlock here+SELECT pg_advisory_lock(3);++SELECT pg_advisory_unlock_all();+}+ });++# Clean up+$node->safe_psql('postgres', 'DELETE FROM first_client_table;');+
# done
$node->stop;
done_testing();
diff --git a/src/bin/pgbench/t/002_pgbench_no_server.pl b/src/bin/pgbench/t/002_pgbench_no_server.plindex c1c2c1e..50626c2 100644--- a/src/bin/pgbench/t/002_pgbench_no_server.pl+++ b/src/bin/pgbench/t/002_pgbench_no_server.pl@@ -157,6 +157,11 @@ my @options = (
qr{error while setting random seed from --random-seed option}
]
],
+ [+ 'bad maximum number of tries',+ '--max-tries -10',+ [ qr{invalid number of maximum tries: "-10"} ]+ ],
# loging sub-options
[
diff --git a/src/fe_utils/conditional.c b/src/fe_utils/conditional.cindex db2a0a5..4d14066 100644--- a/src/fe_utils/conditional.c+++ b/src/fe_utils/conditional.c@@ -24,13 +24,25 @@ conditional_stack_create(void)
}
/*
- * destroy stack+ * Destroy all the elements from the stack. The stack itself is not freed.
*/
void
-conditional_stack_destroy(ConditionalStack cstack)+conditional_stack_reset(ConditionalStack cstack)
{
+ if (!cstack)+ return; /* nothing to do here */+
while (conditional_stack_pop(cstack))
continue;
+}++/*+ * destroy stack+ */+void+conditional_stack_destroy(ConditionalStack cstack)+{+ conditional_stack_reset(cstack);
free(cstack);
}
diff --git a/src/include/fe_utils/conditional.h b/src/include/fe_utils/conditional.hindex 9b91de5..59c8d8a 100644--- a/src/include/fe_utils/conditional.h+++ b/src/include/fe_utils/conditional.h@@ -73,6 +73,8 @@ typedef struct ConditionalStackData *ConditionalStack;
extern ConditionalStack conditional_stack_create(void);
+extern void conditional_stack_reset(ConditionalStack cstack);+
extern void conditional_stack_destroy(ConditionalStack cstack);
extern int conditional_stack_depth(ConditionalStack cstack);
--
2.7.4
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: m.polyakova@postgrespro.ru, coelho@cri.ensmp.fr, alvherre@2ndquadrant.com, i.kurbangaliev@postgrespro.ru, teodor@sigaev.ru
Subject: Re: [HACKERS] WIP Patch: Pgbench Serialization and deadlock errors
In-Reply-To: <25d7b1f518c218a8c335bdfc6c858ea1@postgrespro.ru>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox