Hello Andres,

FWIW, leaving windows, error handling, and other annoyances aside, this
can be implemented fairly simply. See below.

Attached an attempt at improving things.

I've put 2 barriers: one so that all threads are up, one when all connections are setup and the bench is ready to go.

I've done a blind attempt at implementing the barrier stuff on windows.

I've changed the performance calculations depending on -C or not. Ramp-up effects are smoothed.

I've merged all time-related stuff (time_t, instr_time, int64) to use a unique type (pg_time_usec_t) and set of functions/macros, which simplifies the code somehow.

I've tried to do some variable renaming to distinguish timestamps and intervals.

This is work in progress.

--
Fabien.
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index b8864c6ae5..a16d9d49e1 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -113,18 +113,29 @@ typedef struct socket_set
  */
 
 #ifdef WIN32
+#define PTHREAD_BARRIER_SERIAL_THREAD (-1)
+
 /* Use native win32 threads on Windows */
 typedef struct win32_pthread *pthread_t;
 typedef int pthread_attr_t;
+typedef SYNCHRONIZATION_BARRIER pthread_barrier_t;
 
 static int	pthread_create(pthread_t *thread, pthread_attr_t *attr, void *(*start_routine) (void *), void *arg);
 static int	pthread_join(pthread_t th, void **thread_return);
+
+static int	pthread_barrier_init(pthread_barrier_t *barrier, void *unused, int nthreads);
+static int	pthread_barrier_wait(pthread_barrier_t *barrier);
+static int	pthread_barrier_destroy(pthread_barrier_t *barrier);
 #elif defined(ENABLE_THREAD_SAFETY)
 /* Use platform-dependent pthread capability */
 #include <pthread.h>
 #else
 /* No threads implementation, use none (-j 1) */
 #define pthread_t void *
+#define pthread_barrier_t void *
+#define pthread_barrier_init(a, b, c) /* ignore */
+#define pthread_barrier_wait(a) /* ignore */
+#define pthread_barrier_destroy(a) /* ignore */
 #endif
 
 
@@ -291,7 +302,7 @@ typedef struct SimpleStats
  */
 typedef struct StatsData
 {
-	time_t		start_time;		/* interval start time, for aggregates */
+	pg_time_usec_t	start_time;		/* interval start time, for aggregates */
 	int64		cnt;			/* number of transactions, including skipped */
 	int64		skipped;		/* number of transactions skipped under --rate
 								 * and --latency-limit */
@@ -310,6 +321,11 @@ typedef struct RandomState
 /* Various random sequences are initialized from this one. */
 static RandomState base_random_sequence;
 
+/* Thread synchronization barriers */
+static pthread_barrier_t
+	start_barrier,		/* all threads are started */
+	bench_barrier;		/* benchmarking ready to start */
+
 /*
  * Connection state machine states.
  */
@@ -417,10 +433,10 @@ typedef struct
 	bool		vars_sorted;	/* are variables sorted by name? */
 
 	/* various times about current transaction */
-	int64		txn_scheduled;	/* scheduled start time of transaction (usec) */
-	int64		sleep_until;	/* scheduled start time of next cmd (usec) */
-	instr_time	txn_begin;		/* used for measuring schedule lag times */
-	instr_time	stmt_begin;		/* used for measuring statement latencies */
+	pg_time_usec_t	txn_scheduled;	/* scheduled start time of transaction (usec) */
+	pg_time_usec_t	sleep_until;	/* scheduled start time of next cmd (usec) */
+	pg_time_usec_t	txn_begin;		/* used for measuring schedule lag times (usec) */
+	pg_time_usec_t	stmt_begin;		/* used for measuring statement latencies (usec) */
 
 	bool		prepared[MAX_SCRIPTS];	/* whether client prepared the script */
 
@@ -452,10 +468,13 @@ typedef struct
 	FILE	   *logfile;		/* where to log, or NULL */
 
 	/* per thread collected stats */
-	instr_time	start_time;		/* thread start time */
-	instr_time	conn_time;
+	pg_time_usec_t	start_time;		/* thread start (creation) time */
+	pg_time_usec_t	started_time;	/* thread is running after start barrier */
+	pg_time_usec_t	bench_start_time; 	/* thread is really benchmarking */
+	pg_time_usec_t	conn_delay;		/* cumulated connection and deconnection delays (usec) */
+
 	StatsData	stats;
-	int64		latency_late;	/* executed but late transactions */
+	int64		latency_late;	/* count executed but late transactions */
 } TState;
 
 #define INVALID_THREAD		((pthread_t) 0)
@@ -594,10 +613,10 @@ static void setIntValue(PgBenchValue *pv, int64 ival);
 static void setDoubleValue(PgBenchValue *pv, double dval);
 static bool evaluateExpr(CState *st, PgBenchExpr *expr,
 						 PgBenchValue *retval);
-static ConnectionStateEnum executeMetaCommand(CState *st, instr_time *now);
+static ConnectionStateEnum executeMetaCommand(CState *st, pg_time_usec_t *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,
+static void processXactStats(TState *thread, CState *st, pg_time_usec_t *now,
 							 bool skipped, StatsData *agg);
 static void append_fillfactor(char *opts, int len);
 static void addScript(ParsedScript script);
@@ -1102,9 +1121,9 @@ mergeSimpleStats(SimpleStats *acc, SimpleStats *ss)
  * the given value.
  */
 static void
-initStats(StatsData *sd, time_t start_time)
+initStats(StatsData *sd, pg_time_usec_t start)
 {
-	sd->start_time = start_time;
+	sd->start_time = start;
 	sd->cnt = 0;
 	sd->skipped = 0;
 	initSimpleStats(&sd->latency);
@@ -2857,7 +2876,6 @@ evaluateSleep(CState *st, int argc, char **argv, int *usecs)
 static void
 advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 {
-	instr_time	now;
 
 	/*
 	 * gettimeofday() isn't free, so we get the current timestamp lazily the
@@ -2867,7 +2885,7 @@ advanceConnectionState(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_SET_ZERO(now);
+	pg_time_usec_t	now = 0;
 
 	/*
 	 * Loop in the state machine, until we have to wait for a result from the
@@ -2902,29 +2920,30 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 
 				/* Start new transaction (script) */
 			case CSTATE_START_TX:
+				PG_TIME_SET_CURRENT_LAZY(now);
 
 				/* establish connection if needed, i.e. under --connect */
 				if (st->con == NULL)
 				{
-					instr_time	start;
+					pg_time_usec_t	start = now;
 
-					INSTR_TIME_SET_CURRENT_LAZY(now);
-					start = now;
 					if ((st->con = doConnect()) == NULL)
 					{
 						pg_log_error("client %d aborted while establishing connection", st->id);
 						st->state = CSTATE_ABORTED;
 						break;
 					}
-					INSTR_TIME_SET_CURRENT(now);
-					INSTR_TIME_ACCUM_DIFF(thread->conn_time, now, start);
+
+					/* reset now after connection */
+					now = pg_time_get_usec();
+
+					thread->conn_delay += now - start;
 
 					/* Reset session-local state */
 					memset(st->prepared, 0, sizeof(st->prepared));
 				}
 
 				/* record transaction start time */
-				INSTR_TIME_SET_CURRENT_LAZY(now);
 				st->txn_begin = now;
 
 				/*
@@ -2932,7 +2951,7 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 				 * scheduled start time.
 				 */
 				if (!throttle_delay)
-					st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
+					st->txn_scheduled = now;
 
 				/* Begin with the first command */
 				st->state = CSTATE_START_COMMAND;
@@ -2968,12 +2987,9 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 				 */
 				if (latency_limit)
 				{
-					int64		now_us;
+					PG_TIME_SET_CURRENT_LAZY(now);
 
-					INSTR_TIME_SET_CURRENT_LAZY(now);
-					now_us = INSTR_TIME_GET_MICROSEC(now);
-
-					while (thread->throttle_trigger < now_us - latency_limit &&
+					while (thread->throttle_trigger < now - latency_limit &&
 						   (nxacts <= 0 || st->cnt < nxacts))
 					{
 						processXactStats(thread, st, &now, true, agg);
@@ -3006,9 +3022,9 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 				 * Wait until it's time to start next transaction.
 				 */
 			case CSTATE_THROTTLE:
-				INSTR_TIME_SET_CURRENT_LAZY(now);
+				PG_TIME_SET_CURRENT_LAZY(now);
 
-				if (INSTR_TIME_GET_MICROSEC(now) < st->txn_scheduled)
+				if (now < st->txn_scheduled)
 					return;		/* still sleeping, nothing to do here */
 
 				/* done sleeping, but don't start transaction if we're done */
@@ -3031,7 +3047,7 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 				/* record begin time of next command, and initiate it */
 				if (report_per_command)
 				{
-					INSTR_TIME_SET_CURRENT_LAZY(now);
+					PG_TIME_SET_CURRENT_LAZY(now);
 					st->stmt_begin = now;
 				}
 
@@ -3194,8 +3210,8 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 				 * instead of CSTATE_START_TX.
 				 */
 			case CSTATE_SLEEP:
-				INSTR_TIME_SET_CURRENT_LAZY(now);
-				if (INSTR_TIME_GET_MICROSEC(now) < st->sleep_until)
+				PG_TIME_SET_CURRENT_LAZY(now);
+				if (now < st->sleep_until)
 					return;		/* still sleeping, nothing to do here */
 				/* Else done sleeping. */
 				st->state = CSTATE_END_COMMAND;
@@ -3215,13 +3231,12 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 				{
 					Command    *command;
 
-					INSTR_TIME_SET_CURRENT_LAZY(now);
+					PG_TIME_SET_CURRENT_LAZY(now);
 
 					command = sql_script[st->use_file].commands[st->command];
 					/* XXX could use a mutex here, but we choose not to */
 					addToSimpleStats(&command->stats,
-									 INSTR_TIME_GET_DOUBLE(now) -
-									 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
+									 PG_TIME_GET_DOUBLE(now - st->stmt_begin));
 				}
 
 				/* Go ahead with next command, to be executed or skipped */
@@ -3247,7 +3262,7 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 				if (is_connect)
 				{
 					finishCon(st);
-					INSTR_TIME_SET_ZERO(now);
+					now = 0;
 				}
 
 				if ((st->cnt >= nxacts && duration <= 0) || timer_exceeded)
@@ -3285,7 +3300,7 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
  * take no time to execute.
  */
 static ConnectionStateEnum
-executeMetaCommand(CState *st, instr_time *now)
+executeMetaCommand(CState *st, pg_time_usec_t *now)
 {
 	Command    *command = sql_script[st->use_file].commands[st->command];
 	int			argc;
@@ -3327,8 +3342,8 @@ executeMetaCommand(CState *st, instr_time *now)
 			return CSTATE_ABORTED;
 		}
 
-		INSTR_TIME_SET_CURRENT_LAZY(*now);
-		st->sleep_until = INSTR_TIME_GET_MICROSEC(*now) + usec;
+		PG_TIME_SET_CURRENT_LAZY(*now);
+		st->sleep_until = (*now) + usec;
 		return CSTATE_SLEEP;
 	}
 	else if (command->meta == META_SET)
@@ -3431,7 +3446,7 @@ executeMetaCommand(CState *st, instr_time *now)
 	 * executing the expression or shell command might have taken a
 	 * non-negligible amount of time, so reset 'now'
 	 */
-	INSTR_TIME_SET_ZERO(*now);
+	*now = 0;
 
 	return CSTATE_END_COMMAND;
 }
@@ -3441,14 +3456,15 @@ executeMetaCommand(CState *st, instr_time *now)
  *
  * We print Unix-epoch timestamps in the log, so that entries can be
  * correlated against other logs.  On some platforms this could be obtained
- * from the instr_time reading the caller has, but rather than get entangled
- * with that, we just eat the cost of an extra syscall in all cases.
+ * from the caller, but rather than get entangled with that, we just eat
+ * the cost of an extra syscall in all cases.
  */
 static void
 doLog(TState *thread, CState *st,
 	  StatsData *agg, bool skipped, double latency, double lag)
 {
 	FILE	   *logfile = thread->logfile;
+	pg_time_usec_t	now = pg_time_get_usec();
 
 	Assert(use_log);
 
@@ -3468,13 +3484,12 @@ doLog(TState *thread, CState *st,
 		 * any empty intervals in between (this may happen with very low tps,
 		 * e.g. --rate=0.1).
 		 */
-		time_t		now = time(NULL);
 
 		while (agg->start_time + agg_interval <= now)
 		{
 			/* print aggregated report to logfile */
-			fprintf(logfile, "%ld " INT64_FORMAT " %.0f %.0f %.0f %.0f",
-					(long) agg->start_time,
+			fprintf(logfile, INT64_FORMAT " " INT64_FORMAT " %.0f %.0f %.0f %.0f",
+					agg->start_time,
 					agg->cnt,
 					agg->latency.sum,
 					agg->latency.sum2,
@@ -3502,17 +3517,13 @@ doLog(TState *thread, CState *st,
 	else
 	{
 		/* no, print raw transactions */
-		struct timeval tv;
-
-		gettimeofday(&tv, NULL);
 		if (skipped)
 			fprintf(logfile, "%d " INT64_FORMAT " skipped %d %ld %ld",
-					st->id, st->cnt, st->use_file,
-					(long) tv.tv_sec, (long) tv.tv_usec);
+					st->id, st->cnt, st->use_file, now / 1000000, now % 1000000);
 		else
 			fprintf(logfile, "%d " INT64_FORMAT " %.0f %d %ld %ld",
 					st->id, st->cnt, latency, st->use_file,
-					(long) tv.tv_sec, (long) tv.tv_usec);
+					now / 1000000, now % 1000000);
 		if (throttle_delay)
 			fprintf(logfile, " %.0f", lag);
 		fputc('\n', logfile);
@@ -3526,7 +3537,7 @@ doLog(TState *thread, CState *st,
  * Note that even skipped transactions are counted in the "cnt" fields.)
  */
 static void
-processXactStats(TState *thread, CState *st, instr_time *now,
+processXactStats(TState *thread, CState *st, pg_time_usec_t *now,
 				 bool skipped, StatsData *agg)
 {
 	double		latency = 0.0,
@@ -3536,11 +3547,11 @@ processXactStats(TState *thread, CState *st, instr_time *now,
 
 	if (detailed && !skipped)
 	{
-		INSTR_TIME_SET_CURRENT_LAZY(*now);
+		PG_TIME_SET_CURRENT_LAZY(*now);
 
 		/* compute latency & lag */
-		latency = INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled;
-		lag = INSTR_TIME_GET_MICROSEC(st->txn_begin) - st->txn_scheduled;
+		latency = (*now) - st->txn_scheduled;
+		lag = st->txn_begin - st->txn_scheduled;
 	}
 
 	if (thread_details)
@@ -3803,10 +3814,7 @@ initGenerateDataClientSide(PGconn *con)
 	int64		k;
 
 	/* used to track elapsed time and estimate of the remaining time */
-	instr_time	start,
-				diff;
-	double		elapsed_sec,
-				remaining_sec;
+	pg_time_usec_t	start;
 	int			log_interval = 1;
 
 	/* Stay on the same line if reporting to a terminal */
@@ -3856,7 +3864,7 @@ initGenerateDataClientSide(PGconn *con)
 	}
 	PQclear(res);
 
-	INSTR_TIME_SET_CURRENT(start);
+	start = pg_time_get_usec();
 
 	for (k = 0; k < (int64) naccounts * scale; k++)
 	{
@@ -3881,11 +3889,8 @@ initGenerateDataClientSide(PGconn *con)
 		 */
 		if ((!use_quiet) && (j % 100000 == 0))
 		{
-			INSTR_TIME_SET_CURRENT(diff);
-			INSTR_TIME_SUBTRACT(diff, start);
-
-			elapsed_sec = INSTR_TIME_GET_DOUBLE(diff);
-			remaining_sec = ((double) scale * naccounts - j) * elapsed_sec / j;
+			double elapsed_sec = PG_TIME_GET_DOUBLE(pg_time_get_usec() - start);
+			double remaining_sec = ((double) scale * naccounts - j) * elapsed_sec / j;
 
 			fprintf(stderr, INT64_FORMAT " of " INT64_FORMAT " tuples (%d%%) done (elapsed %.2f s, remaining %.2f s)%c",
 					j, (int64) naccounts * scale,
@@ -3895,11 +3900,8 @@ initGenerateDataClientSide(PGconn *con)
 		/* let's not call the timing for each row, but only each 100 rows */
 		else if (use_quiet && (j % 100 == 0))
 		{
-			INSTR_TIME_SET_CURRENT(diff);
-			INSTR_TIME_SUBTRACT(diff, start);
-
-			elapsed_sec = INSTR_TIME_GET_DOUBLE(diff);
-			remaining_sec = ((double) scale * naccounts - j) * elapsed_sec / j;
+			double elapsed_sec = PG_TIME_GET_DOUBLE(pg_time_get_usec() - start);
+			double remaining_sec = ((double) scale * naccounts - j) * elapsed_sec / j;
 
 			/* have we reached the next interval (or end)? */
 			if ((j == scale * naccounts) || (elapsed_sec >= log_interval * LOG_STEP_SECONDS))
@@ -4095,10 +4097,8 @@ runInitSteps(const char *initialize_steps)
 
 	for (step = initialize_steps; *step != '\0'; step++)
 	{
-		instr_time	start;
 		char	   *op = NULL;
-
-		INSTR_TIME_SET_CURRENT(start);
+		pg_time_usec_t	start = pg_time_get_usec();
 
 		switch (*step)
 		{
@@ -4140,12 +4140,7 @@ runInitSteps(const char *initialize_steps)
 
 		if (op != NULL)
 		{
-			instr_time	diff;
-			double		elapsed_sec;
-
-			INSTR_TIME_SET_CURRENT(diff);
-			INSTR_TIME_SUBTRACT(diff, start);
-			elapsed_sec = INSTR_TIME_GET_DOUBLE(diff);
+			double		elapsed_sec = PG_TIME_GET_DOUBLE(pg_time_get_usec() - start);
 
 			if (!first)
 				appendPQExpBufferStr(&stats, ", ");
@@ -5064,12 +5059,12 @@ addScript(ParsedScript script)
  * progress report.  On exit, they are updated with the new stats.
  */
 static void
-printProgressReport(TState *threads, int64 test_start, int64 now,
+printProgressReport(TState *threads, int64 test_start, pg_time_usec_t now,
 					StatsData *last, int64 *last_report)
 {
 	/* generate and show report */
-	int64		run = now - *last_report,
-				ntx;
+	pg_time_usec_t	run = now - *last_report;
+	int64		ntx;
 	double		tps,
 				total_run,
 				latency,
@@ -5116,16 +5111,7 @@ printProgressReport(TState *threads, int64 test_start, int64 now,
 
 	if (progress_timestamp)
 	{
-		/*
-		 * On some platforms the current system timestamp is available in
-		 * now_time, but rather than get entangled with that, we just eat the
-		 * cost of an extra syscall in all cases.
-		 */
-		struct timeval tv;
-
-		gettimeofday(&tv, NULL);
-		snprintf(tbuf, sizeof(tbuf), "%ld.%03ld s",
-				 (long) tv.tv_sec, (long) (tv.tv_usec / 1000));
+		snprintf(tbuf, sizeof(tbuf), "%.3f s", PG_TIME_GET_DOUBLE(now));
 	}
 	else
 	{
@@ -5165,20 +5151,16 @@ printSimpleStats(const char *prefix, SimpleStats *ss)
 
 /* print out results */
 static void
-printResults(StatsData *total, instr_time total_time,
-			 instr_time conn_total_time, int64 latency_late)
+printResults(StatsData *total,
+			 pg_time_usec_t total_delay,		/* benchmarking time */
+			 pg_time_usec_t conn_total_delay,	/* is_connect */
+			 pg_time_usec_t conn_elapsed_delay,	/* !is_connect */
+			 int64 latency_late)
 {
-	double		time_include,
-				tps_include,
-				tps_exclude;
+	/* tps is about actually executed transactions during benchmarking */
 	int64		ntx = total->cnt - total->skipped;
-
-	time_include = INSTR_TIME_GET_DOUBLE(total_time);
-
-	/* tps is about actually executed transactions */
-	tps_include = ntx / time_include;
-	tps_exclude = ntx /
-		(time_include - (INSTR_TIME_GET_DOUBLE(conn_total_time) / nclients));
+	double 		bench_delay = PG_TIME_GET_DOUBLE(total_delay);
+	double		tps = ntx / bench_delay;
 
 	/* Report test parameters. */
 	printf("transaction type: %s\n",
@@ -5210,8 +5192,7 @@ printResults(StatsData *total, instr_time total_time,
 
 	if (throttle_delay && latency_limit)
 		printf("number of transactions skipped: " INT64_FORMAT " (%.3f %%)\n",
-			   total->skipped,
-			   100.0 * total->skipped / total->cnt);
+			   total->skipped, 100.0 * total->skipped / total->cnt);
 
 	if (latency_limit)
 		printf("number of transactions above the %.1f ms latency limit: " INT64_FORMAT "/" INT64_FORMAT " (%.3f %%)\n",
@@ -5224,7 +5205,7 @@ printResults(StatsData *total, instr_time total_time,
 	{
 		/* no measurement, show average latency computed from run time */
 		printf("latency average = %.3f ms\n",
-			   1000.0 * time_include * nclients / total->cnt);
+			   0.001 * total_delay * nclients / total->cnt);
 	}
 
 	if (throttle_delay)
@@ -5239,8 +5220,16 @@ printResults(StatsData *total, instr_time total_time,
 			   0.001 * total->lag.sum / total->cnt, 0.001 * total->lag.max);
 	}
 
-	printf("tps = %f (including connections establishing)\n", tps_include);
-	printf("tps = %f (excluding connections establishing)\n", tps_exclude);
+	if (is_connect)
+	{
+		printf("average connection time = %.3f ms\n", 0.001 * conn_total_delay / total->cnt);
+		printf("tps = %f (including reconnection times)\n", tps);
+	}
+	else
+	{
+		printf("initial connection time = %.3f ms\n", 0.001 * conn_elapsed_delay);
+		printf("tps = %f (without initial connection establishing)\n", tps);
+	}
 
 	/* Report per-script/command statistics */
 	if (per_script_stats || report_per_command)
@@ -5261,7 +5250,7 @@ printResults(StatsData *total, instr_time total_time,
 					   100.0 * sql_script[i].weight / total_weight,
 					   sstats->cnt,
 					   100.0 * sstats->cnt / total->cnt,
-					   (sstats->cnt - sstats->skipped) / time_include);
+					   (sstats->cnt - sstats->skipped) / bench_delay);
 
 				if (throttle_delay && latency_limit && sstats->cnt > 0)
 					printf(" - number of transactions skipped: " INT64_FORMAT " (%.3f%%)\n",
@@ -5309,10 +5298,7 @@ set_random_seed(const char *seed)
 	if (seed == NULL || strcmp(seed, "time") == 0)
 	{
 		/* rely on current time */
-		instr_time	now;
-
-		INSTR_TIME_SET_CURRENT(now);
-		iseed = (uint64) INSTR_TIME_GET_MICROSEC(now);
+		iseed = pg_time_get_usec();
 	}
 	else if (strcmp(seed, "rand") == 0)
 	{
@@ -5415,9 +5401,10 @@ main(int argc, char **argv)
 	CState	   *state;			/* status of clients */
 	TState	   *threads;		/* array of thread */
 
-	instr_time	start_time;		/* start up time */
-	instr_time	total_time;
-	instr_time	conn_total_time;
+	pg_time_usec_t
+				start_time,				/* start up time */
+				bench_start_time = 0,	/* first recorded benchmarking time */
+				conn_total_delay;		/* cumulated connection time in threads */
 	int64		latency_late = 0;
 	StatsData	stats;
 	int			weight;
@@ -6100,25 +6087,28 @@ main(int argc, char **argv)
 	/* all clients must be assigned to a thread */
 	Assert(nclients_dealt == nclients);
 
-	/* get start up time */
-	INSTR_TIME_SET_CURRENT(start_time);
+	/* get start up time for the whole computation */
+	start_time = pg_time_get_usec();
 
 	/* set alarm if duration is specified. */
 	if (duration > 0)
 		setalarm(duration);
 
+	pthread_barrier_init(&start_barrier, NULL, nthreads);
+	pthread_barrier_init(&bench_barrier, NULL, nthreads);
+
 	/* start threads */
 #ifdef ENABLE_THREAD_SAFETY
+
 	for (i = 0; i < nthreads; i++)
 	{
 		TState	   *thread = &threads[i];
 
-		INSTR_TIME_SET_CURRENT(thread->start_time);
+		thread->start_time = pg_time_get_usec();
 
 		/* compute when to stop */
 		if (duration > 0)
-			end_time = INSTR_TIME_GET_MICROSEC(thread->start_time) +
-				(int64) 1000000 * duration;
+			end_time = thread->start_time + (int64) 1000000 * duration;
 
 		/* the first thread (i = 0) is executed by main thread */
 		if (i > 0)
@@ -6137,17 +6127,17 @@ main(int argc, char **argv)
 		}
 	}
 #else
-	INSTR_TIME_SET_CURRENT(threads[0].start_time);
+	threads[0].start_time = pg_time_get_usec();
 	/* compute when to stop */
 	if (duration > 0)
-		end_time = INSTR_TIME_GET_MICROSEC(threads[0].start_time) +
-			(int64) 1000000 * duration;
+		end_time = threads[0].start_time + (int64) 1000000 * duration;
 	threads[0].thread = INVALID_THREAD;
 #endif							/* ENABLE_THREAD_SAFETY */
 
 	/* wait for threads and accumulate results */
 	initStats(&stats, 0);
-	INSTR_TIME_SET_ZERO(conn_total_time);
+	conn_total_delay = 0;
+
 	for (i = 0; i < nthreads; i++)
 	{
 		TState	   *thread = &threads[i];
@@ -6173,8 +6163,14 @@ main(int argc, char **argv)
 		stats.cnt += thread->stats.cnt;
 		stats.skipped += thread->stats.skipped;
 		latency_late += thread->latency_late;
-		INSTR_TIME_ADD(conn_total_time, thread->conn_time);
+		conn_total_delay += thread->conn_delay;
+
+		/* first recorded benchmarking start time */
+		if (bench_start_time == 0 || thread->bench_start_time < bench_start_time)
+			bench_start_time = thread->bench_start_time;
 	}
+
+	/* FIXME: should this be connection time? */
 	disconnect_all(state, nclients);
 
 	/*
@@ -6187,9 +6183,11 @@ main(int argc, char **argv)
 	 * easily exceed steady state performance.  This is one of the many ways
 	 * short runs convey deceptive performance figures.
 	 */
-	INSTR_TIME_SET_CURRENT(total_time);
-	INSTR_TIME_SUBTRACT(total_time, start_time);
-	printResults(&stats, total_time, conn_total_time, latency_late);
+	printResults(&stats, pg_time_get_usec() - bench_start_time, conn_total_delay,
+				 bench_start_time - start_time, latency_late);
+
+	pthread_barrier_destroy(&start_barrier);
+	pthread_barrier_destroy(&bench_barrier);
 
 	if (exit_code != 0)
 		pg_log_fatal("Run was aborted; the above results are incomplete.");
@@ -6202,34 +6200,16 @@ threadRun(void *arg)
 {
 	TState	   *thread = (TState *) arg;
 	CState	   *state = thread->state;
-	instr_time	start,
-				end;
+	pg_time_usec_t	start;
 	int			nstate = thread->nstate;
 	int			remains = nstate;	/* number of remaining clients */
 	socket_set *sockets = alloc_socket_set(nstate);
-	int			i;
-
-	/* for reporting progress: */
-	int64		thread_start = INSTR_TIME_GET_MICROSEC(thread->start_time);
-	int64		last_report = thread_start;
-	int64		next_report = last_report + (int64) progress * 1000000;
+	int64		thread_start,
+				last_report,
+				next_report;
 	StatsData	last,
 				aggs;
 
-	/*
-	 * Initialize throttling rate target for all of the thread's clients.  It
-	 * might be a little more accurate to reset thread->start_time here too.
-	 * The possible drift seems too small relative to typical throttle delay
-	 * times to worry about it.
-	 */
-	INSTR_TIME_SET_CURRENT(start);
-	thread->throttle_trigger = INSTR_TIME_GET_MICROSEC(start);
-
-	INSTR_TIME_SET_ZERO(thread->conn_time);
-
-	initStats(&aggs, time(NULL));
-	last = aggs;
-
 	/* open log file if requested */
 	if (use_log)
 	{
@@ -6250,32 +6230,55 @@ threadRun(void *arg)
 		}
 	}
 
+	/* explicitly initialize the state machines */
+	for (int i = 0; i < nstate; i++)
+	{
+		state[i].state = CSTATE_CHOOSE_SCRIPT;
+	}
+
+	/* READY */
+	pthread_barrier_wait(&start_barrier);
+
+	thread_start = pg_time_get_usec();
+	thread->started_time = thread_start;
+	last_report = thread_start;
+	next_report = last_report + (int64) 1000000 * progress;
+
+	/* STEADY */
 	if (!is_connect)
 	{
 		/* make connections to the database before starting */
-		for (i = 0; i < nstate; i++)
+		for (int i = 0; i < nstate; i++)
 		{
 			if ((state[i].con = doConnect()) == NULL)
 				goto done;
 		}
+
+		/* compute connection delay */
+		thread->conn_delay = pg_time_get_usec() - thread->started_time;
 	}
-
-	/* time after thread and connections set up */
-	INSTR_TIME_SET_CURRENT(thread->conn_time);
-	INSTR_TIME_SUBTRACT(thread->conn_time, thread->start_time);
-
-	/* explicitly initialize the state machines */
-	for (i = 0; i < nstate; i++)
+	else
 	{
-		state[i].state = CSTATE_CHOOSE_SCRIPT;
+		/* no connection delay to record */
+		thread->conn_delay = 0;
 	}
 
+	/* GO */
+	pthread_barrier_wait(&bench_barrier);
+
+	start = pg_time_get_usec();
+	thread->bench_start_time = start;
+	thread->throttle_trigger = start;
+
+	initStats(&aggs, start);
+	last = aggs;
+
 	/* loop till all clients have terminated */
 	while (remains > 0)
 	{
 		int			nsocks;		/* number of sockets to be waited for */
-		int64		min_usec;
-		int64		now_usec = 0;	/* set this only if needed */
+		pg_time_usec_t	min_usec;
+		pg_time_usec_t	now = 0;	/* set this only if needed */
 
 		/*
 		 * identify which client sockets should be checked for input, and
@@ -6284,27 +6287,21 @@ threadRun(void *arg)
 		clear_socket_set(sockets);
 		nsocks = 0;
 		min_usec = PG_INT64_MAX;
-		for (i = 0; i < nstate; i++)
+		for (int i = 0; i < nstate; i++)
 		{
 			CState	   *st = &state[i];
 
 			if (st->state == CSTATE_SLEEP || st->state == CSTATE_THROTTLE)
 			{
 				/* a nap from the script, or under throttling */
-				int64		this_usec;
+				pg_time_usec_t		this_usec;
 
 				/* get current time if needed */
-				if (now_usec == 0)
-				{
-					instr_time	now;
-
-					INSTR_TIME_SET_CURRENT(now);
-					now_usec = INSTR_TIME_GET_MICROSEC(now);
-				}
+				PG_TIME_SET_CURRENT_LAZY(now);
 
 				/* min_usec should be the minimum delay across all clients */
 				this_usec = (st->state == CSTATE_SLEEP ?
-							 st->sleep_until : st->txn_scheduled) - now_usec;
+							 st->sleep_until : st->txn_scheduled) - now;
 				if (min_usec > this_usec)
 					min_usec = this_usec;
 			}
@@ -6339,19 +6336,12 @@ threadRun(void *arg)
 		/* also wake up to print the next progress report on time */
 		if (progress && min_usec > 0 && thread->tid == 0)
 		{
-			/* get current time if needed */
-			if (now_usec == 0)
-			{
-				instr_time	now;
+			PG_TIME_SET_CURRENT_LAZY(now);
 
-				INSTR_TIME_SET_CURRENT(now);
-				now_usec = INSTR_TIME_GET_MICROSEC(now);
-			}
-
-			if (now_usec >= next_report)
+			if (now >= next_report)
 				min_usec = 0;
-			else if ((next_report - now_usec) < min_usec)
-				min_usec = next_report - now_usec;
+			else if ((next_report - now) < min_usec)
+				min_usec = next_report - now;
 		}
 
 		/*
@@ -6400,7 +6390,7 @@ threadRun(void *arg)
 
 		/* ok, advance the state machine of each connection */
 		nsocks = 0;
-		for (i = 0; i < nstate; i++)
+		for (int i = 0; i < nstate; i++)
 		{
 			CState	   *st = &state[i];
 
@@ -6438,11 +6428,8 @@ threadRun(void *arg)
 		/* progress report is made by thread 0 for all threads */
 		if (progress && thread->tid == 0)
 		{
-			instr_time	now_time;
-			int64		now;
+			pg_time_usec_t	now = pg_time_get_usec();
 
-			INSTR_TIME_SET_CURRENT(now_time);
-			now = INSTR_TIME_GET_MICROSEC(now_time);
 			if (now >= next_report)
 			{
 				/*
@@ -6460,17 +6447,17 @@ threadRun(void *arg)
 				 */
 				do
 				{
-					next_report += (int64) progress * 1000000;
+					next_report += (int64) 1000000 * progress;
 				} while (now >= next_report);
 			}
 		}
 	}
 
 done:
-	INSTR_TIME_SET_CURRENT(start);
+	start = pg_time_get_usec();
 	disconnect_all(state, nstate);
-	INSTR_TIME_SET_CURRENT(end);
-	INSTR_TIME_ACCUM_DIFF(thread->conn_time, end, start);
+	thread->conn_delay += pg_time_get_usec() - start;
+
 	if (thread->logfile)
 	{
 		if (agg_interval > 0)
@@ -6783,4 +6770,26 @@ pthread_join(pthread_t th, void **thread_return)
 	return 0;
 }
 
+static int
+pthread_barrier_init(pthread_barrier_t *barrier, void *unused, int nthreads)
+{
+	/* no spinning: threads are not expected to arrive at the barrier together */
+	bool ok = InitializeSynchronizationBarrier(barrier, nthreads, 0);
+	return 0;
+}
+
+static int
+pthread_barrier_wait(pthread_barrier_t *barrier)
+{
+	bool last = EnterSynchronizationBarrier(barrier, SYNCHRONIZATION_BARRIER_FLAGS_BLOCK_ONLY);
+	return last ? PTHREAD_BARRIER_SERIAL_THREAD : 0;
+}
+
+static int
+pthread_barrier_destroy(pthread_barrier_t *barrier)
+{
+	(void) DeleteSynchronizationBarrier(barrier);
+	return 0;
+}
+
 #endif							/* WIN32 */
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index d6459327cc..df58604121 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -253,4 +253,27 @@ GetTimerFrequency(void)
 #define INSTR_TIME_SET_CURRENT_LAZY(t) \
 	(INSTR_TIME_IS_ZERO(t) ? INSTR_TIME_SET_CURRENT(t), true : false)
 
+/*
+ * Simpler convenient interface
+ *
+ * The instr_time type is expensive when dealing with time arithmetic.
+ * Define a type to hold microseconds on top of this, suitable for
+ * benchmarking performance measures, eg in "pgbench".
+ */
+typedef int64 pg_time_usec_t;
+
+static inline pg_time_usec_t
+pg_time_get_usec(void)
+{
+	instr_time now;
+
+	INSTR_TIME_SET_CURRENT(now);
+	return (pg_time_usec_t) INSTR_TIME_GET_MICROSEC(now);
+}
+
+#define PG_TIME_SET_CURRENT_LAZY(t)		\
+	if ((t) == 0) 						\
+		(t) = pg_time_get_usec()
+
+#define PG_TIME_GET_DOUBLE(t) (0.000001 * (t))
 #endif							/* INSTR_TIME_H */

Reply via email to