pgbench - doCustom cleanup

Started by Fabien COELHOover 7 years ago17 messages
#1Fabien COELHO
coelho@cri.ensmp.fr
1 attachment(s)

Hello pgdev,

This patch rework & clarifies pgbench internal state machine.

It was indirectly triggered by Heikki review of pgbench tap tests
(https://commitfest.postgresql.org/19/1306/), and by Marina's patch about
tx retry on some errors (https://commitfest.postgresql.org/19/1645/) which
I am reviewing.

- it adds more comments to the enum state definitions and to doCustom.

- there is some code cleanup/simplifications:
. a few useless intermediate variables are removed,
. a macro is added to avoid a repeated pattern to set the current time,
. performance data are always collected instead of trying to be clever
and not collect some data in some cases.

- more fundamentally, all state changes are performed within doCustom,
prior that there was one performed by threadRun which made undertanding
the end of run harder. Now threadRun only look at the current state
to make decisions about a client.

- doCustom is made to always return at the end of a script to avoid
an infinite loop on backslash-command only script, instead of hack
with a variable to detect loops, which made it return every two
script runs in such cases.

- there is a small behavioral change:

prior to the patch, a script would always run to its end once started,
with the exception of \sleep commands which could be interrupted by
threadRun.

Marina's patch should enforce somehow one script = one transaction so
that a retry makes sense, so this exception is removed to avoid
aborting a tx implicitely.

--
Fabien.

Attachments:

pgbench-state-change-2.patchtext/plain; name=pgbench-state-change-2.patchDownload
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 41b756c089..369e321196 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -267,14 +267,22 @@ typedef enum
 	 * transaction, and advance to CSTATE_THROTTLE.  CSTATE_THROTTLE state
 	 * sleeps until that moment.  (If throttling is not enabled, doCustom()
 	 * falls directly through from CSTATE_START_THROTTLE to CSTATE_START_TX.)
+	 *
+	 * It may also detect that the next transaction would start beyond the end
+	 * of run, and switch to CSTATE_FINISHED.
 	 */
 	CSTATE_START_THROTTLE,
 	CSTATE_THROTTLE,
 
 	/*
 	 * CSTATE_START_TX performs start-of-transaction processing.  Establishes
-	 * a new connection for the transaction, in --connect mode, and records
-	 * the transaction start time.
+	 * a new connection for the transaction in --connect mode, records
+	 * the transaction start time, and proceed to the first command.
+	 *
+	 * Note: once a script is started, it will either error or run till
+	 * its end, where it may be interrupted. It is not interrupted while
+	 * running, so pgbench --time is to be understood as tx are allowed to
+	 * start in that time, and will finish when their work is completed.
 	 */
 	CSTATE_START_TX,
 
@@ -287,9 +295,6 @@ typedef enum
 	 * and we enter the CSTATE_SLEEP state to wait for it to expire. Other
 	 * meta-commands are executed immediately.
 	 *
-	 * CSTATE_SKIP_COMMAND for conditional branches which are not executed,
-	 * quickly skip commands that do not need any evaluation.
-	 *
 	 * CSTATE_WAIT_RESULT waits until we get a result set back from the server
 	 * for the current command.
 	 *
@@ -297,19 +302,25 @@ typedef enum
 	 *
 	 * CSTATE_END_COMMAND records the end-of-command timestamp, increments the
 	 * command counter, and loops back to CSTATE_START_COMMAND state.
+	 *
+	 * CSTATE_SKIP_COMMAND is used by conditional branches which are not
+	 * executed. It quickly skip commands that do not need any evaluation.
+	 * This state can move forward several commands, till there is something
+	 * to do or the end of the script.
 	 */
 	CSTATE_START_COMMAND,
-	CSTATE_SKIP_COMMAND,
 	CSTATE_WAIT_RESULT,
 	CSTATE_SLEEP,
 	CSTATE_END_COMMAND,
+	CSTATE_SKIP_COMMAND,
 
 	/*
-	 * 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
-	 * in CSTATE_START_THROTTLE state, or enters CSTATE_FINISHED if we have no
-	 * more work to do.
+	 * CSTATE_END_TX performs end-of-transaction processing.  It calculates
+	 * latency, and logs the transaction.  In --connect mode, it closes the
+	 * current connection.
+	 *
+	 * Then either starts over in CSTATE_CHOOSE_SCRIPT, or enters CSTATE_FINISHED
+	 * if we have no more work to do.
 	 */
 	CSTATE_END_TX,
 
@@ -2679,16 +2690,13 @@ evaluateSleep(CState *st, int argc, char **argv, int *usecs)
 
 /*
  * Advance the state machine of a connection, if possible.
+ *
+ * All state changes are performed within this function called
+ * by threadRun.
  */
 static void
 doCustom(TState *thread, CState *st, StatsData *agg)
 {
-	PGresult   *res;
-	Command    *command;
-	instr_time	now;
-	bool		end_tx_processed = false;
-	int64		wait;
-
 	/*
 	 * gettimeofday() isn't free, so we get the current timestamp lazily the
 	 * first time it's needed, and reuse the same value throughout this
@@ -2697,37 +2705,44 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 	 * means "not set yet".  Reset "now" when we execute shell commands or
 	 * expressions, which might take a non-negligible amount of time, though.
 	 */
+	instr_time	now;
 	INSTR_TIME_SET_ZERO(now);
 
 	/*
 	 * Loop in the state machine, until we have to wait for a result from the
-	 * server (or have to sleep, for throttling or for \sleep).
+	 * server or have to sleep for throttling or \sleep.
 	 *
 	 * Note: In the switch-statement below, 'break' will loop back here,
 	 * meaning "continue in the state machine".  Return is used to return to
-	 * the caller.
+	 * the caller, giving the thread opportunity to move forward another client.
 	 */
 	for (;;)
 	{
+		PGresult   *res;
+		Command    *command;
+
 		switch (st->state)
 		{
 				/*
 				 * Select transaction to run.
 				 */
 			case CSTATE_CHOOSE_SCRIPT:
-
 				st->use_file = chooseScript(thread);
 
 				if (debug)
 					fprintf(stderr, "client %d executing script \"%s\"\n", st->id,
 							sql_script[st->use_file].desc);
 
-				if (throttle_delay > 0)
+				/* check stack consistency */
+				Assert(conditional_stack_empty(st->cstack));
+
+				if (timer_exceeded)
+					st->state = CSTATE_FINISHED;
+				else if (throttle_delay > 0)
 					st->state = CSTATE_START_THROTTLE;
 				else
 					st->state = CSTATE_START_TX;
-				/* check consistency */
-				Assert(conditional_stack_empty(st->cstack));
+
 				break;
 
 				/*
@@ -2745,21 +2760,10 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * away.
 				 */
 				Assert(throttle_delay > 0);
-				wait = getPoissonRand(thread, throttle_delay);
 
-				thread->throttle_trigger += wait;
+				thread->throttle_trigger += getPoissonRand(thread, throttle_delay);
 				st->txn_scheduled = thread->throttle_trigger;
 
-				/*
-				 * stop client if next transaction is beyond pgbench end of
-				 * execution
-				 */
-				if (duration > 0 && st->txn_scheduled > end_time)
-				{
-					st->state = CSTATE_FINISHED;
-					break;
-				}
-
 				/*
 				 * If --latency-limit is used, and this slot is already late
 				 * so that the transaction will miss the latency limit even if
@@ -2771,19 +2775,19 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				{
 					int64		now_us;
 
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					now_us = INSTR_TIME_GET_MICROSEC(now);
+
 					while (thread->throttle_trigger < now_us - latency_limit &&
 						   (nxacts <= 0 || st->cnt < nxacts))
 					{
 						processXactStats(thread, st, &now, true, agg);
 						/* next rendez-vous */
-						wait = getPoissonRand(thread, throttle_delay);
-						thread->throttle_trigger += wait;
+						thread->throttle_trigger += getPoissonRand(thread, throttle_delay);
 						st->txn_scheduled = thread->throttle_trigger;
 					}
-					/* stop client if -t exceeded */
+
+					/* stop client if -t was exceeded in the previous skip loop */
 					if (nxacts > 0 && st->cnt >= nxacts)
 					{
 						st->state = CSTATE_FINISHED;
@@ -2791,38 +2795,45 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 				}
 
+				/*
+				 * stop client if next transaction is beyond pgbench end of
+				 * execution.
+				 */
+				if (duration > 0 && st->txn_scheduled > end_time)
+				{
+					st->state = CSTATE_FINISHED;
+					break;
+				}
+
 				st->state = CSTATE_THROTTLE;
-				if (debug)
-					fprintf(stderr, "client %d throttling " INT64_FORMAT " us\n",
-							st->id, wait);
 				break;
 
 				/*
 				 * Wait until it's time to start next transaction.
 				 */
 			case CSTATE_THROTTLE:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
+
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+
 				if (INSTR_TIME_GET_MICROSEC(now) < st->txn_scheduled)
-					return;		/* Still sleeping, nothing to do here */
+					return;		/* still sleeping, nothing to do here */
 
-				/* Else done sleeping, start the transaction */
-				st->state = CSTATE_START_TX;
+				/* done sleeping, but do not start if transaction if we are done */
+				if (timer_exceeded)
+					st->state = CSTATE_FINISHED;
+				else
+					st->state = CSTATE_START_TX;
 				break;
 
 				/* Start new transaction */
 			case CSTATE_START_TX:
 
-				/*
-				 * Establish connection on first call, or if is_connect is
-				 * true.
-				 */
+				/* establish connection if needed, i.e. under --connect */
 				if (st->con == NULL)
 				{
 					instr_time	start;
 
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					start = now;
 					if ((st->con = doConnect()) == NULL)
 					{
@@ -2838,28 +2849,20 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					memset(st->prepared, 0, sizeof(st->prepared));
 				}
 
+				/* record transaction start time.  */
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+				st->txn_begin = now;
+
 				/*
-				 * Record transaction start time under logging, progress or
-				 * throttling.
+				 * When not throttling, this is also the transaction's
+				 * scheduled start time.
 				 */
-				if (use_log || progress || throttle_delay || latency_limit ||
-					per_script_stats)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
-					st->txn_begin = now;
-
-					/*
-					 * When not throttling, this is also the transaction's
-					 * scheduled start time.
-					 */
-					if (!throttle_delay)
-						st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
-				}
+				if (!throttle_delay)
+					st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
 
 				/* Begin with the first command */
-				st->command = 0;
 				st->state = CSTATE_START_COMMAND;
+				st->command = 0;
 				break;
 
 				/*
@@ -2878,17 +2881,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					break;
 				}
 
-				/*
-				 * Record statement start time if per-command latencies are
-				 * requested
-				 */
-				if (is_latencies)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
-					st->stmt_begin = now;
-				}
+				/* record statement start time. */
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+				st->stmt_begin = now;
 
+				/* execute the command */
 				if (command->type == SQL_COMMAND)
 				{
 					if (!sendCommand(st, command))
@@ -2931,8 +2928,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 							break;
 						}
 
-						if (INSTR_TIME_IS_ZERO(now))
-							INSTR_TIME_SET_CURRENT(now);
+						INSTR_TIME_SET_CURRENT_LAZY(now);
+
 						st->sleep_until = INSTR_TIME_GET_MICROSEC(now) + usec;
 						st->state = CSTATE_SLEEP;
 						break;
@@ -2983,10 +2980,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 							}
 							else	/* elif */
 							{
-								/*
-								 * we should get here only if the "elif"
-								 * needed evaluation
-								 */
+								/* we should get here only if the "elif" needed evaluation */
 								Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
 								conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
 							}
@@ -3018,43 +3012,23 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 					else if (command->meta == META_SETSHELL)
 					{
-						bool		ret = runShellCommand(st, argv[1], argv + 2, argc - 2);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
+						if (!runShellCommand(st, argv[1], argv + 2, argc - 2))
 						{
 							commandFailed(st, "setshell", "execution of meta-command failed");
 							st->state = CSTATE_ABORTED;
 							break;
 						}
-						else
-						{
-							/* succeeded */
-						}
+						/* else success */
 					}
 					else if (command->meta == META_SHELL)
 					{
-						bool		ret = runShellCommand(st, NULL, argv + 1, argc - 1);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
+						if (!runShellCommand(st, NULL, argv + 1, argc - 1))
 						{
 							commandFailed(st, "shell", "execution of meta-command failed");
 							st->state = CSTATE_ABORTED;
 							break;
 						}
-						else
-						{
-							/* succeeded */
-						}
+						/* else success */
 					}
 
 			move_to_end_command:
@@ -3156,6 +3130,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 
 					if (st->state != CSTATE_SKIP_COMMAND)
+						/* out of quick skip command loop */
 						break;
 				}
 				break;
@@ -3205,10 +3180,9 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * instead of CSTATE_START_TX.
 				 */
 			case CSTATE_SLEEP:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
 				if (INSTR_TIME_GET_MICROSEC(now) < st->sleep_until)
-					return;		/* Still sleeping, nothing to do here */
+					return;		/* still sleeping, nothing to do here */
 				/* Else done sleeping. */
 				st->state = CSTATE_END_COMMAND;
 				break;
@@ -3223,17 +3197,13 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * in thread-local data structure, if per-command latencies
 				 * are requested.
 				 */
-				if (is_latencies)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
 
-					/* XXX could use a mutex here, but we choose not to */
-					command = sql_script[st->use_file].commands[st->command];
-					addToSimpleStats(&command->stats,
-									 INSTR_TIME_GET_DOUBLE(now) -
-									 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
-				}
+				/* XXX could use a mutex here, but we choose not to */
+				command = sql_script[st->use_file].commands[st->command];
+				addToSimpleStats(&command->stats,
+								 INSTR_TIME_GET_DOUBLE(now) -
+								 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
 
 				/* Go ahead with next command, to be executed or skipped */
 				st->command++;
@@ -3242,19 +3212,15 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				break;
 
 				/*
-				 * End of transaction.
+				 * End of transaction (end of script, really).
 				 */
 			case CSTATE_END_TX:
 
 				/* transaction finished: calculate latency and do log */
 				processXactStats(thread, st, &now, false, 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);
-				}
+				/* missing \endif... cannot happen if CheckConditional was okay */
+				Assert(conditional_stack_empty(st->cstack));
 
 				if (is_connect)
 				{
@@ -3268,26 +3234,17 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					st->state = CSTATE_FINISHED;
 					break;
 				}
+				else
+				{
+					/* next transaction */
+					st->state = CSTATE_CHOOSE_SCRIPT;
 
-				/*
-				 * No transaction is underway anymore.
-				 */
-				st->state = CSTATE_CHOOSE_SCRIPT;
-
-				/*
-				 * If we paced through all commands in the script in this
-				 * loop, without returning to the caller even once, do it now.
-				 * This gives the thread a chance to process other
-				 * connections, and to do progress reporting.  This can
-				 * currently only happen if the script consists entirely of
-				 * meta-commands.
-				 */
-				if (end_tx_processed)
+					/*
+					 * Ensure that we always return on this point, so as
+					 * to avoid an infinite loop if the script only contains
+					 * meta commands.
+					 */
 					return;
-				else
-				{
-					end_tx_processed = true;
-					break;
 				}
 
 				/*
@@ -3401,8 +3358,7 @@ processXactStats(TState *thread, CState *st, instr_time *now,
 
 	if (detailed && !skipped)
 	{
-		if (INSTR_TIME_IS_ZERO(*now))
-			INSTR_TIME_SET_CURRENT(*now);
+		INSTR_TIME_SET_CURRENT_LAZY(*now);
 
 		/* compute latency & lag */
 		latency = INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled;
@@ -5652,7 +5608,7 @@ threadRun(void *arg)
 
 	if (!is_connect)
 	{
-		/* make connections to the database */
+		/* make connections to the database before starting */
 		for (i = 0; i < nstate; i++)
 		{
 			if ((state[i].con = doConnect()) == NULL)
@@ -5686,14 +5642,7 @@ threadRun(void *arg)
 		{
 			CState	   *st = &state[i];
 
-			if (st->state == CSTATE_THROTTLE && timer_exceeded)
-			{
-				/* interrupt client that has not started a transaction */
-				st->state = CSTATE_FINISHED;
-				finishCon(st);
-				remains--;
-			}
-			else if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
+			if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
 			{
 				/* a nap from the script, or under throttling */
 				int64		this_usec;
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f968444671..c46f6825bb 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -20,6 +20,8 @@
  *
  * INSTR_TIME_SET_CURRENT(t)		set t to current time
  *
+ * INSTR_TIME_SET_CURRENT_LAZY(t)	set t to current time if t is zero
+ *
  * INSTR_TIME_ADD(x, y)				x += y
  *
  * INSTR_TIME_SUBTRACT(x, y)		x -= y
@@ -245,4 +247,9 @@ GetTimerFrequency(void)
 
 #endif							/* WIN32 */
 
+/* same macro on all platforms */
+#define INSTR_TIME_SET_CURRENT_LAZY(t) \
+	if (INSTR_TIME_IS_ZERO(t)) \
+		INSTR_TIME_SET_CURRENT(t)
+
 #endif							/* INSTR_TIME_H */
#2Jamison, Kirk
k.jamison@jp.fujitsu.com
In reply to: Fabien COELHO (#1)
RE: pgbench - doCustom cleanup

Hello Fabien,

I have decided to take a look into this patch.
--
patching file src/bin/pgbench/pgbench.c
Hunk #1 succeeded at 296 (offset 29 lines).
[…Snip…]
Hunk #21 succeeded at 5750 (offset 108 lines).
patching file src/include/portability/instr_time.h
….
=======================
All 189 tests passed.
=======================
Build success

It applies cleanly, passes the tests, and builds successfully.

The simplification and refactoring of code also seems logical to me.
That said, the code looks clean and the comments are clear.
Agree that it makes sense to move all the state changes from threadRun() to doCustom() for code consistency.

I noticed in your refactored code that CSTATE_CHOOSE_SCRIPT may now also change to CSTATE_FINISHED when timer is exceeded. (Before, it only changes to either CSTATE_START_THROTTLE or CSTATE_START_TX)
But the change has not been indicated YET in the typedef enum part for CSTATE_CHOOSE_SCRIPT.
[snip]
/*
* The client must first choose a script to execute. Once chosen, it can
* either be throttled (state CSTATE_START_THROTTLE under --rate) or start
* right away (state CSTATE_START_TX).
*/
CSTATE_CHOOSE_SCRIPT,

As for the behavioral change, it is assumed that there will be 1 script per transaction run.
After code reading, I interpreted the "modified" state changes below:

1. CSTATE_CHOOSE_SCRIPT may now switch CSTATE_FINISHED
Previously, it may only switch to CSTATE_THROTTLE or CSTATE_START_TX.

2. CSTATE_START_THROTTLE (Similar to #1) may now switch to CSTATE_FINISHED.
Previously, it may only switch to CSTATE_THROTTLE or CSTATE_START_TX.

3. CSTATE_START_TX: Transactions, once started, cannot be interrupted while running, and now proceeds to first command. Interrupt may only be allowed either after tx error or when tx run ends.

4. CSTATE_SKIP_COMMAND
No particular change in code logic, but clarified in the typedef that this state can move forward several commands until it meets next commands or finishes script.

5. CSTATE_END_TX: either starts over with new script (CSTATE_CHOOSE_SCRIPT) or finishes (CSTATE_FINISHED).
Previously, it either defaults to CSTATE_START_THROTTLE when choosing a new script, or finishes.

Regards,
Kirk Jamison

-----Original Message-----
From: Fabien COELHO [mailto:coelho@cri.ensmp.fr]
Sent: Saturday, August 11, 2018 6:14 PM
To: PostgreSQL Developers <pgsql-hackers@lists.postgresql.org>
Subject: pgbench - doCustom cleanup

Hello pgdev,

This patch rework & clarifies pgbench internal state machine.

It was indirectly triggered by Heikki review of pgbench tap tests (https://commitfest.postgresql.org/19/1306/), and by Marina's patch about tx retry on some errors (https://commitfest.postgresql.org/19/1645/) which I am reviewing.

- it adds more comments to the enum state definitions and to doCustom.

- there is some code cleanup/simplifications:
. a few useless intermediate variables are removed,
. a macro is added to avoid a repeated pattern to set the current time,
. performance data are always collected instead of trying to be clever
and not collect some data in some cases.

- more fundamentally, all state changes are performed within doCustom,
prior that there was one performed by threadRun which made undertanding
the end of run harder. Now threadRun only look at the current state
to make decisions about a client.

- doCustom is made to always return at the end of a script to avoid
an infinite loop on backslash-command only script, instead of hack
with a variable to detect loops, which made it return every two
script runs in such cases.

- there is a small behavioral change:

prior to the patch, a script would always run to its end once started,
with the exception of \sleep commands which could be interrupted by
threadRun.

Marina's patch should enforce somehow one script = one transaction so
that a retry makes sense, so this exception is removed to avoid
aborting a tx implicitely.

--
Fabien.

#3Fabien COELHO
coelho@cri.ensmp.fr
In reply to: Jamison, Kirk (#2)
1 attachment(s)
RE: pgbench - doCustom cleanup

Hello Kirk,

I have decided to take a look into this patch.

Thanks for the feedback.

I noticed in your refactored code that CSTATE_CHOOSE_SCRIPT may now also
change to CSTATE_FINISHED when timer is exceeded. (Before, it only
changes to either CSTATE_START_THROTTLE or CSTATE_START_TX) But the
change has not been indicated YET in the typedef enum part for
CSTATE_CHOOSE_SCRIPT.

Indeed, the comment is inaccurate and need updating.

As for the behavioral change, it is assumed that there will be 1 script
per transaction run. After code reading, I interpreted the "modified"
state changes below:

1. CSTATE_CHOOSE_SCRIPT may now switch CSTATE_FINISHED
Previously, it may only switch to CSTATE_THROTTLE or CSTATE_START_TX.

Yes, I have added a shortcut there.

2. CSTATE_START_THROTTLE (Similar to #1) may now switch to CSTATE_FINISHED.
Previously, it may only switch to CSTATE_THROTTLE or CSTATE_START_TX.

This was somehow already the case before the patch in some cases, but I
moved the decision after the while throttle so that it catches more cases.

3. CSTATE_START_TX: Transactions, once started, cannot be interrupted
while running, and now proceeds to first command. Interrupt may only be
allowed either after tx error or when tx run ends.

Yes, I removed all interruptions.

4. CSTATE_SKIP_COMMAND
No particular change in code logic, but clarified in the typedef that this state can move forward several commands until it meets next commands or finishes script.

Yes.

5. CSTATE_END_TX: either starts over with new script (CSTATE_CHOOSE_SCRIPT) or finishes (CSTATE_FINISHED).
Previously, it either defaults to CSTATE_START_THROTTLE when choosing a new script, or finishes.

Nope, it was already jumping between CHOOSE & FINISHED, however I
simplified the logic there to avoid doCustom to stay in one client
by always returning.

Attached is a v3, where I have updated inaccurate comments.

--
Fabien.

Attachments:

pgbench-state-change-3.patchtext/x-diff; name=pgbench-state-change-3.patchDownload
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 436764b9c9..ac1b08d6d8 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -287,23 +287,31 @@ typedef enum
 	/*
 	 * The client must first choose a script to execute.  Once chosen, it can
 	 * either be throttled (state CSTATE_START_THROTTLE under --rate) or start
-	 * right away (state CSTATE_START_TX).
+	 * right away (state CSTATE_START_TX) or not start at all if the timer was
+	 * exceeded (state CSTATE_FINISHED).
 	 */
 	CSTATE_CHOOSE_SCRIPT,
 
 	/*
 	 * In CSTATE_START_THROTTLE state, we calculate when to begin the next
 	 * transaction, and advance to CSTATE_THROTTLE.  CSTATE_THROTTLE state
-	 * sleeps until that moment.  (If throttling is not enabled, doCustom()
-	 * falls directly through from CSTATE_START_THROTTLE to CSTATE_START_TX.)
+	 * sleeps until that moment.
+	 *
+	 * It may also detect that the next transaction would start beyond the end
+	 * of run, and switch to CSTATE_FINISHED.
 	 */
 	CSTATE_START_THROTTLE,
 	CSTATE_THROTTLE,
 
 	/*
 	 * CSTATE_START_TX performs start-of-transaction processing.  Establishes
-	 * a new connection for the transaction, in --connect mode, and records
-	 * the transaction start time.
+	 * a new connection for the transaction in --connect mode, records
+	 * the transaction start time, and proceed to the first command.
+	 *
+	 * Note: once a script is started, it will either error or run till
+	 * its end, where it may be interrupted. It is not interrupted while
+	 * running, so pgbench --time is to be understood as tx are allowed to
+	 * start in that time, and will finish when their work is completed.
 	 */
 	CSTATE_START_TX,
 
@@ -316,9 +324,6 @@ typedef enum
 	 * and we enter the CSTATE_SLEEP state to wait for it to expire. Other
 	 * meta-commands are executed immediately.
 	 *
-	 * CSTATE_SKIP_COMMAND for conditional branches which are not executed,
-	 * quickly skip commands that do not need any evaluation.
-	 *
 	 * CSTATE_WAIT_RESULT waits until we get a result set back from the server
 	 * for the current command.
 	 *
@@ -326,19 +331,25 @@ typedef enum
 	 *
 	 * CSTATE_END_COMMAND records the end-of-command timestamp, increments the
 	 * command counter, and loops back to CSTATE_START_COMMAND state.
+	 *
+	 * CSTATE_SKIP_COMMAND is used by conditional branches which are not
+	 * executed. It quickly skip commands that do not need any evaluation.
+	 * This state can move forward several commands, till there is something
+	 * to do or the end of the script.
 	 */
 	CSTATE_START_COMMAND,
-	CSTATE_SKIP_COMMAND,
 	CSTATE_WAIT_RESULT,
 	CSTATE_SLEEP,
 	CSTATE_END_COMMAND,
+	CSTATE_SKIP_COMMAND,
 
 	/*
-	 * 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
-	 * in CSTATE_START_THROTTLE state, or enters CSTATE_FINISHED if we have no
-	 * more work to do.
+	 * CSTATE_END_TX performs end-of-transaction processing.  It calculates
+	 * latency, and logs the transaction.  In --connect mode, it closes the
+	 * current connection.
+	 *
+	 * Then either starts over in CSTATE_CHOOSE_SCRIPT, or enters CSTATE_FINISHED
+	 * if we have no more work to do.
 	 */
 	CSTATE_END_TX,
 
@@ -2780,16 +2791,13 @@ evaluateSleep(CState *st, int argc, char **argv, int *usecs)
 
 /*
  * Advance the state machine of a connection, if possible.
+ *
+ * All state changes are performed within this function called
+ * by threadRun.
  */
 static void
 doCustom(TState *thread, CState *st, StatsData *agg)
 {
-	PGresult   *res;
-	Command    *command;
-	instr_time	now;
-	bool		end_tx_processed = false;
-	int64		wait;
-
 	/*
 	 * gettimeofday() isn't free, so we get the current timestamp lazily the
 	 * first time it's needed, and reuse the same value throughout this
@@ -2798,37 +2806,44 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 	 * means "not set yet".  Reset "now" when we execute shell commands or
 	 * expressions, which might take a non-negligible amount of time, though.
 	 */
+	instr_time	now;
 	INSTR_TIME_SET_ZERO(now);
 
 	/*
 	 * Loop in the state machine, until we have to wait for a result from the
-	 * server (or have to sleep, for throttling or for \sleep).
+	 * server or have to sleep for throttling or \sleep.
 	 *
 	 * Note: In the switch-statement below, 'break' will loop back here,
 	 * meaning "continue in the state machine".  Return is used to return to
-	 * the caller.
+	 * the caller, giving the thread opportunity to move forward another client.
 	 */
 	for (;;)
 	{
+		PGresult   *res;
+		Command    *command;
+
 		switch (st->state)
 		{
 				/*
 				 * Select transaction to run.
 				 */
 			case CSTATE_CHOOSE_SCRIPT:
-
 				st->use_file = chooseScript(thread);
 
 				if (debug)
 					fprintf(stderr, "client %d executing script \"%s\"\n", st->id,
 							sql_script[st->use_file].desc);
 
-				if (throttle_delay > 0)
+				/* check stack consistency */
+				Assert(conditional_stack_empty(st->cstack));
+
+				if (timer_exceeded)
+					st->state = CSTATE_FINISHED;
+				else if (throttle_delay > 0)
 					st->state = CSTATE_START_THROTTLE;
 				else
 					st->state = CSTATE_START_TX;
-				/* check consistency */
-				Assert(conditional_stack_empty(st->cstack));
+
 				break;
 
 				/*
@@ -2846,21 +2861,10 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * away.
 				 */
 				Assert(throttle_delay > 0);
-				wait = getPoissonRand(thread, throttle_delay);
 
-				thread->throttle_trigger += wait;
+				thread->throttle_trigger += getPoissonRand(thread, throttle_delay);
 				st->txn_scheduled = thread->throttle_trigger;
 
-				/*
-				 * stop client if next transaction is beyond pgbench end of
-				 * execution
-				 */
-				if (duration > 0 && st->txn_scheduled > end_time)
-				{
-					st->state = CSTATE_FINISHED;
-					break;
-				}
-
 				/*
 				 * If --latency-limit is used, and this slot is already late
 				 * so that the transaction will miss the latency limit even if
@@ -2872,19 +2876,19 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				{
 					int64		now_us;
 
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					now_us = INSTR_TIME_GET_MICROSEC(now);
+
 					while (thread->throttle_trigger < now_us - latency_limit &&
 						   (nxacts <= 0 || st->cnt < nxacts))
 					{
 						processXactStats(thread, st, &now, true, agg);
 						/* next rendez-vous */
-						wait = getPoissonRand(thread, throttle_delay);
-						thread->throttle_trigger += wait;
+						thread->throttle_trigger += getPoissonRand(thread, throttle_delay);
 						st->txn_scheduled = thread->throttle_trigger;
 					}
-					/* stop client if -t exceeded */
+
+					/* stop client if -t was exceeded in the previous skip loop */
 					if (nxacts > 0 && st->cnt >= nxacts)
 					{
 						st->state = CSTATE_FINISHED;
@@ -2892,38 +2896,45 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 				}
 
+				/*
+				 * stop client if next transaction is beyond pgbench end of
+				 * execution.
+				 */
+				if (duration > 0 && st->txn_scheduled > end_time)
+				{
+					st->state = CSTATE_FINISHED;
+					break;
+				}
+
 				st->state = CSTATE_THROTTLE;
-				if (debug)
-					fprintf(stderr, "client %d throttling " INT64_FORMAT " us\n",
-							st->id, wait);
 				break;
 
 				/*
 				 * Wait until it's time to start next transaction.
 				 */
 			case CSTATE_THROTTLE:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
+
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+
 				if (INSTR_TIME_GET_MICROSEC(now) < st->txn_scheduled)
-					return;		/* Still sleeping, nothing to do here */
+					return;		/* still sleeping, nothing to do here */
 
-				/* Else done sleeping, start the transaction */
-				st->state = CSTATE_START_TX;
+				/* done sleeping, but do not start if transaction if we are done */
+				if (timer_exceeded)
+					st->state = CSTATE_FINISHED;
+				else
+					st->state = CSTATE_START_TX;
 				break;
 
 				/* Start new transaction */
 			case CSTATE_START_TX:
 
-				/*
-				 * Establish connection on first call, or if is_connect is
-				 * true.
-				 */
+				/* establish connection if needed, i.e. under --connect */
 				if (st->con == NULL)
 				{
 					instr_time	start;
 
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					start = now;
 					if ((st->con = doConnect()) == NULL)
 					{
@@ -2939,28 +2950,20 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					memset(st->prepared, 0, sizeof(st->prepared));
 				}
 
+				/* record transaction start time.  */
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+				st->txn_begin = now;
+
 				/*
-				 * Record transaction start time under logging, progress or
-				 * throttling.
+				 * When not throttling, this is also the transaction's
+				 * scheduled start time.
 				 */
-				if (use_log || progress || throttle_delay || latency_limit ||
-					per_script_stats)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
-					st->txn_begin = now;
-
-					/*
-					 * When not throttling, this is also the transaction's
-					 * scheduled start time.
-					 */
-					if (!throttle_delay)
-						st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
-				}
+				if (!throttle_delay)
+					st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
 
 				/* Begin with the first command */
-				st->command = 0;
 				st->state = CSTATE_START_COMMAND;
+				st->command = 0;
 				break;
 
 				/*
@@ -2979,17 +2982,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					break;
 				}
 
-				/*
-				 * Record statement start time if per-command latencies are
-				 * requested
-				 */
-				if (is_latencies)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
-					st->stmt_begin = now;
-				}
+				/* record statement start time. */
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+				st->stmt_begin = now;
 
+				/* execute the command */
 				if (command->type == SQL_COMMAND)
 				{
 					if (!sendCommand(st, command))
@@ -3032,8 +3029,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 							break;
 						}
 
-						if (INSTR_TIME_IS_ZERO(now))
-							INSTR_TIME_SET_CURRENT(now);
+						INSTR_TIME_SET_CURRENT_LAZY(now);
+
 						st->sleep_until = INSTR_TIME_GET_MICROSEC(now) + usec;
 						st->state = CSTATE_SLEEP;
 						break;
@@ -3084,10 +3081,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 							}
 							else	/* elif */
 							{
-								/*
-								 * we should get here only if the "elif"
-								 * needed evaluation
-								 */
+								/* we should get here only if the "elif" needed evaluation */
 								Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
 								conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
 							}
@@ -3119,43 +3113,23 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 					else if (command->meta == META_SETSHELL)
 					{
-						bool		ret = runShellCommand(st, argv[1], argv + 2, argc - 2);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
+						if (!runShellCommand(st, argv[1], argv + 2, argc - 2))
 						{
 							commandFailed(st, "setshell", "execution of meta-command failed");
 							st->state = CSTATE_ABORTED;
 							break;
 						}
-						else
-						{
-							/* succeeded */
-						}
+						/* else success */
 					}
 					else if (command->meta == META_SHELL)
 					{
-						bool		ret = runShellCommand(st, NULL, argv + 1, argc - 1);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
+						if (!runShellCommand(st, NULL, argv + 1, argc - 1))
 						{
 							commandFailed(st, "shell", "execution of meta-command failed");
 							st->state = CSTATE_ABORTED;
 							break;
 						}
-						else
-						{
-							/* succeeded */
-						}
+						/* else success */
 					}
 
 			move_to_end_command:
@@ -3257,6 +3231,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 
 					if (st->state != CSTATE_SKIP_COMMAND)
+						/* out of quick skip command loop */
 						break;
 				}
 				break;
@@ -3306,10 +3281,9 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * instead of CSTATE_START_TX.
 				 */
 			case CSTATE_SLEEP:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
 				if (INSTR_TIME_GET_MICROSEC(now) < st->sleep_until)
-					return;		/* Still sleeping, nothing to do here */
+					return;		/* still sleeping, nothing to do here */
 				/* Else done sleeping. */
 				st->state = CSTATE_END_COMMAND;
 				break;
@@ -3324,17 +3298,13 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * in thread-local data structure, if per-command latencies
 				 * are requested.
 				 */
-				if (is_latencies)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
 
-					/* XXX could use a mutex here, but we choose not to */
-					command = sql_script[st->use_file].commands[st->command];
-					addToSimpleStats(&command->stats,
-									 INSTR_TIME_GET_DOUBLE(now) -
-									 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
-				}
+				/* XXX could use a mutex here, but we choose not to */
+				command = sql_script[st->use_file].commands[st->command];
+				addToSimpleStats(&command->stats,
+								 INSTR_TIME_GET_DOUBLE(now) -
+								 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
 
 				/* Go ahead with next command, to be executed or skipped */
 				st->command++;
@@ -3343,19 +3313,15 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				break;
 
 				/*
-				 * End of transaction.
+				 * End of transaction (end of script, really).
 				 */
 			case CSTATE_END_TX:
 
 				/* transaction finished: calculate latency and do log */
 				processXactStats(thread, st, &now, false, 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);
-				}
+				/* missing \endif... cannot happen if CheckConditional was okay */
+				Assert(conditional_stack_empty(st->cstack));
 
 				if (is_connect)
 				{
@@ -3369,26 +3335,17 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					st->state = CSTATE_FINISHED;
 					break;
 				}
+				else
+				{
+					/* next transaction */
+					st->state = CSTATE_CHOOSE_SCRIPT;
 
-				/*
-				 * No transaction is underway anymore.
-				 */
-				st->state = CSTATE_CHOOSE_SCRIPT;
-
-				/*
-				 * If we paced through all commands in the script in this
-				 * loop, without returning to the caller even once, do it now.
-				 * This gives the thread a chance to process other
-				 * connections, and to do progress reporting.  This can
-				 * currently only happen if the script consists entirely of
-				 * meta-commands.
-				 */
-				if (end_tx_processed)
+					/*
+					 * Ensure that we always return on this point, so as
+					 * to avoid an infinite loop if the script only contains
+					 * meta commands.
+					 */
 					return;
-				else
-				{
-					end_tx_processed = true;
-					break;
 				}
 
 				/*
@@ -3502,8 +3459,7 @@ processXactStats(TState *thread, CState *st, instr_time *now,
 
 	if (detailed && !skipped)
 	{
-		if (INSTR_TIME_IS_ZERO(*now))
-			INSTR_TIME_SET_CURRENT(*now);
+		INSTR_TIME_SET_CURRENT_LAZY(*now);
 
 		/* compute latency & lag */
 		latency = INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled;
@@ -5758,7 +5714,7 @@ threadRun(void *arg)
 
 	if (!is_connect)
 	{
-		/* make connections to the database */
+		/* make connections to the database before starting */
 		for (i = 0; i < nstate; i++)
 		{
 			if ((state[i].con = doConnect()) == NULL)
@@ -5794,14 +5750,7 @@ threadRun(void *arg)
 		{
 			CState	   *st = &state[i];
 
-			if (st->state == CSTATE_THROTTLE && timer_exceeded)
-			{
-				/* interrupt client that has not started a transaction */
-				st->state = CSTATE_FINISHED;
-				finishCon(st);
-				remains--;
-			}
-			else if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
+			if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
 			{
 				/* a nap from the script, or under throttling */
 				int64		this_usec;
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f968444671..c46f6825bb 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -20,6 +20,8 @@
  *
  * INSTR_TIME_SET_CURRENT(t)		set t to current time
  *
+ * INSTR_TIME_SET_CURRENT_LAZY(t)	set t to current time if t is zero
+ *
  * INSTR_TIME_ADD(x, y)				x += y
  *
  * INSTR_TIME_SUBTRACT(x, y)		x -= y
@@ -245,4 +247,9 @@ GetTimerFrequency(void)
 
 #endif							/* WIN32 */
 
+/* same macro on all platforms */
+#define INSTR_TIME_SET_CURRENT_LAZY(t) \
+	if (INSTR_TIME_IS_ZERO(t)) \
+		INSTR_TIME_SET_CURRENT(t)
+
 #endif							/* INSTR_TIME_H */
#4Fabien COELHO
coelho@cri.ensmp.fr
In reply to: Fabien COELHO (#3)
1 attachment(s)
RE: pgbench - doCustom cleanup

Attached is a v3, where I have updated inaccurate comments.

Attached v4 is a rebase after 409231919443984635b7ae9b7e2e261ab984eb1e

--
Fabien.

Attachments:

pgbench-state-change-4.patchtext/x-diff; name=pgbench-state-change-4.patchDownload
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 73d3de0677..ed6ff75426 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -295,23 +295,31 @@ typedef enum
 	/*
 	 * The client must first choose a script to execute.  Once chosen, it can
 	 * either be throttled (state CSTATE_START_THROTTLE under --rate) or start
-	 * right away (state CSTATE_START_TX).
+	 * right away (state CSTATE_START_TX) or not start at all if the timer was
+	 * exceeded (state CSTATE_FINISHED).
 	 */
 	CSTATE_CHOOSE_SCRIPT,
 
 	/*
 	 * In CSTATE_START_THROTTLE state, we calculate when to begin the next
 	 * transaction, and advance to CSTATE_THROTTLE.  CSTATE_THROTTLE state
-	 * sleeps until that moment.  (If throttling is not enabled, doCustom()
-	 * falls directly through from CSTATE_START_THROTTLE to CSTATE_START_TX.)
+	 * sleeps until that moment.
+	 *
+	 * It may also detect that the next transaction would start beyond the end
+	 * of run, and switch to CSTATE_FINISHED.
 	 */
 	CSTATE_START_THROTTLE,
 	CSTATE_THROTTLE,
 
 	/*
 	 * CSTATE_START_TX performs start-of-transaction processing.  Establishes
-	 * a new connection for the transaction, in --connect mode, and records
-	 * the transaction start time.
+	 * a new connection for the transaction in --connect mode, records
+	 * the transaction start time, and proceed to the first command.
+	 *
+	 * Note: once a script is started, it will either error or run till
+	 * its end, where it may be interrupted. It is not interrupted while
+	 * running, so pgbench --time is to be understood as tx are allowed to
+	 * start in that time, and will finish when their work is completed.
 	 */
 	CSTATE_START_TX,
 
@@ -324,9 +332,6 @@ typedef enum
 	 * and we enter the CSTATE_SLEEP state to wait for it to expire. Other
 	 * meta-commands are executed immediately.
 	 *
-	 * CSTATE_SKIP_COMMAND for conditional branches which are not executed,
-	 * quickly skip commands that do not need any evaluation.
-	 *
 	 * CSTATE_WAIT_RESULT waits until we get a result set back from the server
 	 * for the current command.
 	 *
@@ -334,19 +339,25 @@ typedef enum
 	 *
 	 * CSTATE_END_COMMAND records the end-of-command timestamp, increments the
 	 * command counter, and loops back to CSTATE_START_COMMAND state.
+	 *
+	 * CSTATE_SKIP_COMMAND is used by conditional branches which are not
+	 * executed. It quickly skip commands that do not need any evaluation.
+	 * This state can move forward several commands, till there is something
+	 * to do or the end of the script.
 	 */
 	CSTATE_START_COMMAND,
-	CSTATE_SKIP_COMMAND,
 	CSTATE_WAIT_RESULT,
 	CSTATE_SLEEP,
 	CSTATE_END_COMMAND,
+	CSTATE_SKIP_COMMAND,
 
 	/*
-	 * 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
-	 * in CSTATE_START_THROTTLE state, or enters CSTATE_FINISHED if we have no
-	 * more work to do.
+	 * CSTATE_END_TX performs end-of-transaction processing.  It calculates
+	 * latency, and logs the transaction.  In --connect mode, it closes the
+	 * current connection.
+	 *
+	 * Then either starts over in CSTATE_CHOOSE_SCRIPT, or enters CSTATE_FINISHED
+	 * if we have no more work to do.
 	 */
 	CSTATE_END_TX,
 
@@ -2821,16 +2832,13 @@ evaluateSleep(CState *st, int argc, char **argv, int *usecs)
 
 /*
  * Advance the state machine of a connection, if possible.
+ *
+ * All state changes are performed within this function called
+ * by threadRun.
  */
 static void
 doCustom(TState *thread, CState *st, StatsData *agg)
 {
-	PGresult   *res;
-	Command    *command;
-	instr_time	now;
-	bool		end_tx_processed = false;
-	int64		wait;
-
 	/*
 	 * gettimeofday() isn't free, so we get the current timestamp lazily the
 	 * first time it's needed, and reuse the same value throughout this
@@ -2839,37 +2847,44 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 	 * means "not set yet".  Reset "now" when we execute shell commands or
 	 * expressions, which might take a non-negligible amount of time, though.
 	 */
+	instr_time	now;
 	INSTR_TIME_SET_ZERO(now);
 
 	/*
 	 * Loop in the state machine, until we have to wait for a result from the
-	 * server (or have to sleep, for throttling or for \sleep).
+	 * server or have to sleep for throttling or \sleep.
 	 *
 	 * Note: In the switch-statement below, 'break' will loop back here,
 	 * meaning "continue in the state machine".  Return is used to return to
-	 * the caller.
+	 * the caller, giving the thread opportunity to move forward another client.
 	 */
 	for (;;)
 	{
+		PGresult   *res;
+		Command    *command;
+
 		switch (st->state)
 		{
 				/*
 				 * Select transaction to run.
 				 */
 			case CSTATE_CHOOSE_SCRIPT:
-
 				st->use_file = chooseScript(thread);
 
 				if (debug)
 					fprintf(stderr, "client %d executing script \"%s\"\n", st->id,
 							sql_script[st->use_file].desc);
 
-				if (throttle_delay > 0)
+				/* check stack consistency */
+				Assert(conditional_stack_empty(st->cstack));
+
+				if (timer_exceeded)
+					st->state = CSTATE_FINISHED;
+				else if (throttle_delay > 0)
 					st->state = CSTATE_START_THROTTLE;
 				else
 					st->state = CSTATE_START_TX;
-				/* check consistency */
-				Assert(conditional_stack_empty(st->cstack));
+
 				break;
 
 				/*
@@ -2887,21 +2902,10 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * away.
 				 */
 				Assert(throttle_delay > 0);
-				wait = getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
 
-				thread->throttle_trigger += wait;
+				thread->throttle_trigger += getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
 				st->txn_scheduled = thread->throttle_trigger;
 
-				/*
-				 * stop client if next transaction is beyond pgbench end of
-				 * execution
-				 */
-				if (duration > 0 && st->txn_scheduled > end_time)
-				{
-					st->state = CSTATE_FINISHED;
-					break;
-				}
-
 				/*
 				 * If --latency-limit is used, and this slot is already late
 				 * so that the transaction will miss the latency limit even if
@@ -2913,20 +2917,20 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				{
 					int64		now_us;
 
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					now_us = INSTR_TIME_GET_MICROSEC(now);
+
 					while (thread->throttle_trigger < now_us - latency_limit &&
 						   (nxacts <= 0 || st->cnt < nxacts))
 					{
 						processXactStats(thread, st, &now, true, agg);
 						/* next rendez-vous */
-						wait = getPoissonRand(&thread->ts_throttle_rs,
-											  throttle_delay);
-						thread->throttle_trigger += wait;
+						thread->throttle_trigger +=
+							getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
 						st->txn_scheduled = thread->throttle_trigger;
 					}
-					/* stop client if -t exceeded */
+
+					/* stop client if -t was exceeded in the previous skip loop */
 					if (nxacts > 0 && st->cnt >= nxacts)
 					{
 						st->state = CSTATE_FINISHED;
@@ -2934,38 +2938,45 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 				}
 
+				/*
+				 * stop client if next transaction is beyond pgbench end of
+				 * execution.
+				 */
+				if (duration > 0 && st->txn_scheduled > end_time)
+				{
+					st->state = CSTATE_FINISHED;
+					break;
+				}
+
 				st->state = CSTATE_THROTTLE;
-				if (debug)
-					fprintf(stderr, "client %d throttling " INT64_FORMAT " us\n",
-							st->id, wait);
 				break;
 
 				/*
 				 * Wait until it's time to start next transaction.
 				 */
 			case CSTATE_THROTTLE:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
+
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+
 				if (INSTR_TIME_GET_MICROSEC(now) < st->txn_scheduled)
-					return;		/* Still sleeping, nothing to do here */
+					return;		/* still sleeping, nothing to do here */
 
-				/* Else done sleeping, start the transaction */
-				st->state = CSTATE_START_TX;
+				/* done sleeping, but do not start if transaction if we are done */
+				if (timer_exceeded)
+					st->state = CSTATE_FINISHED;
+				else
+					st->state = CSTATE_START_TX;
 				break;
 
 				/* Start new transaction */
 			case CSTATE_START_TX:
 
-				/*
-				 * Establish connection on first call, or if is_connect is
-				 * true.
-				 */
+				/* establish connection if needed, i.e. under --connect */
 				if (st->con == NULL)
 				{
 					instr_time	start;
 
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					start = now;
 					if ((st->con = doConnect()) == NULL)
 					{
@@ -2981,28 +2992,20 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					memset(st->prepared, 0, sizeof(st->prepared));
 				}
 
+				/* record transaction start time.  */
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+				st->txn_begin = now;
+
 				/*
-				 * Record transaction start time under logging, progress or
-				 * throttling.
+				 * When not throttling, this is also the transaction's
+				 * scheduled start time.
 				 */
-				if (use_log || progress || throttle_delay || latency_limit ||
-					per_script_stats)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
-					st->txn_begin = now;
-
-					/*
-					 * When not throttling, this is also the transaction's
-					 * scheduled start time.
-					 */
-					if (!throttle_delay)
-						st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
-				}
+				if (!throttle_delay)
+					st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
 
 				/* Begin with the first command */
-				st->command = 0;
 				st->state = CSTATE_START_COMMAND;
+				st->command = 0;
 				break;
 
 				/*
@@ -3021,17 +3024,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					break;
 				}
 
-				/*
-				 * Record statement start time if per-command latencies are
-				 * requested
-				 */
-				if (is_latencies)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
-					st->stmt_begin = now;
-				}
+				/* record statement start time. */
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+				st->stmt_begin = now;
 
+				/* execute the command */
 				if (command->type == SQL_COMMAND)
 				{
 					if (!sendCommand(st, command))
@@ -3074,8 +3071,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 							break;
 						}
 
-						if (INSTR_TIME_IS_ZERO(now))
-							INSTR_TIME_SET_CURRENT(now);
+						INSTR_TIME_SET_CURRENT_LAZY(now);
+
 						st->sleep_until = INSTR_TIME_GET_MICROSEC(now) + usec;
 						st->state = CSTATE_SLEEP;
 						break;
@@ -3126,10 +3123,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 							}
 							else	/* elif */
 							{
-								/*
-								 * we should get here only if the "elif"
-								 * needed evaluation
-								 */
+								/* we should get here only if the "elif" needed evaluation */
 								Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
 								conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
 							}
@@ -3161,43 +3155,23 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 					else if (command->meta == META_SETSHELL)
 					{
-						bool		ret = runShellCommand(st, argv[1], argv + 2, argc - 2);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
+						if (!runShellCommand(st, argv[1], argv + 2, argc - 2))
 						{
 							commandFailed(st, "setshell", "execution of meta-command failed");
 							st->state = CSTATE_ABORTED;
 							break;
 						}
-						else
-						{
-							/* succeeded */
-						}
+						/* else success */
 					}
 					else if (command->meta == META_SHELL)
 					{
-						bool		ret = runShellCommand(st, NULL, argv + 1, argc - 1);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
+						if (!runShellCommand(st, NULL, argv + 1, argc - 1))
 						{
 							commandFailed(st, "shell", "execution of meta-command failed");
 							st->state = CSTATE_ABORTED;
 							break;
 						}
-						else
-						{
-							/* succeeded */
-						}
+						/* else success */
 					}
 
 			move_to_end_command:
@@ -3299,6 +3273,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 
 					if (st->state != CSTATE_SKIP_COMMAND)
+						/* out of quick skip command loop */
 						break;
 				}
 				break;
@@ -3348,10 +3323,9 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * instead of CSTATE_START_TX.
 				 */
 			case CSTATE_SLEEP:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
 				if (INSTR_TIME_GET_MICROSEC(now) < st->sleep_until)
-					return;		/* Still sleeping, nothing to do here */
+					return;		/* still sleeping, nothing to do here */
 				/* Else done sleeping. */
 				st->state = CSTATE_END_COMMAND;
 				break;
@@ -3366,17 +3340,13 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * in thread-local data structure, if per-command latencies
 				 * are requested.
 				 */
-				if (is_latencies)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
 
-					/* XXX could use a mutex here, but we choose not to */
-					command = sql_script[st->use_file].commands[st->command];
-					addToSimpleStats(&command->stats,
-									 INSTR_TIME_GET_DOUBLE(now) -
-									 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
-				}
+				/* XXX could use a mutex here, but we choose not to */
+				command = sql_script[st->use_file].commands[st->command];
+				addToSimpleStats(&command->stats,
+								 INSTR_TIME_GET_DOUBLE(now) -
+								 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
 
 				/* Go ahead with next command, to be executed or skipped */
 				st->command++;
@@ -3385,19 +3355,15 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				break;
 
 				/*
-				 * End of transaction.
+				 * End of transaction (end of script, really).
 				 */
 			case CSTATE_END_TX:
 
 				/* transaction finished: calculate latency and do log */
 				processXactStats(thread, st, &now, false, 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);
-				}
+				/* missing \endif... cannot happen if CheckConditional was okay */
+				Assert(conditional_stack_empty(st->cstack));
 
 				if (is_connect)
 				{
@@ -3411,26 +3377,17 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					st->state = CSTATE_FINISHED;
 					break;
 				}
+				else
+				{
+					/* next transaction */
+					st->state = CSTATE_CHOOSE_SCRIPT;
 
-				/*
-				 * No transaction is underway anymore.
-				 */
-				st->state = CSTATE_CHOOSE_SCRIPT;
-
-				/*
-				 * If we paced through all commands in the script in this
-				 * loop, without returning to the caller even once, do it now.
-				 * This gives the thread a chance to process other
-				 * connections, and to do progress reporting.  This can
-				 * currently only happen if the script consists entirely of
-				 * meta-commands.
-				 */
-				if (end_tx_processed)
+					/*
+					 * Ensure that we always return on this point, so as
+					 * to avoid an infinite loop if the script only contains
+					 * meta commands.
+					 */
 					return;
-				else
-				{
-					end_tx_processed = true;
-					break;
 				}
 
 				/*
@@ -3544,8 +3501,7 @@ processXactStats(TState *thread, CState *st, instr_time *now,
 
 	if (detailed && !skipped)
 	{
-		if (INSTR_TIME_IS_ZERO(*now))
-			INSTR_TIME_SET_CURRENT(*now);
+		INSTR_TIME_SET_CURRENT_LAZY(*now);
 
 		/* compute latency & lag */
 		latency = INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled;
@@ -5809,7 +5765,7 @@ threadRun(void *arg)
 
 	if (!is_connect)
 	{
-		/* make connections to the database */
+		/* make connections to the database before starting */
 		for (i = 0; i < nstate; i++)
 		{
 			if ((state[i].con = doConnect()) == NULL)
@@ -5845,14 +5801,7 @@ threadRun(void *arg)
 		{
 			CState	   *st = &state[i];
 
-			if (st->state == CSTATE_THROTTLE && timer_exceeded)
-			{
-				/* interrupt client that has not started a transaction */
-				st->state = CSTATE_FINISHED;
-				finishCon(st);
-				remains--;
-			}
-			else if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
+			if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
 			{
 				/* a nap from the script, or under throttling */
 				int64		this_usec;
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f968444671..c46f6825bb 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -20,6 +20,8 @@
  *
  * INSTR_TIME_SET_CURRENT(t)		set t to current time
  *
+ * INSTR_TIME_SET_CURRENT_LAZY(t)	set t to current time if t is zero
+ *
  * INSTR_TIME_ADD(x, y)				x += y
  *
  * INSTR_TIME_SUBTRACT(x, y)		x -= y
@@ -245,4 +247,9 @@ GetTimerFrequency(void)
 
 #endif							/* WIN32 */
 
+/* same macro on all platforms */
+#define INSTR_TIME_SET_CURRENT_LAZY(t) \
+	if (INSTR_TIME_IS_ZERO(t)) \
+		INSTR_TIME_SET_CURRENT(t)
+
 #endif							/* INSTR_TIME_H */
#5Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Fabien COELHO (#4)
1 attachment(s)
Re: pgbench - doCustom cleanup

On 2018-Nov-17, Fabien COELHO wrote:

Attached is a v3, where I have updated inaccurate comments.

Attached v4 is a rebase after 409231919443984635b7ae9b7e2e261ab984eb1e

Attached v5. I thought that separating the part that executes the
command was an obvious readability improvement. Tests still pass,
though maybe I broke something inadvertently. (I started by thinking
"does this block require a 'fall-through' comment?" The 600 line
function is pretty hard to read with the multiple messy switches and
conditionals; split into 400 + 200 subroutine it's nicer to reason
about.)

Do we really use the word "move" to talk about state changes? It sounds
very odd to me. I would change that to "transition" -- would anybody
object to that? (Not changed in v5.)

On INSTR_TIME_SET_CURRENT_LAZY(), you cannot just put an "if" inside a
macro -- consider this:
if (foo)
INSTR_TIME_SET_CURRENT_LAZY(bar);
else
something_else();
Which "if" is the else now attached to? Now maybe the C standard has an
answer for that (I don't know what it is), but it's hard to read and
likely the compiler will complain anyway. I wrapped it in "do { }
while(0)" as is customary.

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Attachments:

pgbench-state-change-5.patchtext/x-diff; charset=us-asciiDownload
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 73d3de0677..df14af5259 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -294,24 +294,32 @@ typedef enum
 {
 	/*
 	 * The client must first choose a script to execute.  Once chosen, it can
-	 * either be throttled (state CSTATE_START_THROTTLE under --rate) or start
-	 * right away (state CSTATE_START_TX).
+	 * either be throttled (state CSTATE_START_THROTTLE under --rate), start
+	 * right away (state CSTATE_START_TX) or not start at all if the timer was
+	 * exceeded (state CSTATE_FINISHED).
 	 */
 	CSTATE_CHOOSE_SCRIPT,
 
 	/*
 	 * In CSTATE_START_THROTTLE state, we calculate when to begin the next
 	 * transaction, and advance to CSTATE_THROTTLE.  CSTATE_THROTTLE state
-	 * sleeps until that moment.  (If throttling is not enabled, doCustom()
-	 * falls directly through from CSTATE_START_THROTTLE to CSTATE_START_TX.)
+	 * sleeps until that moment.
+	 *
+	 * It may also detect that the next transaction would start beyond the end
+	 * of run, and switch to CSTATE_FINISHED.
 	 */
 	CSTATE_START_THROTTLE,
 	CSTATE_THROTTLE,
 
 	/*
 	 * CSTATE_START_TX performs start-of-transaction processing.  Establishes
-	 * a new connection for the transaction, in --connect mode, and records
-	 * the transaction start time.
+	 * a new connection for the transaction in --connect mode, records
+	 * the transaction start time, and proceed to the first command.
+	 *
+	 * Note: once a script is started, it will either error or run till
+	 * its end, where it may be interrupted. It is not interrupted while
+	 * running, so pgbench --time is to be understood as tx are allowed to
+	 * start in that time, and will finish when their work is completed.
 	 */
 	CSTATE_START_TX,
 
@@ -324,9 +332,6 @@ typedef enum
 	 * and we enter the CSTATE_SLEEP state to wait for it to expire. Other
 	 * meta-commands are executed immediately.
 	 *
-	 * CSTATE_SKIP_COMMAND for conditional branches which are not executed,
-	 * quickly skip commands that do not need any evaluation.
-	 *
 	 * CSTATE_WAIT_RESULT waits until we get a result set back from the server
 	 * for the current command.
 	 *
@@ -334,19 +339,25 @@ typedef enum
 	 *
 	 * CSTATE_END_COMMAND records the end-of-command timestamp, increments the
 	 * command counter, and loops back to CSTATE_START_COMMAND state.
+	 *
+	 * CSTATE_SKIP_COMMAND is used by conditional branches which are not
+	 * executed. It quickly skip commands that do not need any evaluation.
+	 * This state can move forward several commands, till there is something
+	 * to do or the end of the script.
 	 */
 	CSTATE_START_COMMAND,
-	CSTATE_SKIP_COMMAND,
 	CSTATE_WAIT_RESULT,
 	CSTATE_SLEEP,
 	CSTATE_END_COMMAND,
+	CSTATE_SKIP_COMMAND,
 
 	/*
-	 * 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
-	 * in CSTATE_START_THROTTLE state, or enters CSTATE_FINISHED if we have no
-	 * more work to do.
+	 * CSTATE_END_TX performs end-of-transaction processing.  It calculates
+	 * latency, and logs the transaction.  In --connect mode, it closes the
+	 * current connection.
+	 *
+	 * Then either starts over in CSTATE_CHOOSE_SCRIPT, or enters CSTATE_FINISHED
+	 * if we have no more work to do.
 	 */
 	CSTATE_END_TX,
 
@@ -575,6 +586,7 @@ static void processXactStats(TState *thread, CState *st, instr_time *now,
 static void pgbench_error(const char *fmt,...) pg_attribute_printf(1, 2);
 static void addScript(ParsedScript script);
 static void *threadRun(void *arg);
+static instr_time do_execute_command(TState *thread, CState *st, instr_time now);
 static void finishCon(CState *st);
 static void setalarm(int seconds);
 static socket_set *alloc_socket_set(int count);
@@ -2821,16 +2833,12 @@ evaluateSleep(CState *st, int argc, char **argv, int *usecs)
 
 /*
  * Advance the state machine of a connection, if possible.
+ *
+ * All state changes are performed within this function called by threadRun.
  */
 static void
 doCustom(TState *thread, CState *st, StatsData *agg)
 {
-	PGresult   *res;
-	Command    *command;
-	instr_time	now;
-	bool		end_tx_processed = false;
-	int64		wait;
-
 	/*
 	 * gettimeofday() isn't free, so we get the current timestamp lazily the
 	 * first time it's needed, and reuse the same value throughout this
@@ -2839,37 +2847,45 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 	 * means "not set yet".  Reset "now" when we execute shell commands or
 	 * expressions, which might take a non-negligible amount of time, though.
 	 */
+	instr_time	now;
+
 	INSTR_TIME_SET_ZERO(now);
 
 	/*
 	 * Loop in the state machine, until we have to wait for a result from the
-	 * server (or have to sleep, for throttling or for \sleep).
+	 * server or have to sleep for throttling or \sleep.
 	 *
 	 * Note: In the switch-statement below, 'break' will loop back here,
 	 * meaning "continue in the state machine".  Return is used to return to
-	 * the caller.
+	 * the caller, giving the thread the opportunity to advance another client.
 	 */
 	for (;;)
 	{
+		PGresult   *res;
+		Command    *command;
+
 		switch (st->state)
 		{
 				/*
 				 * Select transaction to run.
 				 */
 			case CSTATE_CHOOSE_SCRIPT:
-
 				st->use_file = chooseScript(thread);
 
 				if (debug)
 					fprintf(stderr, "client %d executing script \"%s\"\n", st->id,
 							sql_script[st->use_file].desc);
 
-				if (throttle_delay > 0)
+				/* check stack consistency */
+				Assert(conditional_stack_empty(st->cstack));
+
+				if (timer_exceeded)
+					st->state = CSTATE_FINISHED;
+				else if (throttle_delay > 0)
 					st->state = CSTATE_START_THROTTLE;
 				else
 					st->state = CSTATE_START_TX;
-				/* check consistency */
-				Assert(conditional_stack_empty(st->cstack));
+
 				break;
 
 				/*
@@ -2887,22 +2903,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * away.
 				 */
 				Assert(throttle_delay > 0);
-				wait = getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
 
-				thread->throttle_trigger += wait;
+				thread->throttle_trigger += getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
 				st->txn_scheduled = thread->throttle_trigger;
 
 				/*
-				 * stop client if next transaction is beyond pgbench end of
-				 * execution
-				 */
-				if (duration > 0 && st->txn_scheduled > end_time)
-				{
-					st->state = CSTATE_FINISHED;
-					break;
-				}
-
-				/*
 				 * If --latency-limit is used, and this slot is already late
 				 * so that the transaction will miss the latency limit even if
 				 * it completed immediately, we skip this time slot and
@@ -2913,20 +2918,20 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				{
 					int64		now_us;
 
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					now_us = INSTR_TIME_GET_MICROSEC(now);
+
 					while (thread->throttle_trigger < now_us - latency_limit &&
 						   (nxacts <= 0 || st->cnt < nxacts))
 					{
 						processXactStats(thread, st, &now, true, agg);
 						/* next rendez-vous */
-						wait = getPoissonRand(&thread->ts_throttle_rs,
-											  throttle_delay);
-						thread->throttle_trigger += wait;
+						thread->throttle_trigger +=
+							getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
 						st->txn_scheduled = thread->throttle_trigger;
 					}
-					/* stop client if -t exceeded */
+
+					/* stop client if -t was exceeded in the previous skip loop */
 					if (nxacts > 0 && st->cnt >= nxacts)
 					{
 						st->state = CSTATE_FINISHED;
@@ -2934,38 +2939,42 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 				}
 
+				/*
+				 * stop client if next transaction is beyond pgbench end of
+				 * execution.
+				 */
+				if (duration > 0 && st->txn_scheduled > end_time)
+				{
+					st->state = CSTATE_FINISHED;
+					break;
+				}
+
 				st->state = CSTATE_THROTTLE;
-				if (debug)
-					fprintf(stderr, "client %d throttling " INT64_FORMAT " us\n",
-							st->id, wait);
 				break;
 
 				/*
 				 * Wait until it's time to start next transaction.
 				 */
 			case CSTATE_THROTTLE:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
-				if (INSTR_TIME_GET_MICROSEC(now) < st->txn_scheduled)
-					return;		/* Still sleeping, nothing to do here */
 
-				/* Else done sleeping, start the transaction */
-				st->state = CSTATE_START_TX;
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+
+				if (INSTR_TIME_GET_MICROSEC(now) < st->txn_scheduled)
+					return;		/* still sleeping, nothing to do here */
+
+				/* done sleeping, but do not start transaction if we are done */
+				st->state = timer_exceeded ? CSTATE_FINISHED : CSTATE_START_TX;
 				break;
 
 				/* Start new transaction */
 			case CSTATE_START_TX:
 
-				/*
-				 * Establish connection on first call, or if is_connect is
-				 * true.
-				 */
+				/* establish connection if needed, i.e. under --connect */
 				if (st->con == NULL)
 				{
 					instr_time	start;
 
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					start = now;
 					if ((st->con = doConnect()) == NULL)
 					{
@@ -2981,235 +2990,28 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					memset(st->prepared, 0, sizeof(st->prepared));
 				}
 
-				/*
-				 * Record transaction start time under logging, progress or
-				 * throttling.
-				 */
-				if (use_log || progress || throttle_delay || latency_limit ||
-					per_script_stats)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
-					st->txn_begin = now;
+				/* record transaction start time.  */
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+				st->txn_begin = now;
 
-					/*
-					 * When not throttling, this is also the transaction's
-					 * scheduled start time.
-					 */
-					if (!throttle_delay)
-						st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
-				}
+				/*
+				 * When not throttling, this is also the transaction's
+				 * scheduled start time.
+				 */
+				if (!throttle_delay)
+					st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
 
 				/* Begin with the first command */
-				st->command = 0;
 				st->state = CSTATE_START_COMMAND;
+				st->command = 0;
 				break;
 
 				/*
 				 * Send a command to server (or execute a meta-command)
 				 */
 			case CSTATE_START_COMMAND:
-				command = sql_script[st->use_file].commands[st->command];
 
-				/*
-				 * If we reached the end of the script, move to end-of-xact
-				 * processing.
-				 */
-				if (command == NULL)
-				{
-					st->state = CSTATE_END_TX;
-					break;
-				}
-
-				/*
-				 * Record statement start time if per-command latencies are
-				 * requested
-				 */
-				if (is_latencies)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
-					st->stmt_begin = now;
-				}
-
-				if (command->type == SQL_COMMAND)
-				{
-					if (!sendCommand(st, command))
-					{
-						commandFailed(st, "SQL", "SQL command send failed");
-						st->state = CSTATE_ABORTED;
-					}
-					else
-						st->state = CSTATE_WAIT_RESULT;
-				}
-				else if (command->type == META_COMMAND)
-				{
-					int			argc = command->argc,
-								i;
-					char	  **argv = command->argv;
-
-					if (debug)
-					{
-						fprintf(stderr, "client %d executing \\%s", st->id, argv[0]);
-						for (i = 1; i < argc; i++)
-							fprintf(stderr, " %s", argv[i]);
-						fprintf(stderr, "\n");
-					}
-
-					if (command->meta == META_SLEEP)
-					{
-						/*
-						 * A \sleep doesn't execute anything, we just get the
-						 * delay from the argument, and enter the CSTATE_SLEEP
-						 * state.  (The per-command latency will be recorded
-						 * in CSTATE_SLEEP state, not here, after the delay
-						 * has elapsed.)
-						 */
-						int			usec;
-
-						if (!evaluateSleep(st, argc, argv, &usec))
-						{
-							commandFailed(st, "sleep", "execution of meta-command failed");
-							st->state = CSTATE_ABORTED;
-							break;
-						}
-
-						if (INSTR_TIME_IS_ZERO(now))
-							INSTR_TIME_SET_CURRENT(now);
-						st->sleep_until = INSTR_TIME_GET_MICROSEC(now) + usec;
-						st->state = CSTATE_SLEEP;
-						break;
-					}
-					else if (command->meta == META_SET ||
-							 command->meta == META_IF ||
-							 command->meta == META_ELIF)
-					{
-						/* backslash commands with an expression to evaluate */
-						PgBenchExpr *expr = command->expr;
-						PgBenchValue result;
-
-						if (command->meta == META_ELIF &&
-							conditional_stack_peek(st->cstack) == IFSTATE_TRUE)
-						{
-							/*
-							 * elif after executed block, skip eval and wait
-							 * for endif
-							 */
-							conditional_stack_poke(st->cstack, IFSTATE_IGNORED);
-							goto move_to_end_command;
-						}
-
-						if (!evaluateExpr(thread, st, expr, &result))
-						{
-							commandFailed(st, argv[0], "evaluation of meta-command failed");
-							st->state = CSTATE_ABORTED;
-							break;
-						}
-
-						if (command->meta == META_SET)
-						{
-							if (!putVariableValue(st, argv[0], argv[1], &result))
-							{
-								commandFailed(st, "set", "assignment of meta-command failed");
-								st->state = CSTATE_ABORTED;
-								break;
-							}
-						}
-						else	/* if and elif evaluated cases */
-						{
-							bool		cond = valueTruth(&result);
-
-							/* execute or not depending on evaluated condition */
-							if (command->meta == META_IF)
-							{
-								conditional_stack_push(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
-							}
-							else	/* elif */
-							{
-								/*
-								 * we should get here only if the "elif"
-								 * needed evaluation
-								 */
-								Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
-								conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
-							}
-						}
-					}
-					else if (command->meta == META_ELSE)
-					{
-						switch (conditional_stack_peek(st->cstack))
-						{
-							case IFSTATE_TRUE:
-								conditional_stack_poke(st->cstack, IFSTATE_ELSE_FALSE);
-								break;
-							case IFSTATE_FALSE: /* inconsistent if active */
-							case IFSTATE_IGNORED:	/* inconsistent if active */
-							case IFSTATE_NONE:	/* else without if */
-							case IFSTATE_ELSE_TRUE: /* else after else */
-							case IFSTATE_ELSE_FALSE:	/* else after else */
-							default:
-								/* dead code if conditional check is ok */
-								Assert(false);
-						}
-						goto move_to_end_command;
-					}
-					else if (command->meta == META_ENDIF)
-					{
-						Assert(!conditional_stack_empty(st->cstack));
-						conditional_stack_pop(st->cstack);
-						goto move_to_end_command;
-					}
-					else if (command->meta == META_SETSHELL)
-					{
-						bool		ret = runShellCommand(st, argv[1], argv + 2, argc - 2);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
-						{
-							commandFailed(st, "setshell", "execution of meta-command failed");
-							st->state = CSTATE_ABORTED;
-							break;
-						}
-						else
-						{
-							/* succeeded */
-						}
-					}
-					else if (command->meta == META_SHELL)
-					{
-						bool		ret = runShellCommand(st, NULL, argv + 1, argc - 1);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
-						{
-							commandFailed(st, "shell", "execution of meta-command failed");
-							st->state = CSTATE_ABORTED;
-							break;
-						}
-						else
-						{
-							/* succeeded */
-						}
-					}
-
-			move_to_end_command:
-
-					/*
-					 * executing the expression or shell command might take a
-					 * non-negligible amount of time, so reset 'now'
-					 */
-					INSTR_TIME_SET_ZERO(now);
-
-					st->state = CSTATE_END_COMMAND;
-				}
+				now = do_execute_command(thread, st, now);
 				break;
 
 				/*
@@ -3299,6 +3101,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 
 					if (st->state != CSTATE_SKIP_COMMAND)
+						/* out of quick skip command loop */
 						break;
 				}
 				break;
@@ -3348,10 +3151,9 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * instead of CSTATE_START_TX.
 				 */
 			case CSTATE_SLEEP:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
 				if (INSTR_TIME_GET_MICROSEC(now) < st->sleep_until)
-					return;		/* Still sleeping, nothing to do here */
+					return;		/* still sleeping, nothing to do here */
 				/* Else done sleeping. */
 				st->state = CSTATE_END_COMMAND;
 				break;
@@ -3366,17 +3168,13 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * in thread-local data structure, if per-command latencies
 				 * are requested.
 				 */
-				if (is_latencies)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
 
-					/* XXX could use a mutex here, but we choose not to */
-					command = sql_script[st->use_file].commands[st->command];
-					addToSimpleStats(&command->stats,
-									 INSTR_TIME_GET_DOUBLE(now) -
-									 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
-				}
+				/* XXX could use a mutex here, but we choose not to */
+				command = sql_script[st->use_file].commands[st->command];
+				addToSimpleStats(&command->stats,
+								 INSTR_TIME_GET_DOUBLE(now) -
+								 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
 
 				/* Go ahead with next command, to be executed or skipped */
 				st->command++;
@@ -3385,19 +3183,15 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				break;
 
 				/*
-				 * End of transaction.
+				 * End of transaction (end of script, really).
 				 */
 			case CSTATE_END_TX:
 
 				/* transaction finished: calculate latency and do log */
 				processXactStats(thread, st, &now, false, 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);
-				}
+				/* missing \endif... cannot happen if CheckConditional was okay */
+				Assert(conditional_stack_empty(st->cstack));
 
 				if (is_connect)
 				{
@@ -3411,26 +3205,17 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					st->state = CSTATE_FINISHED;
 					break;
 				}
-
-				/*
-				 * No transaction is underway anymore.
-				 */
-				st->state = CSTATE_CHOOSE_SCRIPT;
-
-				/*
-				 * If we paced through all commands in the script in this
-				 * loop, without returning to the caller even once, do it now.
-				 * This gives the thread a chance to process other
-				 * connections, and to do progress reporting.  This can
-				 * currently only happen if the script consists entirely of
-				 * meta-commands.
-				 */
-				if (end_tx_processed)
-					return;
 				else
 				{
-					end_tx_processed = true;
-					break;
+					/* next transaction */
+					st->state = CSTATE_CHOOSE_SCRIPT;
+
+					/*
+					 * Ensure that we always return on this point, so as
+					 * to avoid an infinite loop if the script only contains
+					 * meta commands.
+					 */
+					return;
 				}
 
 				/*
@@ -3445,6 +3230,189 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 }
 
 /*
+ * do_execute_command -- subroutine for doCustom
+ *		Executes the current command and advance the state machine.
+ *
+ * Returns the time that's current at command finish, which can be the input
+ * time if we consider that the time taken to execute would be negligible.
+ */
+static instr_time
+do_execute_command(TState *thread, CState *st, instr_time now)
+{
+	Command *command;
+
+	command = sql_script[st->use_file].commands[st->command];
+
+	/* If we reached the end of the script, move to end-of-xact processing */
+	if (command == NULL)
+	{
+		st->state = CSTATE_END_TX;
+		return now;
+	}
+
+	/* record statement start time. */
+	INSTR_TIME_SET_CURRENT_LAZY(now);
+	st->stmt_begin = now;
+
+	/* execute the command */
+	if (command->type == SQL_COMMAND)
+	{
+		if (!sendCommand(st, command))
+		{
+			commandFailed(st, "SQL", "SQL command send failed");
+			st->state = CSTATE_ABORTED;
+		}
+		else
+			st->state = CSTATE_WAIT_RESULT;
+	}
+	else if (command->type == META_COMMAND)
+	{
+		int			argc = command->argc;
+		char	  **argv = command->argv;
+
+		if (debug)
+		{
+			fprintf(stderr, "client %d executing \\%s", st->id, argv[0]);
+			for (int i = 1; i < argc; i++)
+				fprintf(stderr, " %s", argv[i]);
+			fprintf(stderr, "\n");
+		}
+
+		if (command->meta == META_SLEEP)
+		{
+			/*
+			 * A \sleep doesn't execute anything, we just get the
+			 * delay from the argument, and enter the CSTATE_SLEEP
+			 * state.  (The per-command latency will be recorded
+			 * in CSTATE_SLEEP state, not here, after the delay
+			 * has elapsed.)
+			 */
+			int			usec;
+
+			if (!evaluateSleep(st, argc, argv, &usec))
+			{
+				commandFailed(st, "sleep", "execution of meta-command failed");
+				st->state = CSTATE_ABORTED;
+				return now;
+			}
+
+			st->sleep_until = INSTR_TIME_GET_MICROSEC(now) + usec;
+			st->state = CSTATE_SLEEP;
+			return now;
+		}
+		else if (command->meta == META_SET ||
+				 command->meta == META_IF ||
+				 command->meta == META_ELIF)
+		{
+			/* backslash commands with an expression to evaluate */
+			PgBenchExpr *expr = command->expr;
+			PgBenchValue result;
+
+			if (command->meta == META_ELIF &&
+				conditional_stack_peek(st->cstack) == IFSTATE_TRUE)
+			{
+				/*
+				 * elif after executed block, skip eval and wait
+				 * for endif
+				 */
+				conditional_stack_poke(st->cstack, IFSTATE_IGNORED);
+				goto move_to_end_command;
+			}
+
+			if (!evaluateExpr(thread, st, expr, &result))
+			{
+				commandFailed(st, argv[0], "evaluation of meta-command failed");
+				st->state = CSTATE_ABORTED;
+				return now;
+			}
+
+			if (command->meta == META_SET)
+			{
+				if (!putVariableValue(st, argv[0], argv[1], &result))
+				{
+					commandFailed(st, "set", "assignment of meta-command failed");
+					st->state = CSTATE_ABORTED;
+					return now;
+				}
+			}
+			else	/* if and elif evaluated cases */
+			{
+				bool		cond = valueTruth(&result);
+
+				/* execute or not depending on evaluated condition */
+				if (command->meta == META_IF)
+				{
+					conditional_stack_push(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
+				}
+				else	/* elif */
+				{
+					/* we should get here only if the "elif" needed evaluation */
+					Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
+					conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
+				}
+			}
+		}
+		else if (command->meta == META_ELSE)
+		{
+			switch (conditional_stack_peek(st->cstack))
+			{
+				case IFSTATE_TRUE:
+					conditional_stack_poke(st->cstack, IFSTATE_ELSE_FALSE);
+					break;
+				case IFSTATE_FALSE: /* inconsistent if active */
+				case IFSTATE_IGNORED:	/* inconsistent if active */
+				case IFSTATE_NONE:	/* else without if */
+				case IFSTATE_ELSE_TRUE: /* else after else */
+				case IFSTATE_ELSE_FALSE:	/* else after else */
+				default:
+					/* dead code if conditional check is ok */
+					Assert(false);
+			}
+			goto move_to_end_command;
+		}
+		else if (command->meta == META_ENDIF)
+		{
+			Assert(!conditional_stack_empty(st->cstack));
+			conditional_stack_pop(st->cstack);
+			goto move_to_end_command;
+		}
+		else if (command->meta == META_SETSHELL)
+		{
+			if (!runShellCommand(st, argv[1], argv + 2, argc - 2))
+			{
+				commandFailed(st, "setshell", "execution of meta-command failed");
+				st->state = CSTATE_ABORTED;
+				return now;
+			}
+			/* else success */
+		}
+		else if (command->meta == META_SHELL)
+		{
+			if (!runShellCommand(st, NULL, argv + 1, argc - 1))
+			{
+				commandFailed(st, "shell", "execution of meta-command failed");
+				st->state = CSTATE_ABORTED;
+				return now;
+			}
+			/* else success */
+		}
+
+move_to_end_command:
+
+		/*
+		 * executing the expression or shell command might take a
+		 * non-negligible amount of time; reset 'now' so that it's
+		 * recomputed by caller.
+		 */
+		INSTR_TIME_SET_ZERO(now);
+
+		st->state = CSTATE_END_COMMAND;
+	}
+
+	return now;
+}
+
+/*
  * Print log entry after completing one transaction.
  *
  * We print Unix-epoch timestamps in the log, so that entries can be
@@ -3544,8 +3512,7 @@ processXactStats(TState *thread, CState *st, instr_time *now,
 
 	if (detailed && !skipped)
 	{
-		if (INSTR_TIME_IS_ZERO(*now))
-			INSTR_TIME_SET_CURRENT(*now);
+		INSTR_TIME_SET_CURRENT_LAZY(*now);
 
 		/* compute latency & lag */
 		latency = INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled;
@@ -5809,7 +5776,7 @@ threadRun(void *arg)
 
 	if (!is_connect)
 	{
-		/* make connections to the database */
+		/* make connections to the database before starting */
 		for (i = 0; i < nstate; i++)
 		{
 			if ((state[i].con = doConnect()) == NULL)
@@ -5845,14 +5812,7 @@ threadRun(void *arg)
 		{
 			CState	   *st = &state[i];
 
-			if (st->state == CSTATE_THROTTLE && timer_exceeded)
-			{
-				/* interrupt client that has not started a transaction */
-				st->state = CSTATE_FINISHED;
-				finishCon(st);
-				remains--;
-			}
-			else if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
+			if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
 			{
 				/* a nap from the script, or under throttling */
 				int64		this_usec;
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f968444671..53d9699015 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -20,6 +20,8 @@
  *
  * INSTR_TIME_SET_CURRENT(t)		set t to current time
  *
+ * INSTR_TIME_SET_CURRENT_LAZY(t)	set t to current time if t is zero
+ *
  * INSTR_TIME_ADD(x, y)				x += y
  *
  * INSTR_TIME_SUBTRACT(x, y)		x -= y
@@ -245,4 +247,11 @@ GetTimerFrequency(void)
 
 #endif							/* WIN32 */
 
+
+#define INSTR_TIME_SET_CURRENT_LAZY(t) \
+	do { \
+		if (INSTR_TIME_IS_ZERO(t)) \
+			INSTR_TIME_SET_CURRENT(t); \
+	} while (0)
+
 #endif							/* INSTR_TIME_H */
#6Fabien COELHO
coelho@cri.ensmp.fr
In reply to: Alvaro Herrera (#5)
1 attachment(s)
Re: pgbench - doCustom cleanup

Hello Alvaro,

Thanks for the review and improvements.

Attached v4 is a rebase after 409231919443984635b7ae9b7e2e261ab984eb1e

Attached v5. I thought that separating the part that executes the
command was an obvious readability improvement.

Hmm. It is somehow, but the aim of the refactoring is to make *ALL* state
transitions to happen in doCustom's switch (st->state) and nowhere else,
which is defeated by creating the separate function.

Although it improves readability at one level, it does not help figuring
out what happens to states, which is my primary concern: The idea is that
reading doCustom is enough to build and check the automaton, which I had
to do repeatedly while reviewing Marina's patches.

Also the added doCustom comment, which announces this property becomes
false under the refactoring function:

All state changes are performed within this function called by threadRun.

So I would suggest not to create this function.

Do we really use the word "move" to talk about state changes? It sounds
very odd to me. I would change that to "transition" -- would anybody
object to that? (Not changed in v5.)

Yep. I removed the goto:-)

On INSTR_TIME_SET_CURRENT_LAZY(), you cannot just put an "if" inside a
macro -- consider this:
if (foo)
INSTR_TIME_SET_CURRENT_LAZY(bar);
else
something_else();
Which "if" is the else now attached to? Now maybe the C standard has an
answer for that (I don't know what it is), but it's hard to read and
likely the compiler will complain anyway. I wrapped it in "do { }
while(0)" as is customary.

Indeed, good catch.

In the attached patched, I have I think included all your changes *but*
the separate function, for the reason discussed above, and removed the
"goto".

--
Fabien.

Attachments:

pgbench-state-change-6.patchtext/x-diff; name=pgbench-state-change-6.patchDownload
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 73d3de0677..82cbd20420 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -294,24 +294,32 @@ typedef enum
 {
 	/*
 	 * The client must first choose a script to execute.  Once chosen, it can
-	 * either be throttled (state CSTATE_START_THROTTLE under --rate) or start
-	 * right away (state CSTATE_START_TX).
+	 * either be throttled (state CSTATE_START_THROTTLE under --rate), start
+	 * right away (state CSTATE_START_TX) or not start at all if the timer was
+	 * exceeded (state CSTATE_FINISHED).
 	 */
 	CSTATE_CHOOSE_SCRIPT,
 
 	/*
 	 * In CSTATE_START_THROTTLE state, we calculate when to begin the next
 	 * transaction, and advance to CSTATE_THROTTLE.  CSTATE_THROTTLE state
-	 * sleeps until that moment.  (If throttling is not enabled, doCustom()
-	 * falls directly through from CSTATE_START_THROTTLE to CSTATE_START_TX.)
+	 * sleeps until that moment.
+	 *
+	 * It may also detect that the next transaction would start beyond the end
+	 * of run, and switch to CSTATE_FINISHED.
 	 */
 	CSTATE_START_THROTTLE,
 	CSTATE_THROTTLE,
 
 	/*
 	 * CSTATE_START_TX performs start-of-transaction processing.  Establishes
-	 * a new connection for the transaction, in --connect mode, and records
-	 * the transaction start time.
+	 * a new connection for the transaction in --connect mode, records
+	 * the transaction start time, and proceed to the first command.
+	 *
+	 * Note: once a script is started, it will either error or run till
+	 * its end, where it may be interrupted. It is not interrupted while
+	 * running, so pgbench --time is to be understood as tx are allowed to
+	 * start in that time, and will finish when their work is completed.
 	 */
 	CSTATE_START_TX,
 
@@ -324,9 +332,6 @@ typedef enum
 	 * and we enter the CSTATE_SLEEP state to wait for it to expire. Other
 	 * meta-commands are executed immediately.
 	 *
-	 * CSTATE_SKIP_COMMAND for conditional branches which are not executed,
-	 * quickly skip commands that do not need any evaluation.
-	 *
 	 * CSTATE_WAIT_RESULT waits until we get a result set back from the server
 	 * for the current command.
 	 *
@@ -334,19 +339,25 @@ typedef enum
 	 *
 	 * CSTATE_END_COMMAND records the end-of-command timestamp, increments the
 	 * command counter, and loops back to CSTATE_START_COMMAND state.
+	 *
+	 * CSTATE_SKIP_COMMAND is used by conditional branches which are not
+	 * executed. It quickly skip commands that do not need any evaluation.
+	 * This state can move forward several commands, till there is something
+	 * to do or the end of the script.
 	 */
 	CSTATE_START_COMMAND,
-	CSTATE_SKIP_COMMAND,
 	CSTATE_WAIT_RESULT,
 	CSTATE_SLEEP,
 	CSTATE_END_COMMAND,
+	CSTATE_SKIP_COMMAND,
 
 	/*
-	 * 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
-	 * in CSTATE_START_THROTTLE state, or enters CSTATE_FINISHED if we have no
-	 * more work to do.
+	 * CSTATE_END_TX performs end-of-transaction processing.  It calculates
+	 * latency, and logs the transaction.  In --connect mode, it closes the
+	 * current connection.
+	 *
+	 * Then either starts over in CSTATE_CHOOSE_SCRIPT, or enters CSTATE_FINISHED
+	 * if we have no more work to do.
 	 */
 	CSTATE_END_TX,
 
@@ -2821,16 +2832,12 @@ evaluateSleep(CState *st, int argc, char **argv, int *usecs)
 
 /*
  * Advance the state machine of a connection, if possible.
+ *
+ * All state changes are performed within this function called by threadRun.
  */
 static void
 doCustom(TState *thread, CState *st, StatsData *agg)
 {
-	PGresult   *res;
-	Command    *command;
-	instr_time	now;
-	bool		end_tx_processed = false;
-	int64		wait;
-
 	/*
 	 * gettimeofday() isn't free, so we get the current timestamp lazily the
 	 * first time it's needed, and reuse the same value throughout this
@@ -2839,37 +2846,44 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 	 * means "not set yet".  Reset "now" when we execute shell commands or
 	 * expressions, which might take a non-negligible amount of time, though.
 	 */
+	instr_time	now;
 	INSTR_TIME_SET_ZERO(now);
 
 	/*
 	 * Loop in the state machine, until we have to wait for a result from the
-	 * server (or have to sleep, for throttling or for \sleep).
+	 * server or have to sleep for throttling or \sleep.
 	 *
 	 * Note: In the switch-statement below, 'break' will loop back here,
 	 * meaning "continue in the state machine".  Return is used to return to
-	 * the caller.
+	 * the caller, giving the thread the opportunity to advance another client.
 	 */
 	for (;;)
 	{
+		PGresult   *res;
+		Command    *command;
+
 		switch (st->state)
 		{
 				/*
 				 * Select transaction to run.
 				 */
 			case CSTATE_CHOOSE_SCRIPT:
-
 				st->use_file = chooseScript(thread);
 
 				if (debug)
 					fprintf(stderr, "client %d executing script \"%s\"\n", st->id,
 							sql_script[st->use_file].desc);
 
-				if (throttle_delay > 0)
+				/* check stack consistency */
+				Assert(conditional_stack_empty(st->cstack));
+
+				if (timer_exceeded)
+					st->state = CSTATE_FINISHED;
+				else if (throttle_delay > 0)
 					st->state = CSTATE_START_THROTTLE;
 				else
 					st->state = CSTATE_START_TX;
-				/* check consistency */
-				Assert(conditional_stack_empty(st->cstack));
+
 				break;
 
 				/*
@@ -2887,21 +2901,10 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * away.
 				 */
 				Assert(throttle_delay > 0);
-				wait = getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
 
-				thread->throttle_trigger += wait;
+				thread->throttle_trigger += getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
 				st->txn_scheduled = thread->throttle_trigger;
 
-				/*
-				 * stop client if next transaction is beyond pgbench end of
-				 * execution
-				 */
-				if (duration > 0 && st->txn_scheduled > end_time)
-				{
-					st->state = CSTATE_FINISHED;
-					break;
-				}
-
 				/*
 				 * If --latency-limit is used, and this slot is already late
 				 * so that the transaction will miss the latency limit even if
@@ -2913,20 +2916,20 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				{
 					int64		now_us;
 
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					now_us = INSTR_TIME_GET_MICROSEC(now);
+
 					while (thread->throttle_trigger < now_us - latency_limit &&
 						   (nxacts <= 0 || st->cnt < nxacts))
 					{
 						processXactStats(thread, st, &now, true, agg);
 						/* next rendez-vous */
-						wait = getPoissonRand(&thread->ts_throttle_rs,
-											  throttle_delay);
-						thread->throttle_trigger += wait;
+						thread->throttle_trigger +=
+							getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
 						st->txn_scheduled = thread->throttle_trigger;
 					}
-					/* stop client if -t exceeded */
+
+					/* stop client if -t was exceeded in the previous skip loop */
 					if (nxacts > 0 && st->cnt >= nxacts)
 					{
 						st->state = CSTATE_FINISHED;
@@ -2934,38 +2937,42 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 				}
 
+				/*
+				 * stop client if next transaction is beyond pgbench end of
+				 * execution.
+				 */
+				if (duration > 0 && st->txn_scheduled > end_time)
+				{
+					st->state = CSTATE_FINISHED;
+					break;
+				}
+
 				st->state = CSTATE_THROTTLE;
-				if (debug)
-					fprintf(stderr, "client %d throttling " INT64_FORMAT " us\n",
-							st->id, wait);
 				break;
 
 				/*
 				 * Wait until it's time to start next transaction.
 				 */
 			case CSTATE_THROTTLE:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
+
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+
 				if (INSTR_TIME_GET_MICROSEC(now) < st->txn_scheduled)
-					return;		/* Still sleeping, nothing to do here */
+					return;		/* still sleeping, nothing to do here */
 
-				/* Else done sleeping, start the transaction */
-				st->state = CSTATE_START_TX;
+				/* done sleeping, but do not start transaction if we are done */
+				st->state = timer_exceeded ? CSTATE_FINISHED : CSTATE_START_TX;
 				break;
 
 				/* Start new transaction */
 			case CSTATE_START_TX:
 
-				/*
-				 * Establish connection on first call, or if is_connect is
-				 * true.
-				 */
+				/* establish connection if needed, i.e. under --connect */
 				if (st->con == NULL)
 				{
 					instr_time	start;
 
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					start = now;
 					if ((st->con = doConnect()) == NULL)
 					{
@@ -2981,28 +2988,20 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					memset(st->prepared, 0, sizeof(st->prepared));
 				}
 
+				/* record transaction start time.  */
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+				st->txn_begin = now;
+
 				/*
-				 * Record transaction start time under logging, progress or
-				 * throttling.
+				 * When not throttling, this is also the transaction's
+				 * scheduled start time.
 				 */
-				if (use_log || progress || throttle_delay || latency_limit ||
-					per_script_stats)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
-					st->txn_begin = now;
-
-					/*
-					 * When not throttling, this is also the transaction's
-					 * scheduled start time.
-					 */
-					if (!throttle_delay)
-						st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
-				}
+				if (!throttle_delay)
+					st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
 
 				/* Begin with the first command */
-				st->command = 0;
 				st->state = CSTATE_START_COMMAND;
+				st->command = 0;
 				break;
 
 				/*
@@ -3021,17 +3020,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					break;
 				}
 
-				/*
-				 * Record statement start time if per-command latencies are
-				 * requested
-				 */
-				if (is_latencies)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
-					st->stmt_begin = now;
-				}
+				/* record statement start time. */
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+				st->stmt_begin = now;
 
+				/* execute the command */
 				if (command->type == SQL_COMMAND)
 				{
 					if (!sendCommand(st, command))
@@ -3074,8 +3067,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 							break;
 						}
 
-						if (INSTR_TIME_IS_ZERO(now))
-							INSTR_TIME_SET_CURRENT(now);
+						INSTR_TIME_SET_CURRENT_LAZY(now);
+
 						st->sleep_until = INSTR_TIME_GET_MICROSEC(now) + usec;
 						st->state = CSTATE_SLEEP;
 						break;
@@ -3093,10 +3086,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 						{
 							/*
 							 * elif after executed block, skip eval and wait
-							 * for endif
+							 * for endif. This is a shortcut.
 							 */
 							conditional_stack_poke(st->cstack, IFSTATE_IGNORED);
-							goto move_to_end_command;
+							st->state = CSTATE_END_COMMAND;
+							break;
 						}
 
 						if (!evaluateExpr(thread, st, expr, &result))
@@ -3126,10 +3120,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 							}
 							else	/* elif */
 							{
-								/*
-								 * we should get here only if the "elif"
-								 * needed evaluation
-								 */
+								/* we should get here only if the "elif" needed evaluation */
 								Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
 								conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
 							}
@@ -3151,56 +3142,33 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 								/* dead code if conditional check is ok */
 								Assert(false);
 						}
-						goto move_to_end_command;
 					}
 					else if (command->meta == META_ENDIF)
 					{
 						Assert(!conditional_stack_empty(st->cstack));
 						conditional_stack_pop(st->cstack);
-						goto move_to_end_command;
 					}
 					else if (command->meta == META_SETSHELL)
 					{
-						bool		ret = runShellCommand(st, argv[1], argv + 2, argc - 2);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
+						if (!runShellCommand(st, argv[1], argv + 2, argc - 2))
 						{
 							commandFailed(st, "setshell", "execution of meta-command failed");
 							st->state = CSTATE_ABORTED;
 							break;
 						}
-						else
-						{
-							/* succeeded */
-						}
+						/* else success */
 					}
 					else if (command->meta == META_SHELL)
 					{
-						bool		ret = runShellCommand(st, NULL, argv + 1, argc - 1);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
+						if (!runShellCommand(st, NULL, argv + 1, argc - 1))
 						{
 							commandFailed(st, "shell", "execution of meta-command failed");
 							st->state = CSTATE_ABORTED;
 							break;
 						}
-						else
-						{
-							/* succeeded */
-						}
+						/* else success */
 					}
-
-			move_to_end_command:
+					/* else nothing: all meta commands have been managed */
 
 					/*
 					 * executing the expression or shell command might take a
@@ -3299,6 +3267,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 
 					if (st->state != CSTATE_SKIP_COMMAND)
+						/* out of quick skip command loop */
 						break;
 				}
 				break;
@@ -3348,10 +3317,9 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * instead of CSTATE_START_TX.
 				 */
 			case CSTATE_SLEEP:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
 				if (INSTR_TIME_GET_MICROSEC(now) < st->sleep_until)
-					return;		/* Still sleeping, nothing to do here */
+					return;		/* still sleeping, nothing to do here */
 				/* Else done sleeping. */
 				st->state = CSTATE_END_COMMAND;
 				break;
@@ -3366,17 +3334,13 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * in thread-local data structure, if per-command latencies
 				 * are requested.
 				 */
-				if (is_latencies)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
 
-					/* XXX could use a mutex here, but we choose not to */
-					command = sql_script[st->use_file].commands[st->command];
-					addToSimpleStats(&command->stats,
-									 INSTR_TIME_GET_DOUBLE(now) -
-									 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
-				}
+				/* XXX could use a mutex here, but we choose not to */
+				command = sql_script[st->use_file].commands[st->command];
+				addToSimpleStats(&command->stats,
+								 INSTR_TIME_GET_DOUBLE(now) -
+								 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
 
 				/* Go ahead with next command, to be executed or skipped */
 				st->command++;
@@ -3385,19 +3349,15 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				break;
 
 				/*
-				 * End of transaction.
+				 * End of transaction (end of script, really).
 				 */
 			case CSTATE_END_TX:
 
 				/* transaction finished: calculate latency and do log */
 				processXactStats(thread, st, &now, false, 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);
-				}
+				/* missing \endif... cannot happen if CheckConditional was okay */
+				Assert(conditional_stack_empty(st->cstack));
 
 				if (is_connect)
 				{
@@ -3411,26 +3371,17 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					st->state = CSTATE_FINISHED;
 					break;
 				}
+				else
+				{
+					/* next transaction */
+					st->state = CSTATE_CHOOSE_SCRIPT;
 
-				/*
-				 * No transaction is underway anymore.
-				 */
-				st->state = CSTATE_CHOOSE_SCRIPT;
-
-				/*
-				 * If we paced through all commands in the script in this
-				 * loop, without returning to the caller even once, do it now.
-				 * This gives the thread a chance to process other
-				 * connections, and to do progress reporting.  This can
-				 * currently only happen if the script consists entirely of
-				 * meta-commands.
-				 */
-				if (end_tx_processed)
+					/*
+					 * Ensure that we always return on this point, so as
+					 * to avoid an infinite loop if the script only contains
+					 * meta commands.
+					 */
 					return;
-				else
-				{
-					end_tx_processed = true;
-					break;
 				}
 
 				/*
@@ -3544,8 +3495,7 @@ processXactStats(TState *thread, CState *st, instr_time *now,
 
 	if (detailed && !skipped)
 	{
-		if (INSTR_TIME_IS_ZERO(*now))
-			INSTR_TIME_SET_CURRENT(*now);
+		INSTR_TIME_SET_CURRENT_LAZY(*now);
 
 		/* compute latency & lag */
 		latency = INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled;
@@ -5809,7 +5759,7 @@ threadRun(void *arg)
 
 	if (!is_connect)
 	{
-		/* make connections to the database */
+		/* make connections to the database before starting */
 		for (i = 0; i < nstate; i++)
 		{
 			if ((state[i].con = doConnect()) == NULL)
@@ -5845,14 +5795,7 @@ threadRun(void *arg)
 		{
 			CState	   *st = &state[i];
 
-			if (st->state == CSTATE_THROTTLE && timer_exceeded)
-			{
-				/* interrupt client that has not started a transaction */
-				st->state = CSTATE_FINISHED;
-				finishCon(st);
-				remains--;
-			}
-			else if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
+			if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
 			{
 				/* a nap from the script, or under throttling */
 				int64		this_usec;
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f968444671..db271c2822 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -20,6 +20,8 @@
  *
  * INSTR_TIME_SET_CURRENT(t)		set t to current time
  *
+ * INSTR_TIME_SET_CURRENT_LAZY(t)	set t to current time if t is zero
+ *
  * INSTR_TIME_ADD(x, y)				x += y
  *
  * INSTR_TIME_SUBTRACT(x, y)		x -= y
@@ -245,4 +247,12 @@ GetTimerFrequency(void)
 
 #endif							/* WIN32 */
 
+/* same macro on all platforms */
+
+#define INSTR_TIME_SET_CURRENT_LAZY(t) \
+	do { \
+		if (INSTR_TIME_IS_ZERO(t)) \
+			INSTR_TIME_SET_CURRENT(t); \
+	} while (0)
+
 #endif							/* INSTR_TIME_H */
#7Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Fabien COELHO (#6)
Re: pgbench - doCustom cleanup

On 2018-Nov-20, Fabien COELHO wrote:

Hmm. It is somehow, but the aim of the refactoring is to make *ALL* state
transitions to happen in doCustom's switch (st->state) and nowhere else,
which is defeated by creating the separate function.

Although it improves readability at one level, it does not help figuring out
what happens to states, which is my primary concern: The idea is that
reading doCustom is enough to build and check the automaton, which I had to
do repeatedly while reviewing Marina's patches.

Yeah, there are conflicting goals here.

I didn't quite understand this hunk. Why does it remove the
is_latencies conditional? (The preceding comment shown here should be
updated obviously if this change is correct, but I'm not sure it is.)

@@ -3364,42 +3334,34 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				/*
 				 * command completed: accumulate per-command execution times
 				 * in thread-local data structure, if per-command latencies
 				 * are requested.
 				 */
-				if (is_latencies)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
-					/* XXX could use a mutex here, but we choose not to */
-					command = sql_script[st->use_file].commands[st->command];
-					addToSimpleStats(&command->stats,
-									 INSTR_TIME_GET_DOUBLE(now) -
-									 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
-				}
+				/* XXX could use a mutex here, but we choose not to */
+				command = sql_script[st->use_file].commands[st->command];
+				addToSimpleStats(&command->stats,
+								 INSTR_TIME_GET_DOUBLE(now) -
+								 INSTR_TIME_GET_DOUBLE(st->stmt_begin));

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#8Fabien COELHO
coelho@cri.ensmp.fr
In reply to: Alvaro Herrera (#7)
Re: pgbench - doCustom cleanup

I didn't quite understand this hunk. Why does it remove the
is_latencies conditional? (The preceding comment shown here should be
updated obviously if this change is correct, but I'm not sure it is.)

Pgbench runs benches a collects performance data about it.

I simplified the code to always collect data, without trying to be clever
about cases where these data may not be useful so some collection can be
skipped.

Here the test avoids recording the statement start time, mostly a simple
assignment and then later another test avoids recording the stats in the
same case, which are mostly a few adds.

ISTM that this is over optimization and unlikely to be have any measurable
effects compared to the other tasks performed when executing commands, so
a simpler code is better.

--
Fabien.

#9Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Fabien COELHO (#8)
Re: pgbench - doCustom cleanup

On 2018-Nov-20, Fabien COELHO wrote:

I didn't quite understand this hunk. Why does it remove the
is_latencies conditional? (The preceding comment shown here should be
updated obviously if this change is correct, but I'm not sure it is.)

Pgbench runs benches a collects performance data about it.

I simplified the code to always collect data, without trying to be clever
about cases where these data may not be useful so some collection can be
skipped.

Here the test avoids recording the statement start time, mostly a simple
assignment and then later another test avoids recording the stats in the
same case, which are mostly a few adds.

ISTM that this is over optimization and unlikely to be have any measurable
effects compared to the other tasks performed when executing commands, so a
simpler code is better.

I don't think we're quite ready to buy this argument just yet.
See /messages/by-id/31856.1400021891@sss.pgh.pa.us

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#10Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Fabien COELHO (#6)
1 attachment(s)
Re: pgbench - doCustom cleanup

On 2018-Nov-20, Fabien COELHO wrote:

Hmm. It is somehow, but the aim of the refactoring is to make *ALL* state
transitions to happen in doCustom's switch (st->state) and nowhere else,
which is defeated by creating the separate function.

Although it improves readability at one level, it does not help figuring out
what happens to states, which is my primary concern: The idea is that
reading doCustom is enough to build and check the automaton, which I had to
do repeatedly while reviewing Marina's patches.

I adopted your patch, then while going over it I decided to go with my
separation proposal anyway, and re-did it.

Looking at the state of the code before this patch, I totally understand
that you want to get away from the current state of affairs. However, I
don't think my proposal makes matters worse; actually it makes them
better. Please give the code a honest look and think whether the
separation of machine state advances is really worse with my proposal.

I also renamed some things. doCustom() was a pretty bad name, as was
CSTATE_START_THROTTLE.

Also the added doCustom comment, which announces this property becomes false
under the refactoring function:

All state changes are performed within this function called by threadRun.

So I would suggest not to create this function.

I agree the state advances in threadRun were real messy.

Thanks for getting rid of the goto.

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Attachments:

pgbench-state-change-7.patchtext/x-diff; charset=us-asciiDownload
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 73d3de0677..710130b022 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -294,24 +294,32 @@ typedef enum
 {
 	/*
 	 * The client must first choose a script to execute.  Once chosen, it can
-	 * either be throttled (state CSTATE_START_THROTTLE under --rate) or start
-	 * right away (state CSTATE_START_TX).
+	 * either be throttled (state CSTATE_PREPARE_THROTTLE under --rate), start
+	 * right away (state CSTATE_START_TX) or not start at all if the timer was
+	 * exceeded (state CSTATE_FINISHED).
 	 */
 	CSTATE_CHOOSE_SCRIPT,
 
 	/*
-	 * In CSTATE_START_THROTTLE state, we calculate when to begin the next
+	 * In CSTATE_PREPARE_THROTTLE state, we calculate when to begin the next
 	 * transaction, and advance to CSTATE_THROTTLE.  CSTATE_THROTTLE state
-	 * sleeps until that moment.  (If throttling is not enabled, doCustom()
-	 * falls directly through from CSTATE_START_THROTTLE to CSTATE_START_TX.)
+	 * sleeps until that moment.
+	 *
+	 * It may also detect that the next transaction would start beyond the end
+	 * of run, and switch to CSTATE_FINISHED.
 	 */
-	CSTATE_START_THROTTLE,
+	CSTATE_PREPARE_THROTTLE,
 	CSTATE_THROTTLE,
 
 	/*
 	 * CSTATE_START_TX performs start-of-transaction processing.  Establishes
-	 * a new connection for the transaction, in --connect mode, and records
-	 * the transaction start time.
+	 * a new connection for the transaction in --connect mode, records the
+	 * transaction start time, and proceed to the first command.
+	 *
+	 * Note: once a script is started, it will either error or run till its
+	 * end, where it may be interrupted. It is not interrupted while running,
+	 * so pgbench --time is to be understood as tx are allowed to start in
+	 * that time, and will finish when their work is completed.
 	 */
 	CSTATE_START_TX,
 
@@ -324,9 +332,6 @@ typedef enum
 	 * and we enter the CSTATE_SLEEP state to wait for it to expire. Other
 	 * meta-commands are executed immediately.
 	 *
-	 * CSTATE_SKIP_COMMAND for conditional branches which are not executed,
-	 * quickly skip commands that do not need any evaluation.
-	 *
 	 * CSTATE_WAIT_RESULT waits until we get a result set back from the server
 	 * for the current command.
 	 *
@@ -334,19 +339,25 @@ typedef enum
 	 *
 	 * CSTATE_END_COMMAND records the end-of-command timestamp, increments the
 	 * command counter, and loops back to CSTATE_START_COMMAND state.
+	 *
+	 * CSTATE_SKIP_COMMAND is used by conditional branches which are not
+	 * executed. It quickly skip commands that do not need any evaluation.
+	 * This state can move forward several commands, till there is something
+	 * to do or the end of the script.
 	 */
 	CSTATE_START_COMMAND,
-	CSTATE_SKIP_COMMAND,
 	CSTATE_WAIT_RESULT,
 	CSTATE_SLEEP,
 	CSTATE_END_COMMAND,
+	CSTATE_SKIP_COMMAND,
 
 	/*
-	 * 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
-	 * in CSTATE_START_THROTTLE state, or enters CSTATE_FINISHED if we have no
-	 * more work to do.
+	 * CSTATE_END_TX performs end-of-transaction processing.  It calculates
+	 * latency, and logs the transaction.  In --connect mode, it closes the
+	 * current connection.
+	 *
+	 * Then either starts over in CSTATE_CHOOSE_SCRIPT, or enters
+	 * CSTATE_FINISHED if we have no more work to do.
 	 */
 	CSTATE_END_TX,
 
@@ -567,7 +578,10 @@ static void setNullValue(PgBenchValue *pv);
 static void setBoolValue(PgBenchValue *pv, bool bval);
 static void setIntValue(PgBenchValue *pv, int64 ival);
 static void setDoubleValue(PgBenchValue *pv, double dval);
-static bool evaluateExpr(TState *, CState *, PgBenchExpr *, PgBenchValue *);
+static bool evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr,
+			 PgBenchValue *retval);
+static instr_time doExecuteCommand(TState *thread, CState *st,
+				 instr_time now);
 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,
@@ -2820,16 +2834,12 @@ evaluateSleep(CState *st, int argc, char **argv, int *usecs)
 }
 
 /*
- * Advance the state machine of a connection, if possible.
+ * Advance the state machine of a connection.
  */
 static void
-doCustom(TState *thread, CState *st, StatsData *agg)
+advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 {
-	PGresult   *res;
-	Command    *command;
 	instr_time	now;
-	bool		end_tx_processed = false;
-	int64		wait;
 
 	/*
 	 * gettimeofday() isn't free, so we get the current timestamp lazily the
@@ -2843,129 +2853,45 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 
 	/*
 	 * Loop in the state machine, until we have to wait for a result from the
-	 * server (or have to sleep, for throttling or for \sleep).
+	 * server or have to sleep for throttling or \sleep.
 	 *
 	 * Note: In the switch-statement below, 'break' will loop back here,
 	 * meaning "continue in the state machine".  Return is used to return to
-	 * the caller.
+	 * the caller, giving the thread the opportunity to advance another
+	 * client.
 	 */
 	for (;;)
 	{
+		PGresult   *res;
+
 		switch (st->state)
 		{
-				/*
-				 * Select transaction to run.
-				 */
+				/* Select transaction (script) to run.  */
 			case CSTATE_CHOOSE_SCRIPT:
-
 				st->use_file = chooseScript(thread);
+				Assert(conditional_stack_empty(st->cstack));
 
 				if (debug)
 					fprintf(stderr, "client %d executing script \"%s\"\n", st->id,
 							sql_script[st->use_file].desc);
 
-				if (throttle_delay > 0)
-					st->state = CSTATE_START_THROTTLE;
-				else
-					st->state = CSTATE_START_TX;
-				/* check consistency */
-				Assert(conditional_stack_empty(st->cstack));
+				/*
+				 * If time is over, we're done; otherwise, get ready to start
+				 * a new transaction, or to get throttled if that's requested.
+				 */
+				st->state = timer_exceeded ? CSTATE_FINISHED :
+					throttle_delay > 0 ? CSTATE_PREPARE_THROTTLE : CSTATE_START_TX;
 				break;
 
-				/*
-				 * Handle throttling once per transaction by sleeping.
-				 */
-			case CSTATE_START_THROTTLE:
-
-				/*
-				 * Generate a delay such that the series of delays will
-				 * approximate a Poisson distribution centered on the
-				 * throttle_delay time.
-				 *
-				 * If transactions are too slow or a given wait is shorter
-				 * than a transaction, the next transaction will start right
-				 * away.
-				 */
-				Assert(throttle_delay > 0);
-				wait = getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
-
-				thread->throttle_trigger += wait;
-				st->txn_scheduled = thread->throttle_trigger;
-
-				/*
-				 * stop client if next transaction is beyond pgbench end of
-				 * execution
-				 */
-				if (duration > 0 && st->txn_scheduled > end_time)
-				{
-					st->state = CSTATE_FINISHED;
-					break;
-				}
-
-				/*
-				 * If --latency-limit is used, and this slot is already late
-				 * so that the transaction will miss the latency limit even if
-				 * it completed immediately, we skip this time slot and
-				 * iterate till the next slot that isn't late yet.  But don't
-				 * iterate beyond the -t limit, if one is given.
-				 */
-				if (latency_limit)
-				{
-					int64		now_us;
-
-					if (INSTR_TIME_IS_ZERO(now))
-						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))
-					{
-						processXactStats(thread, st, &now, true, agg);
-						/* next rendez-vous */
-						wait = getPoissonRand(&thread->ts_throttle_rs,
-											  throttle_delay);
-						thread->throttle_trigger += wait;
-						st->txn_scheduled = thread->throttle_trigger;
-					}
-					/* stop client if -t exceeded */
-					if (nxacts > 0 && st->cnt >= nxacts)
-					{
-						st->state = CSTATE_FINISHED;
-						break;
-					}
-				}
-
-				st->state = CSTATE_THROTTLE;
-				if (debug)
-					fprintf(stderr, "client %d throttling " INT64_FORMAT " us\n",
-							st->id, wait);
-				break;
-
-				/*
-				 * Wait until it's time to start next transaction.
-				 */
-			case CSTATE_THROTTLE:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
-				if (INSTR_TIME_GET_MICROSEC(now) < st->txn_scheduled)
-					return;		/* Still sleeping, nothing to do here */
-
-				/* Else done sleeping, start the transaction */
-				st->state = CSTATE_START_TX;
-				break;
-
-				/* Start new transaction */
+				/* Start new transaction (script) */
 			case CSTATE_START_TX:
 
-				/*
-				 * Establish connection on first call, or if is_connect is
-				 * true.
-				 */
+				/* establish connection if needed, i.e. under --connect */
 				if (st->con == NULL)
 				{
 					instr_time	start;
 
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					start = now;
 					if ((st->con = doConnect()) == NULL)
 					{
@@ -2981,235 +2907,126 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					memset(st->prepared, 0, sizeof(st->prepared));
 				}
 
-				/*
-				 * Record transaction start time under logging, progress or
-				 * throttling.
-				 */
-				if (use_log || progress || throttle_delay || latency_limit ||
-					per_script_stats)
-				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
-					st->txn_begin = now;
+				/* record transaction start time */
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+				st->txn_begin = now;
 
-					/*
-					 * When not throttling, this is also the transaction's
-					 * scheduled start time.
-					 */
-					if (!throttle_delay)
-						st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
-				}
+				/*
+				 * When not throttling, this is also the transaction's
+				 * scheduled start time.
+				 */
+				if (!throttle_delay)
+					st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
 
 				/* Begin with the first command */
-				st->command = 0;
 				st->state = CSTATE_START_COMMAND;
+				st->command = 0;
+				break;
+
+				/*
+				 * Handle throttling once per transaction by sleeping.
+				 */
+			case CSTATE_PREPARE_THROTTLE:
+
+				/*
+				 * Generate a delay such that the series of delays will
+				 * approximate a Poisson distribution centered on the
+				 * throttle_delay time.
+				 *
+				 * If transactions are too slow or a given wait is shorter
+				 * than a transaction, the next transaction will start right
+				 * away.
+				 */
+				Assert(throttle_delay > 0);
+
+				thread->throttle_trigger +=
+					getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
+				st->txn_scheduled = thread->throttle_trigger;
+
+				/*
+				 * If --latency-limit is used, and this slot is already late
+				 * so that the transaction will miss the latency limit even if
+				 * it completed immediately, skip this time slot and schedule
+				 * to continue running on the next slot that isn't late yet.
+				 * But don't iterate beyond the -t limit, if one is given.
+				 */
+				if (latency_limit)
+				{
+					int64		now_us;
+
+					INSTR_TIME_SET_CURRENT_LAZY(now);
+					now_us = INSTR_TIME_GET_MICROSEC(now);
+
+					while (thread->throttle_trigger < now_us - latency_limit &&
+						   (nxacts <= 0 || st->cnt < nxacts))
+					{
+						processXactStats(thread, st, &now, true, agg);
+						/* next rendez-vous */
+						thread->throttle_trigger +=
+							getPoissonRand(&thread->ts_throttle_rs, throttle_delay);
+						st->txn_scheduled = thread->throttle_trigger;
+					}
+
+					/*
+					 * stop client if -t was exceeded in the previous skip
+					 * loop
+					 */
+					if (nxacts > 0 && st->cnt >= nxacts)
+					{
+						st->state = CSTATE_FINISHED;
+						break;
+					}
+				}
+
+				/*
+				 * stop client if next transaction is beyond pgbench end of
+				 * execution; otherwise, throttle it.
+				 */
+				st->state = end_time > 0 && st->txn_scheduled > end_time ?
+					CSTATE_FINISHED : CSTATE_THROTTLE;
+				break;
+
+				/*
+				 * Wait until it's time to start next transaction.
+				 */
+			case CSTATE_THROTTLE:
+				INSTR_TIME_SET_CURRENT_LAZY(now);
+
+				if (INSTR_TIME_GET_MICROSEC(now) < st->txn_scheduled)
+					return;		/* still sleeping, nothing to do here */
+
+				/* done sleeping, but don't start transaction if we're done */
+				st->state = timer_exceeded ? CSTATE_FINISHED : CSTATE_START_TX;
 				break;
 
 				/*
 				 * Send a command to server (or execute a meta-command)
 				 */
 			case CSTATE_START_COMMAND:
-				command = sql_script[st->use_file].commands[st->command];
-
-				/*
-				 * If we reached the end of the script, move to end-of-xact
-				 * processing.
-				 */
-				if (command == NULL)
+				/* Transition to script end processing if done */
+				if (sql_script[st->use_file].commands[st->command] == NULL)
 				{
 					st->state = CSTATE_END_TX;
 					break;
 				}
 
-				/*
-				 * Record statement start time if per-command latencies are
-				 * requested
-				 */
+				/* record begin time of next command, and initiate it */
 				if (is_latencies)
 				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 					st->stmt_begin = now;
 				}
+				now = doExecuteCommand(thread, st, now);
 
-				if (command->type == SQL_COMMAND)
-				{
-					if (!sendCommand(st, command))
-					{
-						commandFailed(st, "SQL", "SQL command send failed");
-						st->state = CSTATE_ABORTED;
-					}
-					else
-						st->state = CSTATE_WAIT_RESULT;
-				}
-				else if (command->type == META_COMMAND)
-				{
-					int			argc = command->argc,
-								i;
-					char	  **argv = command->argv;
-
-					if (debug)
-					{
-						fprintf(stderr, "client %d executing \\%s", st->id, argv[0]);
-						for (i = 1; i < argc; i++)
-							fprintf(stderr, " %s", argv[i]);
-						fprintf(stderr, "\n");
-					}
-
-					if (command->meta == META_SLEEP)
-					{
-						/*
-						 * A \sleep doesn't execute anything, we just get the
-						 * delay from the argument, and enter the CSTATE_SLEEP
-						 * state.  (The per-command latency will be recorded
-						 * in CSTATE_SLEEP state, not here, after the delay
-						 * has elapsed.)
-						 */
-						int			usec;
-
-						if (!evaluateSleep(st, argc, argv, &usec))
-						{
-							commandFailed(st, "sleep", "execution of meta-command failed");
-							st->state = CSTATE_ABORTED;
-							break;
-						}
-
-						if (INSTR_TIME_IS_ZERO(now))
-							INSTR_TIME_SET_CURRENT(now);
-						st->sleep_until = INSTR_TIME_GET_MICROSEC(now) + usec;
-						st->state = CSTATE_SLEEP;
-						break;
-					}
-					else if (command->meta == META_SET ||
-							 command->meta == META_IF ||
-							 command->meta == META_ELIF)
-					{
-						/* backslash commands with an expression to evaluate */
-						PgBenchExpr *expr = command->expr;
-						PgBenchValue result;
-
-						if (command->meta == META_ELIF &&
-							conditional_stack_peek(st->cstack) == IFSTATE_TRUE)
-						{
-							/*
-							 * elif after executed block, skip eval and wait
-							 * for endif
-							 */
-							conditional_stack_poke(st->cstack, IFSTATE_IGNORED);
-							goto move_to_end_command;
-						}
-
-						if (!evaluateExpr(thread, st, expr, &result))
-						{
-							commandFailed(st, argv[0], "evaluation of meta-command failed");
-							st->state = CSTATE_ABORTED;
-							break;
-						}
-
-						if (command->meta == META_SET)
-						{
-							if (!putVariableValue(st, argv[0], argv[1], &result))
-							{
-								commandFailed(st, "set", "assignment of meta-command failed");
-								st->state = CSTATE_ABORTED;
-								break;
-							}
-						}
-						else	/* if and elif evaluated cases */
-						{
-							bool		cond = valueTruth(&result);
-
-							/* execute or not depending on evaluated condition */
-							if (command->meta == META_IF)
-							{
-								conditional_stack_push(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
-							}
-							else	/* elif */
-							{
-								/*
-								 * we should get here only if the "elif"
-								 * needed evaluation
-								 */
-								Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
-								conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
-							}
-						}
-					}
-					else if (command->meta == META_ELSE)
-					{
-						switch (conditional_stack_peek(st->cstack))
-						{
-							case IFSTATE_TRUE:
-								conditional_stack_poke(st->cstack, IFSTATE_ELSE_FALSE);
-								break;
-							case IFSTATE_FALSE: /* inconsistent if active */
-							case IFSTATE_IGNORED:	/* inconsistent if active */
-							case IFSTATE_NONE:	/* else without if */
-							case IFSTATE_ELSE_TRUE: /* else after else */
-							case IFSTATE_ELSE_FALSE:	/* else after else */
-							default:
-								/* dead code if conditional check is ok */
-								Assert(false);
-						}
-						goto move_to_end_command;
-					}
-					else if (command->meta == META_ENDIF)
-					{
-						Assert(!conditional_stack_empty(st->cstack));
-						conditional_stack_pop(st->cstack);
-						goto move_to_end_command;
-					}
-					else if (command->meta == META_SETSHELL)
-					{
-						bool		ret = runShellCommand(st, argv[1], argv + 2, argc - 2);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
-						{
-							commandFailed(st, "setshell", "execution of meta-command failed");
-							st->state = CSTATE_ABORTED;
-							break;
-						}
-						else
-						{
-							/* succeeded */
-						}
-					}
-					else if (command->meta == META_SHELL)
-					{
-						bool		ret = runShellCommand(st, NULL, argv + 1, argc - 1);
-
-						if (timer_exceeded) /* timeout */
-						{
-							st->state = CSTATE_FINISHED;
-							break;
-						}
-						else if (!ret)	/* on error */
-						{
-							commandFailed(st, "shell", "execution of meta-command failed");
-							st->state = CSTATE_ABORTED;
-							break;
-						}
-						else
-						{
-							/* succeeded */
-						}
-					}
-
-			move_to_end_command:
-
-					/*
-					 * executing the expression or shell command might take a
-					 * non-negligible amount of time, so reset 'now'
-					 */
-					INSTR_TIME_SET_ZERO(now);
-
-					st->state = CSTATE_END_COMMAND;
-				}
+				/*
+				 * We're now waiting for an SQL command to complete, or
+				 * finished processing a metacommand, or need to sleep, or
+				 * something bad happened.
+				 */
+				Assert(st->state == CSTATE_WAIT_RESULT ||
+					   st->state == CSTATE_END_COMMAND ||
+					   st->state == CSTATE_SLEEP ||
+					   st->state == CSTATE_ABORTED);
 				break;
 
 				/*
@@ -3220,6 +3037,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				/* quickly skip commands until something to do... */
 				while (true)
 				{
+					Command    *command;
+
 					command = sql_script[st->use_file].commands[st->command];
 
 					/* cannot reach end of script in that state */
@@ -3299,6 +3118,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					}
 
 					if (st->state != CSTATE_SKIP_COMMAND)
+						/* out of quick skip command loop */
 						break;
 				}
 				break;
@@ -3307,11 +3127,11 @@ 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];
 				if (debug)
 					fprintf(stderr, "client %d receiving\n", st->id);
 				if (!PQconsumeInput(st->con))
-				{				/* there's something wrong */
+				{
+					/* there's something wrong */
 					commandFailed(st, "SQL", "perhaps the backend died while processing");
 					st->state = CSTATE_ABORTED;
 					break;
@@ -3319,9 +3139,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				if (PQisBusy(st->con))
 					return;		/* don't have the whole result yet */
 
-				/*
-				 * Read and discard the query result;
-				 */
+				/* Read and discard the query result */
 				res = PQgetResult(st->con);
 				switch (PQresultStatus(res))
 				{
@@ -3348,10 +3166,9 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * instead of CSTATE_START_TX.
 				 */
 			case CSTATE_SLEEP:
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
+				INSTR_TIME_SET_CURRENT_LAZY(now);
 				if (INSTR_TIME_GET_MICROSEC(now) < st->sleep_until)
-					return;		/* Still sleeping, nothing to do here */
+					return;		/* still sleeping, nothing to do here */
 				/* Else done sleeping. */
 				st->state = CSTATE_END_COMMAND;
 				break;
@@ -3368,11 +3185,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 */
 				if (is_latencies)
 				{
-					if (INSTR_TIME_IS_ZERO(now))
-						INSTR_TIME_SET_CURRENT(now);
+					Command    *command = sql_script[st->use_file].commands[st->command];
+
+					INSTR_TIME_SET_CURRENT_LAZY(now);
 
 					/* XXX could use a mutex here, but we choose not to */
-					command = sql_script[st->use_file].commands[st->command];
 					addToSimpleStats(&command->stats,
 									 INSTR_TIME_GET_DOUBLE(now) -
 									 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
@@ -3385,19 +3202,18 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				break;
 
 				/*
-				 * End of transaction.
+				 * End of transaction (end of script, really).
 				 */
 			case CSTATE_END_TX:
 
 				/* transaction finished: calculate latency and do log */
 				processXactStats(thread, st, &now, false, 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);
-				}
+				/*
+				 * missing \endif... cannot happen if CheckConditional was
+				 * okay
+				 */
+				Assert(conditional_stack_empty(st->cstack));
 
 				if (is_connect)
 				{
@@ -3411,26 +3227,17 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					st->state = CSTATE_FINISHED;
 					break;
 				}
-
-				/*
-				 * No transaction is underway anymore.
-				 */
-				st->state = CSTATE_CHOOSE_SCRIPT;
-
-				/*
-				 * If we paced through all commands in the script in this
-				 * loop, without returning to the caller even once, do it now.
-				 * This gives the thread a chance to process other
-				 * connections, and to do progress reporting.  This can
-				 * currently only happen if the script consists entirely of
-				 * meta-commands.
-				 */
-				if (end_tx_processed)
-					return;
 				else
 				{
-					end_tx_processed = true;
-					break;
+					/* next transaction (script) */
+					st->state = CSTATE_CHOOSE_SCRIPT;
+
+					/*
+					 * Ensure that we always return on this point, so as to
+					 * avoid an infinite loop if the script only contains meta
+					 * commands.
+					 */
+					return;
 				}
 
 				/*
@@ -3445,6 +3252,182 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 }
 
 /*
+ * Subroutine for advanceConnectionState -- execute or initiate the current
+ * command, and transition to next state appropriately.
+ *
+ * Returns an updated timestamp from 'now', used to update 'now' at callsite.
+ */
+static instr_time
+doExecuteCommand(TState *thread, CState *st, instr_time now)
+{
+	Command    *command = sql_script[st->use_file].commands[st->command];
+
+	/* execute the command */
+	if (command->type == SQL_COMMAND)
+	{
+		if (!sendCommand(st, command))
+		{
+			commandFailed(st, "SQL", "SQL command send failed");
+			st->state = CSTATE_ABORTED;
+		}
+		else
+			st->state = CSTATE_WAIT_RESULT;
+	}
+	else if (command->type == META_COMMAND)
+	{
+		int			argc = command->argc;
+		char	  **argv = command->argv;
+
+		if (debug)
+		{
+			fprintf(stderr, "client %d executing \\%s",
+					st->id, argv[0]);
+			for (int i = 1; i < argc; i++)
+				fprintf(stderr, " %s", argv[i]);
+			fprintf(stderr, "\n");
+		}
+
+		if (command->meta == META_SLEEP)
+		{
+			int			usec;
+
+			/*
+			 * A \sleep doesn't execute anything, we just get the delay from
+			 * the argument, and enter the CSTATE_SLEEP state.  (The
+			 * per-command latency will be recorded in CSTATE_SLEEP state, not
+			 * here, after the delay has elapsed.)
+			 */
+			if (!evaluateSleep(st, argc, argv, &usec))
+			{
+				commandFailed(st, "sleep", "execution of meta-command failed");
+				st->state = CSTATE_ABORTED;
+				return now;
+			}
+
+			INSTR_TIME_SET_CURRENT_LAZY(now);
+
+			st->sleep_until = INSTR_TIME_GET_MICROSEC(now) + usec;
+			st->state = CSTATE_SLEEP;
+			return now;
+		}
+		else if (command->meta == META_SET)
+		{
+			PgBenchExpr *expr = command->expr;
+			PgBenchValue result;
+
+			if (!evaluateExpr(thread, st, expr, &result))
+			{
+				commandFailed(st, argv[0], "evaluation of meta-command failed");
+				st->state = CSTATE_ABORTED;
+				return now;
+			}
+
+			if (!putVariableValue(st, argv[0], argv[1], &result))
+			{
+				commandFailed(st, "set", "assignment of meta-command failed");
+				st->state = CSTATE_ABORTED;
+				return now;
+			}
+		}
+		else if (command->meta == META_IF)
+		{
+			/* backslash commands with an expression to evaluate */
+			PgBenchExpr *expr = command->expr;
+			PgBenchValue result;
+			bool		cond;
+
+			if (!evaluateExpr(thread, st, expr, &result))
+			{
+				commandFailed(st, argv[0], "evaluation of meta-command failed");
+				st->state = CSTATE_ABORTED;
+				return now;
+			}
+
+			cond = valueTruth(&result);
+			conditional_stack_push(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
+		}
+		else if (command->meta == META_ELIF)
+		{
+			/* backslash commands with an expression to evaluate */
+			PgBenchExpr *expr = command->expr;
+			PgBenchValue result;
+			bool		cond;
+
+			if (conditional_stack_peek(st->cstack) == IFSTATE_TRUE)
+			{
+				/*
+				 * elif after executed block, skip eval and wait for endif.
+				 */
+				conditional_stack_poke(st->cstack, IFSTATE_IGNORED);
+				st->state = CSTATE_END_COMMAND;
+				return now;
+			}
+
+			if (!evaluateExpr(thread, st, expr, &result))
+			{
+				commandFailed(st, argv[0], "evaluation of meta-command failed");
+				st->state = CSTATE_ABORTED;
+				return now;
+			}
+
+			cond = valueTruth(&result);
+			Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
+			conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
+		}
+		else if (command->meta == META_ELSE)
+		{
+			switch (conditional_stack_peek(st->cstack))
+			{
+				case IFSTATE_TRUE:
+					conditional_stack_poke(st->cstack, IFSTATE_ELSE_FALSE);
+					break;
+				case IFSTATE_FALSE: /* inconsistent if active */
+				case IFSTATE_IGNORED:	/* inconsistent if active */
+				case IFSTATE_NONE:	/* else without if */
+				case IFSTATE_ELSE_TRUE: /* else after else */
+				case IFSTATE_ELSE_FALSE:	/* else after else */
+				default:
+					/* dead code if conditional check is ok */
+					Assert(false);
+			}
+		}
+		else if (command->meta == META_ENDIF)
+		{
+			Assert(!conditional_stack_empty(st->cstack));
+			conditional_stack_pop(st->cstack);
+		}
+		else if (command->meta == META_SETSHELL)
+		{
+			if (!runShellCommand(st, argv[1], argv + 2, argc - 2))
+			{
+				commandFailed(st, "setshell", "execution of meta-command failed");
+				st->state = CSTATE_ABORTED;
+				return now;
+			}
+		}
+		else if (command->meta == META_SHELL)
+		{
+			if (!runShellCommand(st, NULL, argv + 1, argc - 1))
+			{
+				commandFailed(st, "shell", "execution of meta-command failed");
+				st->state = CSTATE_ABORTED;
+				return now;
+			}
+		}
+
+		/*
+		 * executing the expression or shell command might have taken a
+		 * non-negligible amount of time, so reset 'now'
+		 */
+		INSTR_TIME_SET_ZERO(now);
+
+		st->state = CSTATE_END_COMMAND;
+	}
+
+	return now;
+}
+
+/*
  * Print log entry after completing one transaction.
  *
  * We print Unix-epoch timestamps in the log, so that entries can be
@@ -3544,8 +3527,7 @@ processXactStats(TState *thread, CState *st, instr_time *now,
 
 	if (detailed && !skipped)
 	{
-		if (INSTR_TIME_IS_ZERO(*now))
-			INSTR_TIME_SET_CURRENT(*now);
+		INSTR_TIME_SET_CURRENT_LAZY(*now);
 
 		/* compute latency & lag */
 		latency = INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled;
@@ -5809,7 +5791,7 @@ threadRun(void *arg)
 
 	if (!is_connect)
 	{
-		/* make connections to the database */
+		/* make connections to the database before starting */
 		for (i = 0; i < nstate; i++)
 		{
 			if ((state[i].con = doConnect()) == NULL)
@@ -5845,14 +5827,7 @@ threadRun(void *arg)
 		{
 			CState	   *st = &state[i];
 
-			if (st->state == CSTATE_THROTTLE && timer_exceeded)
-			{
-				/* interrupt client that has not started a transaction */
-				st->state = CSTATE_FINISHED;
-				finishCon(st);
-				remains--;
-			}
-			else if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
+			if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
 			{
 				/* a nap from the script, or under throttling */
 				int64		this_usec;
@@ -5971,7 +5946,7 @@ threadRun(void *arg)
 
 			if (st->state == CSTATE_WAIT_RESULT)
 			{
-				/* don't call doCustom unless data is available */
+				/* don't call advanceConnectionState unless data is available */
 				int			sock = PQsocket(st->con);
 
 				if (sock < 0)
@@ -5991,9 +5966,12 @@ threadRun(void *arg)
 				continue;
 			}
 
-			doCustom(thread, st, &aggs);
+			advanceConnectionState(thread, st, &aggs);
 
-			/* If doCustom changed client to finished state, reduce remains */
+			/*
+			 * If advanceConnectionState changed client to finished state,
+			 * that's one less client that remains.
+			 */
 			if (st->state == CSTATE_FINISHED || st->state == CSTATE_ABORTED)
 				remains--;
 		}
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f968444671..db271c2822 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -20,6 +20,8 @@
  *
  * INSTR_TIME_SET_CURRENT(t)		set t to current time
  *
+ * INSTR_TIME_SET_CURRENT_LAZY(t)	set t to current time if t is zero
+ *
  * INSTR_TIME_ADD(x, y)				x += y
  *
  * INSTR_TIME_SUBTRACT(x, y)		x -= y
@@ -245,4 +247,12 @@ GetTimerFrequency(void)
 
 #endif							/* WIN32 */
 
+/* same macro on all platforms */
+
+#define INSTR_TIME_SET_CURRENT_LAZY(t) \
+	do { \
+		if (INSTR_TIME_IS_ZERO(t)) \
+			INSTR_TIME_SET_CURRENT(t); \
+	} while (0)
+
 #endif							/* INSTR_TIME_H */
#11Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Fabien COELHO (#6)
Re: pgbench - doCustom cleanup

On 2018-Nov-20, Fabien COELHO wrote:

On INSTR_TIME_SET_CURRENT_LAZY(), you cannot just put an "if" inside a
macro -- consider this:
if (foo)
INSTR_TIME_SET_CURRENT_LAZY(bar);
else
something_else();
Which "if" is the else now attached to? Now maybe the C standard has an
answer for that (I don't know what it is), but it's hard to read and
likely the compiler will complain anyway. I wrapped it in "do { }
while(0)" as is customary.

Indeed, good catch.

Actually, reviewing this bit again, I realized that it should be a
statement that evaluates to whether the change was made or not -- this
way, it can be used in one existing place. Pushed that way. (I
verified that InstrStartNode fails in the expected way if you call it
twice.)

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#12Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Alvaro Herrera (#10)
Re: pgbench - doCustom cleanup

I just pushed this. I hope not to have upset you too much with the
subroutine thing.

Thanks for the submission and Kirk for the review.

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#13Fabien COELHO
coelho@cri.ensmp.fr
In reply to: Alvaro Herrera (#12)
1 attachment(s)
Re: pgbench - doCustom cleanup

Hello Alvaro,

I just pushed this. I hope not to have upset you too much with the
subroutine thing.

Sorry for the feedback delay, my week was kind of overloaded…

Thanks for the push.

About the patch you committed, a post-commit review:

- the state and function renamings are indeed a good thing.

- I'm not fond of "now = func(..., now)", I'd have just passed a
reference.

- I'd put out the meta commands, but keep the SQL case and the state
assignment in the initial function, so that all state changes are in
one function… which was the initial aim of the submission.
Kind of a compromise:-)

See the attached followup patch which implements these suggestions. The
patch is quite small under "git diff -w", but larger because of the
reindentation as one "if" level is removed.

--
Fabien.

Attachments:

pgbench-state-change-followup-1.patchtext/x-diff; name=pgbench-state-change-followup-1.patchDownload
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index c64e16187a..7392cf8688 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -580,8 +580,7 @@ static void setIntValue(PgBenchValue *pv, int64 ival);
 static void setDoubleValue(PgBenchValue *pv, double dval);
 static bool evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr,
 			 PgBenchValue *retval);
-static instr_time doExecuteCommand(TState *thread, CState *st,
-				 instr_time now);
+static ConnectionStateEnum executeMetaCommand(TState *thread, CState *st, instr_time *now);
 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,
@@ -2862,6 +2861,7 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 	 */
 	for (;;)
 	{
+		Command	   *command;
 		PGresult   *res;
 
 		switch (st->state)
@@ -3003,8 +3003,10 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 				 * Send a command to server (or execute a meta-command)
 				 */
 			case CSTATE_START_COMMAND:
+				command = sql_script[st->use_file].commands[st->command];
+
 				/* Transition to script end processing if done */
-				if (sql_script[st->use_file].commands[st->command] == NULL)
+				if (command == NULL)
 				{
 					st->state = CSTATE_END_TX;
 					break;
@@ -3016,7 +3018,27 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 					INSTR_TIME_SET_CURRENT_LAZY(now);
 					st->stmt_begin = now;
 				}
-				now = doExecuteCommand(thread, st, now);
+
+				if (command->type == SQL_COMMAND)
+				{
+					if (!sendCommand(st, command))
+					{
+						commandFailed(st, "SQL", "SQL command send failed");
+						st->state = CSTATE_ABORTED;
+					}
+					else
+						st->state = CSTATE_WAIT_RESULT;
+				}
+				else if (command->type == META_COMMAND)
+				{
+					/*-----
+					 * Possible state changes when executing meta commands:
+					 * - on errors CSTATE_ABORTED
+					 * - on sleep CSTATE_SLEEP
+					 * - else CSTATE_END_COMMAND
+					 */
+					st->state = executeMetaCommand(thread, st, &now);
+				}
 
 				/*
 				 * We're now waiting for an SQL command to complete, or
@@ -3254,178 +3276,151 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 
 /*
  * Subroutine for advanceConnectionState -- execute or initiate the current
- * command, and transition to next state appropriately.
- *
- * Returns an updated timestamp from 'now', used to update 'now' at callsite.
+ * meta command, and return to next state appropriately.
  */
-static instr_time
-doExecuteCommand(TState *thread, CState *st, instr_time now)
+static ConnectionStateEnum
+executeMetaCommand(TState *thread, CState *st, instr_time *now)
 {
 	Command    *command = sql_script[st->use_file].commands[st->command];
+	int			argc;
+	char	  **argv;
 
-	/* execute the command */
-	if (command->type == SQL_COMMAND)
+	Assert(command != NULL && command->type == META_COMMAND);
+
+	argc = command->argc;
+	argv = command->argv;
+
+	if (debug)
 	{
-		if (!sendCommand(st, command))
-		{
-			commandFailed(st, "SQL", "SQL command send failed");
-			st->state = CSTATE_ABORTED;
-		}
-		else
-			st->state = CSTATE_WAIT_RESULT;
+		fprintf(stderr, "client %d executing \\%s", st->id, argv[0]);
+		for (int i = 1; i < argc; i++)
+			fprintf(stderr, " %s", argv[i]);
+		fprintf(stderr, "\n");
 	}
-	else if (command->type == META_COMMAND)
+
+	if (command->meta == META_SLEEP)
 	{
-		int			argc = command->argc;
-		char	  **argv = command->argv;
-
-		if (debug)
-		{
-			fprintf(stderr, "client %d executing \\%s",
-					st->id, argv[0]);
-			for (int i = 1; i < argc; i++)
-				fprintf(stderr, " %s", argv[i]);
-			fprintf(stderr, "\n");
-		}
-
-		if (command->meta == META_SLEEP)
-		{
-			int			usec;
-
-			/*
-			 * A \sleep doesn't execute anything, we just get the delay from
-			 * the argument, and enter the CSTATE_SLEEP state.  (The
-			 * per-command latency will be recorded in CSTATE_SLEEP state, not
-			 * here, after the delay has elapsed.)
-			 */
-			if (!evaluateSleep(st, argc, argv, &usec))
-			{
-				commandFailed(st, "sleep", "execution of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-
-			INSTR_TIME_SET_CURRENT_LAZY(now);
-
-			st->sleep_until = INSTR_TIME_GET_MICROSEC(now) + usec;
-			st->state = CSTATE_SLEEP;
-			return now;
-		}
-		else if (command->meta == META_SET)
-		{
-			PgBenchExpr *expr = command->expr;
-			PgBenchValue result;
-
-			if (!evaluateExpr(thread, st, expr, &result))
-			{
-				commandFailed(st, argv[0], "evaluation of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-
-			if (!putVariableValue(st, argv[0], argv[1], &result))
-			{
-				commandFailed(st, "set", "assignment of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-		}
-		else if (command->meta == META_IF)
-		{
-			/* backslash commands with an expression to evaluate */
-			PgBenchExpr *expr = command->expr;
-			PgBenchValue result;
-			bool		cond;
-
-			if (!evaluateExpr(thread, st, expr, &result))
-			{
-				commandFailed(st, argv[0], "evaluation of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-
-			cond = valueTruth(&result);
-			conditional_stack_push(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
-		}
-		else if (command->meta == META_ELIF)
-		{
-			/* backslash commands with an expression to evaluate */
-			PgBenchExpr *expr = command->expr;
-			PgBenchValue result;
-			bool		cond;
-
-			if (conditional_stack_peek(st->cstack) == IFSTATE_TRUE)
-			{
-				/*
-				 * elif after executed block, skip eval and wait for endif.
-				 */
-				conditional_stack_poke(st->cstack, IFSTATE_IGNORED);
-				st->state = CSTATE_END_COMMAND;
-				return now;
-			}
-
-			if (!evaluateExpr(thread, st, expr, &result))
-			{
-				commandFailed(st, argv[0], "evaluation of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-
-			cond = valueTruth(&result);
-			Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
-			conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
-		}
-		else if (command->meta == META_ELSE)
-		{
-			switch (conditional_stack_peek(st->cstack))
-			{
-				case IFSTATE_TRUE:
-					conditional_stack_poke(st->cstack, IFSTATE_ELSE_FALSE);
-					break;
-				case IFSTATE_FALSE: /* inconsistent if active */
-				case IFSTATE_IGNORED:	/* inconsistent if active */
-				case IFSTATE_NONE:	/* else without if */
-				case IFSTATE_ELSE_TRUE: /* else after else */
-				case IFSTATE_ELSE_FALSE:	/* else after else */
-				default:
-					/* dead code if conditional check is ok */
-					Assert(false);
-			}
-		}
-		else if (command->meta == META_ENDIF)
-		{
-			Assert(!conditional_stack_empty(st->cstack));
-			conditional_stack_pop(st->cstack);
-		}
-		else if (command->meta == META_SETSHELL)
-		{
-			if (!runShellCommand(st, argv[1], argv + 2, argc - 2))
-			{
-				commandFailed(st, "setshell", "execution of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-		}
-		else if (command->meta == META_SHELL)
-		{
-			if (!runShellCommand(st, NULL, argv + 1, argc - 1))
-			{
-				commandFailed(st, "shell", "execution of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-		}
+		int			usec;
 
 		/*
-		 * executing the expression or shell command might have taken a
-		 * non-negligible amount of time, so reset 'now'
+		 * A \sleep doesn't execute anything, we just get the delay from
+		 * the argument, and enter the CSTATE_SLEEP state.  (The
+		 * per-command latency will be recorded in CSTATE_SLEEP state, not
+		 * here, after the delay has elapsed.)
 		 */
-		INSTR_TIME_SET_ZERO(now);
+		if (!evaluateSleep(st, argc, argv, &usec))
+		{
+			commandFailed(st, "sleep", "execution of meta-command failed");
+			return CSTATE_ABORTED;
+		}
 
-		st->state = CSTATE_END_COMMAND;
+		INSTR_TIME_SET_CURRENT_LAZY(*now);
+		st->sleep_until = INSTR_TIME_GET_MICROSEC(*now) + usec;
+		return CSTATE_SLEEP;
 	}
+	else if (command->meta == META_SET)
+	{
+		PgBenchExpr *expr = command->expr;
+		PgBenchValue result;
 
-	return now;
+		if (!evaluateExpr(thread, st, expr, &result))
+		{
+			commandFailed(st, argv[0], "evaluation of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+
+		if (!putVariableValue(st, argv[0], argv[1], &result))
+		{
+			commandFailed(st, "set", "assignment of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+	}
+	else if (command->meta == META_IF)
+	{
+		/* backslash commands with an expression to evaluate */
+		PgBenchExpr *expr = command->expr;
+		PgBenchValue result;
+		bool		cond;
+
+		if (!evaluateExpr(thread, st, expr, &result))
+		{
+			commandFailed(st, argv[0], "evaluation of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+
+		cond = valueTruth(&result);
+		conditional_stack_push(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
+	}
+	else if (command->meta == META_ELIF)
+	{
+		/* backslash commands with an expression to evaluate */
+		PgBenchExpr *expr = command->expr;
+		PgBenchValue result;
+		bool		cond;
+
+		if (conditional_stack_peek(st->cstack) == IFSTATE_TRUE)
+		{
+			/* elif after executed block, skip eval and wait for endif. */
+			conditional_stack_poke(st->cstack, IFSTATE_IGNORED);
+			return CSTATE_END_COMMAND;
+		}
+
+		if (!evaluateExpr(thread, st, expr, &result))
+		{
+			commandFailed(st, argv[0], "evaluation of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+
+		cond = valueTruth(&result);
+		Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
+		conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
+	}
+	else if (command->meta == META_ELSE)
+	{
+		switch (conditional_stack_peek(st->cstack))
+		{
+			case IFSTATE_TRUE:
+				conditional_stack_poke(st->cstack, IFSTATE_ELSE_FALSE);
+				break;
+			case IFSTATE_FALSE: /* inconsistent if active */
+			case IFSTATE_IGNORED:	/* inconsistent if active */
+			case IFSTATE_NONE:	/* else without if */
+			case IFSTATE_ELSE_TRUE: /* else after else */
+			case IFSTATE_ELSE_FALSE:	/* else after else */
+			default:
+				/* dead code if conditional check is ok */
+				Assert(false);
+		}
+	}
+	else if (command->meta == META_ENDIF)
+	{
+		Assert(!conditional_stack_empty(st->cstack));
+		conditional_stack_pop(st->cstack);
+	}
+	else if (command->meta == META_SETSHELL)
+	{
+		if (!runShellCommand(st, argv[1], argv + 2, argc - 2))
+		{
+			commandFailed(st, "setshell", "execution of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+	}
+	else if (command->meta == META_SHELL)
+	{
+		if (!runShellCommand(st, NULL, argv + 1, argc - 1))
+		{
+			commandFailed(st, "shell", "execution of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+	}
+
+	/*
+	 * executing the expression or shell command might have taken a
+	 * non-negligible amount of time, so reset 'now'
+	 */
+	INSTR_TIME_SET_ZERO(*now);
+
+	return CSTATE_END_COMMAND;
 }
 
 /*
#14Jamison, Kirk
k.jamison@jp.fujitsu.com
In reply to: Fabien COELHO (#13)
1 attachment(s)
RE: pgbench - doCustom cleanup

Hi Fabien and Alvaro,

I found that I have already reviewed this thread before,
so I tried to apply the patch, but part of the chunk failed,
because of the unused line below which was already removed in the
recent related commit.

PGResult *res;

I removed the line and fixed the other trailing whitespaces.
See the attached latest patch.
The attached patch applies, builds cleanly,
and passes the regression tests.

On Saturday, November 24, 2018 5:58PM (GMT+9), Fabien Coelho wrote:

About the patch you committed, a post-commit review:

- the state and function renamings are indeed a good thing.

- I'm not fond of "now = func(..., now)", I'd have just passed a
reference.

- I'd put out the meta commands, but keep the SQL case and the state
assignment in the initial function, so that all state changes are in
one function… which was the initial aim of the submission.
Kind of a compromise:-)

I have confirmed the following changes:

1.

- I'm not fond of "now = func(..., now)", I'd have just passed a
reference.

1.1. advanceConnectionState():
Removed > now = doExecuteCommand(thread, st, now);
1.2. executeMetaCommand(): direct reference to state
Before:

- st->state = CSTATE_ABORTED;
- return now;

After:

+ return CSTATE_ABORTED;

2. SQL_COMMAND type is executed in initial function advanceConnectionState(),
while META_COMMAND is executed in the subroutine executeMetaCommand().
This seems reasonable to me.

3. The function name also changed, which describes the subroutine better.
-static instr_time doExecuteCommand(TState *thread, CState *st,
-				 instr_time now);
+static ConnectionStateEnum executeMetaCommand(TState *thread, CState *st, instr_time *now);

No problems on my part as I find the changes logical.
This also needs a confirmation from Alvaro.

Regards,
Kirk Jamison

Attachments:

pgbench-state-change-followup-2.patchapplication/octet-stream; name=pgbench-state-change-followup-2.patchDownload
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 19532cf..c53ada6 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -607,8 +607,7 @@ static void setIntValue(PgBenchValue *pv, int64 ival);
 static void setDoubleValue(PgBenchValue *pv, double dval);
 static bool evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr,
 			 PgBenchValue *retval);
-static instr_time doExecuteCommand(TState *thread, CState *st,
-				 instr_time now);
+static ConnectionStateEnum executeMetaCommand(TState *thread, CState *st, instr_time *now);
 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,
@@ -3009,6 +3008,8 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 	 */
 	for (;;)
 	{
+		Command *command;
+
 		switch (st->state)
 		{
 				/* Select transaction (script) to run.  */
@@ -3148,8 +3149,10 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 				 * Send a command to server (or execute a meta-command)
 				 */
 			case CSTATE_START_COMMAND:
+				command = sql_script[st->use_file].commands[st->command];
+
 				/* Transition to script end processing if done */
-				if (sql_script[st->use_file].commands[st->command] == NULL)
+				if (command == NULL)
 				{
 					st->state = CSTATE_END_TX;
 					break;
@@ -3161,7 +3164,27 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 					INSTR_TIME_SET_CURRENT_LAZY(now);
 					st->stmt_begin = now;
 				}
-				now = doExecuteCommand(thread, st, now);
+
+				if (command->type == SQL_COMMAND)
+				{
+					if (!sendCommand(st, command))
+					{
+						commandFailed(st, "SQL", "SQL command send failed");
+						st->state = CSTATE_ABORTED;
+					}
+					else
+						st->state = CSTATE_WAIT_RESULT;
+				}
+				else if (command->type == META_COMMAND)
+				{
+					/*-----
+					 * Possible state changes when executing meta commands:
+					 * - on errors CSTATE_ABORTED
+					 * - on sleep CSTATE_SLEEP
+					 * - else CSTATE_END_COMMAND
+					 */
+					st->state = executeMetaCommand(thread, st, &now);
+				}
 
 				/*
 				 * We're now waiting for an SQL command to complete, or
@@ -3385,178 +3408,151 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 
 /*
  * Subroutine for advanceConnectionState -- execute or initiate the current
- * command, and transition to next state appropriately.
- *
- * Returns an updated timestamp from 'now', used to update 'now' at callsite.
+ * meta command, and return to next state appropriately.
  */
-static instr_time
-doExecuteCommand(TState *thread, CState *st, instr_time now)
+static ConnectionStateEnum
+executeMetaCommand(TState *thread, CState *st, instr_time *now)
 {
 	Command    *command = sql_script[st->use_file].commands[st->command];
+	int			argc;
+	char	  **argv;
 
-	/* execute the command */
-	if (command->type == SQL_COMMAND)
+	Assert(command != NULL && command->type == META_COMMAND);
+
+	argc = command->argc;
+	argv = command->argv;
+
+	if (debug)
 	{
-		if (!sendCommand(st, command))
-		{
-			commandFailed(st, "SQL", "SQL command send failed");
-			st->state = CSTATE_ABORTED;
-		}
-		else
-			st->state = CSTATE_WAIT_RESULT;
+		fprintf(stderr, "client %d executing \\%s", st->id, argv[0]);
+		for (int i = 1; i < argc; i++)
+			fprintf(stderr, " %s", argv[i]);
+		fprintf(stderr, "\n");
 	}
-	else if (command->type == META_COMMAND)
+
+	if (command->meta == META_SLEEP)
 	{
-		int			argc = command->argc;
-		char	  **argv = command->argv;
-
-		if (debug)
-		{
-			fprintf(stderr, "client %d executing \\%s",
-					st->id, argv[0]);
-			for (int i = 1; i < argc; i++)
-				fprintf(stderr, " %s", argv[i]);
-			fprintf(stderr, "\n");
-		}
-
-		if (command->meta == META_SLEEP)
-		{
-			int			usec;
-
-			/*
-			 * A \sleep doesn't execute anything, we just get the delay from
-			 * the argument, and enter the CSTATE_SLEEP state.  (The
-			 * per-command latency will be recorded in CSTATE_SLEEP state, not
-			 * here, after the delay has elapsed.)
-			 */
-			if (!evaluateSleep(st, argc, argv, &usec))
-			{
-				commandFailed(st, "sleep", "execution of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-
-			INSTR_TIME_SET_CURRENT_LAZY(now);
-
-			st->sleep_until = INSTR_TIME_GET_MICROSEC(now) + usec;
-			st->state = CSTATE_SLEEP;
-			return now;
-		}
-		else if (command->meta == META_SET)
-		{
-			PgBenchExpr *expr = command->expr;
-			PgBenchValue result;
-
-			if (!evaluateExpr(thread, st, expr, &result))
-			{
-				commandFailed(st, argv[0], "evaluation of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-
-			if (!putVariableValue(st, argv[0], argv[1], &result))
-			{
-				commandFailed(st, "set", "assignment of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-		}
-		else if (command->meta == META_IF)
-		{
-			/* backslash commands with an expression to evaluate */
-			PgBenchExpr *expr = command->expr;
-			PgBenchValue result;
-			bool		cond;
-
-			if (!evaluateExpr(thread, st, expr, &result))
-			{
-				commandFailed(st, argv[0], "evaluation of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-
-			cond = valueTruth(&result);
-			conditional_stack_push(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
-		}
-		else if (command->meta == META_ELIF)
-		{
-			/* backslash commands with an expression to evaluate */
-			PgBenchExpr *expr = command->expr;
-			PgBenchValue result;
-			bool		cond;
-
-			if (conditional_stack_peek(st->cstack) == IFSTATE_TRUE)
-			{
-				/*
-				 * elif after executed block, skip eval and wait for endif.
-				 */
-				conditional_stack_poke(st->cstack, IFSTATE_IGNORED);
-				st->state = CSTATE_END_COMMAND;
-				return now;
-			}
-
-			if (!evaluateExpr(thread, st, expr, &result))
-			{
-				commandFailed(st, argv[0], "evaluation of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-
-			cond = valueTruth(&result);
-			Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
-			conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
-		}
-		else if (command->meta == META_ELSE)
-		{
-			switch (conditional_stack_peek(st->cstack))
-			{
-				case IFSTATE_TRUE:
-					conditional_stack_poke(st->cstack, IFSTATE_ELSE_FALSE);
-					break;
-				case IFSTATE_FALSE: /* inconsistent if active */
-				case IFSTATE_IGNORED:	/* inconsistent if active */
-				case IFSTATE_NONE:	/* else without if */
-				case IFSTATE_ELSE_TRUE: /* else after else */
-				case IFSTATE_ELSE_FALSE:	/* else after else */
-				default:
-					/* dead code if conditional check is ok */
-					Assert(false);
-			}
-		}
-		else if (command->meta == META_ENDIF)
-		{
-			Assert(!conditional_stack_empty(st->cstack));
-			conditional_stack_pop(st->cstack);
-		}
-		else if (command->meta == META_SETSHELL)
-		{
-			if (!runShellCommand(st, argv[1], argv + 2, argc - 2))
-			{
-				commandFailed(st, "setshell", "execution of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-		}
-		else if (command->meta == META_SHELL)
-		{
-			if (!runShellCommand(st, NULL, argv + 1, argc - 1))
-			{
-				commandFailed(st, "shell", "execution of meta-command failed");
-				st->state = CSTATE_ABORTED;
-				return now;
-			}
-		}
+		int			usec;
 
 		/*
-		 * executing the expression or shell command might have taken a
-		 * non-negligible amount of time, so reset 'now'
+		 * A \sleep doesn't execute anything, we just get the delay from
+		 * the argument, and enter the CSTATE_SLEEP state.  (The
+		 * per-command latency will be recorded in CSTATE_SLEEP state, not
+		 * here, after the delay has elapsed.)
 		 */
-		INSTR_TIME_SET_ZERO(now);
+		if (!evaluateSleep(st, argc, argv, &usec))
+		{
+			commandFailed(st, "sleep", "execution of meta-command failed");
+			return CSTATE_ABORTED;
+		}
 
-		st->state = CSTATE_END_COMMAND;
+		INSTR_TIME_SET_CURRENT_LAZY(*now);
+		st->sleep_until = INSTR_TIME_GET_MICROSEC(*now) + usec;
+		return CSTATE_SLEEP;
 	}
+	else if (command->meta == META_SET)
+	{
+		PgBenchExpr *expr = command->expr;
+		PgBenchValue result;
 
-	return now;
+		if (!evaluateExpr(thread, st, expr, &result))
+		{
+			commandFailed(st, argv[0], "evaluation of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+
+		if (!putVariableValue(st, argv[0], argv[1], &result))
+		{
+			commandFailed(st, "set", "assignment of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+	}
+	else if (command->meta == META_IF)
+	{
+		/* backslash commands with an expression to evaluate */
+		PgBenchExpr *expr = command->expr;
+		PgBenchValue result;
+		bool		cond;
+
+		if (!evaluateExpr(thread, st, expr, &result))
+		{
+			commandFailed(st, argv[0], "evaluation of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+
+		cond = valueTruth(&result);
+		conditional_stack_push(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
+	}
+	else if (command->meta == META_ELIF)
+	{
+		/* backslash commands with an expression to evaluate */
+		PgBenchExpr *expr = command->expr;
+		PgBenchValue result;
+		bool		cond;
+
+		if (conditional_stack_peek(st->cstack) == IFSTATE_TRUE)
+		{
+			/* elif after executed block, skip eval and wait for endif. */
+			conditional_stack_poke(st->cstack, IFSTATE_IGNORED);
+			return CSTATE_END_COMMAND;
+		}
+
+		if (!evaluateExpr(thread, st, expr, &result))
+		{
+			commandFailed(st, argv[0], "evaluation of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+
+		cond = valueTruth(&result);
+		Assert(conditional_stack_peek(st->cstack) == IFSTATE_FALSE);
+		conditional_stack_poke(st->cstack, cond ? IFSTATE_TRUE : IFSTATE_FALSE);
+	}
+	else if (command->meta == META_ELSE)
+	{
+		switch (conditional_stack_peek(st->cstack))
+		{
+			case IFSTATE_TRUE:
+				conditional_stack_poke(st->cstack, IFSTATE_ELSE_FALSE);
+				break;
+			case IFSTATE_FALSE: /* inconsistent if active */
+			case IFSTATE_IGNORED:	/* inconsistent if active */
+			case IFSTATE_NONE:	/* else without if */
+			case IFSTATE_ELSE_TRUE: /* else after else */
+			case IFSTATE_ELSE_FALSE:	/* else after else */
+			default:
+				/* dead code if conditional check is ok */
+				Assert(false);
+		}
+	}
+	else if (command->meta == META_ENDIF)
+	{
+		Assert(!conditional_stack_empty(st->cstack));
+		conditional_stack_pop(st->cstack);
+	}
+	else if (command->meta == META_SETSHELL)
+	{
+		if (!runShellCommand(st, argv[1], argv + 2, argc - 2))
+		{
+			commandFailed(st, "setshell", "execution of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+	}
+	else if (command->meta == META_SHELL)
+	{
+		if (!runShellCommand(st, NULL, argv + 1, argc - 1))
+		{
+			commandFailed(st, "shell", "execution of meta-command failed");
+			return CSTATE_ABORTED;
+		}
+	}
+
+	/*
+	 * executing the expression or shell command might have taken a
+	 * non-negligible amount of time, so reset 'now'
+	 */
+	INSTR_TIME_SET_ZERO(*now);
+
+	return CSTATE_END_COMMAND;
 }
 
 /*
#15Fabien COELHO
coelho@cri.ensmp.fr
In reply to: Jamison, Kirk (#14)
RE: pgbench - doCustom cleanup

Hello Kirk,

so I tried to apply the patch, but part of the chunk failed,
because of the unused line below which was already removed in the
recent related commit.

PGResult *res;

I removed the line and fixed the other trailing whitespaces.

Indeed. Thanks for the fix.

See the attached latest patch.
The attached patch applies, builds cleanly,
and passes the regression tests.

[...]

No problems on my part as I find the changes logical.
This also needs a confirmation from Alvaro.

Ok.

You switched the patch to "waiting on author": What are you waiting from
me?

If you think that it is ok and that it should be considered by a
committer, probably Alvaro, it can be marked as "ready".

--
Fabien.

#16Jamison, Kirk
k.jamison@jp.fujitsu.com
In reply to: Fabien COELHO (#15)
RE: pgbench - doCustom cleanup

Hi Fabien,

See the attached latest patch.
The attached patch applies, builds cleanly, and passes the regression
tests.

No problems on my part as I find the changes logical.
This also needs a confirmation from Alvaro.

Ok.

You switched the patch to "waiting on author": What are you waiting from me?

If you think that it is ok and that it should be considered by a committer,
probably Alvaro, it can be marked as "ready".

Indeed, it was my mistake.
I have already marked it as "Ready for Committer".

Regards,
Kirk Jamison

#17Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Fabien COELHO (#15)
Re: pgbench - doCustom cleanup

Pushed, thanks.

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services