Date: Wed, 27 Jan 2016 03:03:11 +0100
From: Alvaro Herrera <alvherre@2ndquadrant.com>
To: Fabien COELHO <coelho@cri.ensmp.fr>
Cc: "pgsql-hackers@postgresql.org" <pgsql-hackers@postgresql.org>
Subject: Re: pgbench stats per script & other stuff
Message-ID: <20160127020311.GA593894@alvherre.pgsql>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="sm4nu43k4a2Rpi4c"
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <20160126231755.GA580522@alvherre.pgsql>
User-Agent: Mutt/1.5.23 (2014-03-12)
Precedence: bulk
Sender: pgsql-hackers-owner@postgresql.org


--sm4nu43k4a2Rpi4c
Content-Type: text/plain; charset=iso-8859-1
Content-Disposition: inline
Content-Transfer-Encoding: 8bit

Alvaro Herrera wrote:

> I'm uncomfortable with the prefix-matching aspect of -b.  It makes
> "-b s" ambiguous -- whether it stands for select-only or simple-update
> is merely a matter of what comes earlier in the table, which doesn't
> seem reasonable to me.  [...]

> I'm going to change this to use strlen(builtin_script[i].name) instead
> of "len" here.

I pushed like that, but of course that means you can use "-b
simple-update-foo" and it works.  I could have used just strcmp().
(Part e is pushed too along with an initial pgindent).

Here's part b rebased, pgindented and with some minor additional tweaks
(mostly function commands and the function renames I mentioned).  Still
concerned about the unlocked stat accums.

I haven't tried to rebase the other ones yet, they need manual conflict
fixes.

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

--sm4nu43k4a2Rpi4c
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment; filename="pgbench-script-stats-14-b.patch"
Content-Transfer-Encoding: quoted-printable

commit dd71004519237e9449bb1902de3004a01f695365=1B[m
Author:     Alvaro Herrera <alvherre@alvh.no-ip.org>
AuthorDate: Tue Jan 26 10:12:51 2016 -0300
CommitDate: Wed Jan 27 02:57:18 2016 +0100

    apply 13-b, fix conflicts

diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index d5f242c..305c319 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -166,10 +166,8 @@ int			agg_interval;		/* log aggregates instead of indi=
vidual
 								 * transactions */
 int			progress =3D 0;		/* thread progress report every this seconds */
 bool		progress_timestamp =3D false; /* progress report with Unix time */
-int			progress_nclients =3D 0;		/* number of clients for progress
-										 * report */
-int			progress_nthreads =3D 0;		/* number of threads for progress
-										 * report */
+int			nclients =3D 1;		/* number of clients */
+int			nthreads =3D 1;		/* number of threads */
 bool		is_connect;			/* establish connection for each transaction */
 bool		is_latencies;		/* report per-command latencies */
 int			main_pid;			/* main process id used in log filename */
@@ -193,6 +191,35 @@ typedef struct
 #define SHELL_COMMAND_SIZE	256 /* maximum size allowed for shell command */
=20
 /*
+ * Simple data structure to keep stats about something.
+ *
+ * XXX probably the first value should be kept and used as an offset for
+ * better numerical stability...
+ */
+typedef struct
+{
+	int64		count;			/* how many values were encountered */
+	double		min;			/* the minimum seen */
+	double		max;			/* the maximum seen */
+	double		sum;			/* sum of values */
+	double		sum2;			/* sum of squared values */
+} SimpleStats;
+
+/*
+ * Data structure to hold various statistics, used for interval statistics=
 as
+ * well as file statistics.
+ */
+typedef struct
+{
+	long		start_time;		/* interval start time, for aggregates */
+	int64		cnt;			/* number of transactions */
+	int64		skipped;		/* number of transactions skipped under --rate
+								 * and --latency-limit */
+	SimpleStats latency;
+	SimpleStats lag;
+} StatsData;
+
+/*
  * Connection state
  */
 typedef struct
@@ -213,10 +240,8 @@ typedef struct
 	bool		prepared[MAX_SCRIPTS];	/* whether client prepared the script */
=20
 	/* per client collected stats */
-	int			cnt;			/* xacts count */
+	int64		cnt;			/* transaction count */
 	int			ecnt;			/* error count */
-	int64		txn_latencies;	/* cumulated latencies */
-	int64		txn_sqlats;		/* cumulated square latencies */
 } CState;
=20
 /*
@@ -228,19 +253,14 @@ typedef struct
 	pthread_t	thread;			/* thread handle */
 	CState	   *state;			/* array of CState */
 	int			nstate;			/* length of state[] */
-	instr_time	start_time;		/* thread start time */
-	instr_time *exec_elapsed;	/* time spent executing cmds (per Command) */
-	int		   *exec_count;		/* number of cmd executions (per Command) */
 	unsigned short random_state[3];		/* separate randomness for each thread */
 	int64		throttle_trigger;		/* previous/next throttling (us) */
=20
 	/* per thread collected stats */
+	instr_time	start_time;		/* thread start time */
 	instr_time	conn_time;
-	int64		throttle_lag;	/* total transaction lag behind throttling */
-	int64		throttle_lag_max;		/* max transaction lag */
-	int64		throttle_latency_skipped;		/* lagging transactions
-												 * skipped */
-	int64		latency_late;	/* late transactions */
+	StatsData	stats;
+	int64		latency_late;	/* executed but late transactions */
 } TState;
=20
 #define INVALID_THREAD		((pthread_t) 0)
@@ -272,33 +292,14 @@ typedef struct
 	char	   *argv[MAX_ARGS]; /* command word list */
 	int			cols[MAX_ARGS]; /* corresponding column starting from 1 */
 	PgBenchExpr *expr;			/* parsed expression */
+	SimpleStats stats;			/* time spent in this command */
 } Command;
=20
-typedef struct
-{
-
-	long		start_time;		/* when does the interval start */
-	int			cnt;			/* number of transactions */
-	int			skipped;		/* number of transactions skipped under --rate
-								 * and --latency-limit */
-
-	double		min_latency;	/* min/max latencies */
-	double		max_latency;
-	double		sum_latency;	/* sum(latency), sum(latency^2) - for
-								 * estimates */
-	double		sum2_latency;
-
-	double		min_lag;
-	double		max_lag;
-	double		sum_lag;		/* sum(lag) */
-	double		sum2_lag;		/* sum(lag*lag) */
-} AggVals;
-
 static struct
 {
 	const char *name;
-	Command	 **commands;
-} sql_script[MAX_SCRIPTS];		/* SQL script files */
+	Command   **commands;
+}	sql_script[MAX_SCRIPTS];	/* SQL script files */
 static int	num_scripts;		/* number of scripts in sql_script[] */
 static int	num_commands =3D 0;	/* total number of Command structs */
 static int	debug =3D 0;			/* debug flag */
@@ -361,9 +362,8 @@ static struct
 /* Function prototypes */
 static void setalarm(int seconds);
 static void *threadRun(void *arg);
+static void doTxStats(TState *, CState *, instr_time *, bool, FILE *, Stat=
sData *);
=20
-static void doLog(TState *thread, CState *st, FILE *logfile, instr_time *n=
ow,
-	  AggVals *agg, bool skipped);
=20
 static void
 usage(void)
@@ -602,6 +602,63 @@ getPoissonRand(TState *thread, int64 center)
 	return (int64) (-log(uniform) * ((double) center) + 0.5);
 }
=20
+/*
+ * Initialize the given SimpleStats struct to all zeroes
+ */
+static void
+initSimpleStats(SimpleStats *ss)
+{
+	memset(ss, 0, sizeof(SimpleStats));
+}
+
+/*
+ * Accumulate one value into a SimpleStats struct.
+ */
+static void
+addToSimpleStats(SimpleStats *ss, double val)
+{
+	if (ss->count =3D=3D 0 || val < ss->min)
+		ss->min =3D val;
+	if (ss->count =3D=3D 0 || val > ss->max)
+		ss->max =3D val;
+	ss->count++;
+	ss->sum +=3D val;
+	ss->sum2 +=3D val * val;
+}
+
+/*
+ * Merge two SimpleStats objects
+ */
+static void
+mergeSimpleStats(SimpleStats *acc, SimpleStats *ss)
+{
+	if (acc->count =3D=3D 0 || ss->min < acc->min)
+		acc->min =3D ss->min;
+	if (acc->count =3D=3D 0 || ss->max > acc->max)
+		acc->max =3D ss->max;
+	acc->count +=3D ss->count;
+	acc->sum +=3D ss->sum;
+	acc->sum2 +=3D ss->sum2;
+}
+
+/*
+ * Initialize a StatsData struct to all zeroes.
+ *
+ * If the given start_time is different from 0.0, it is used; otherwise
+ * the original value is retained.
+ */
+static void
+initStats(StatsData *sd, double start_time)
+{
+	if (start_time !=3D 0.0)
+		sd->start_time =3D start_time;
+
+	sd->cnt =3D 0;
+	sd->skipped =3D 0;
+	initSimpleStats(&sd->latency);
+	initSimpleStats(&sd->lag);
+}
+
 /* call PQexec() and exit() on failure */
 static void
 executeStatement(PGconn *con, const char *sql)
@@ -1121,30 +1178,6 @@ clientDone(CState *st, bool ok)
 	return false;				/* always false */
 }
=20
-static void
-agg_vals_init(AggVals *aggs, instr_time start)
-{
-	/* basic counters */
-	aggs->cnt =3D 0;				/* number of transactions (includes skipped) */
-	aggs->skipped =3D 0;			/* xacts skipped under --rate --latency-limit */
-
-	aggs->sum_latency =3D 0;		/* SUM(latency) */
-	aggs->sum2_latency =3D 0;		/* SUM(latency*latency) */
-
-	/* min and max transaction duration */
-	aggs->min_latency =3D 0;
-	aggs->max_latency =3D 0;
-
-	/* schedule lag counters */
-	aggs->sum_lag =3D 0;
-	aggs->sum2_lag =3D 0;
-	aggs->min_lag =3D 0;
-	aggs->max_lag =3D 0;
-
-	/* start of the current interval */
-	aggs->start_time =3D INSTR_TIME_GET_DOUBLE(start);
-}
-
 static int
 chooseScript(TState *thread)
 {
@@ -1156,7 +1189,7 @@ chooseScript(TState *thread)
=20
 /* return false iff client should be disconnected */
 static bool
-doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile,=
 AggVals *agg)
+doCustom(TState *thread, CState *st, FILE *logfile, StatsData *agg)
 {
 	PGresult   *res;
 	Command   **commands;
@@ -1210,11 +1243,8 @@ top:
 			now_us =3D INSTR_TIME_GET_MICROSEC(now);
 			while (thread->throttle_trigger < now_us - latency_limit)
 			{
-				thread->throttle_latency_skipped++;
-
-				if (logfile)
-					doLog(thread, st, logfile, &now, agg, true);
-
+				doTxStats(thread, st, &now, true, logfile, agg);
+				/* next rendez-vous */
 				wait =3D getPoissonRand(thread, throttle_delay);
 				thread->throttle_trigger +=3D wait;
 				st->txn_scheduled =3D thread->throttle_trigger;
@@ -1231,28 +1261,13 @@ top:
=20
 	if (st->sleeping)
 	{							/* are we sleeping? */
-		int64		now_us;
-
 		if (INSTR_TIME_IS_ZERO(now))
 			INSTR_TIME_SET_CURRENT(now);
-		now_us =3D INSTR_TIME_GET_MICROSEC(now);
-		if (st->txn_scheduled <=3D now_us)
-		{
-			/* Done sleeping, go ahead with next command */
-			st->sleeping =3D false;
-			if (st->throttling)
-			{
-				/* Measure lag of throttled transaction relative to target */
-				int64		lag =3D now_us - st->txn_scheduled;
-
-				thread->throttle_lag +=3D lag;
-				if (lag > thread->throttle_lag_max)
-					thread->throttle_lag_max =3D lag;
-				st->throttling =3D false;
-			}
-		}
-		else
+		if (INSTR_TIME_GET_MICROSEC(now) < st->txn_scheduled)
 			return true;		/* Still sleeping, nothing to do here */
+		/* Else done sleeping, go ahead with next command */
+		st->sleeping =3D 0;
+		st->throttling =3D false;
 	}
=20
 	if (st->listen)
@@ -1276,47 +1291,27 @@ top:
 		 */
 		if (is_latencies)
 		{
-			int			cnum =3D commands[st->state]->command_num;
-
 			if (INSTR_TIME_IS_ZERO(now))
 				INSTR_TIME_SET_CURRENT(now);
-			INSTR_TIME_ACCUM_DIFF(thread->exec_elapsed[cnum],
-								  now, st->stmt_begin);
-			thread->exec_count[cnum]++;
+
+			/*
+			 * XXX When doing multiple threads, more than one could try to
+			 * update the stats for one command simultaneously.  Instead of
+			 * adding the overhead of a mutex, we accept the very small
+			 * probability of getting slightly wrong values.
+			 */
+			addToSimpleStats(&commands[st->state]->stats,
+							 INSTR_TIME_GET_DOUBLE(now) -
+							 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
 		}
=20
 		/* transaction finished: calculate latency and log the transaction */
 		if (commands[st->state + 1] =3D=3D NULL)
 		{
-			/* only calculate latency if an option is used that needs it */
-			if (progress || throttle_delay || latency_limit)
-			{
-				int64		latency;
-
-				if (INSTR_TIME_IS_ZERO(now))
-					INSTR_TIME_SET_CURRENT(now);
-
-				latency =3D INSTR_TIME_GET_MICROSEC(now) - st->txn_scheduled;
-
-				st->txn_latencies +=3D latency;
-
-				/*
-				 * XXX In a long benchmark run of high-latency transactions,
-				 * this int64 addition eventually overflows.  For example, 100
-				 * threads running 10s transactions will overflow it in 2.56
-				 * hours.  With a more-typical OLTP workload of .1s
-				 * transactions, overflow would take 256 hours.
-				 */
-				st->txn_sqlats +=3D latency * latency;
-
-				/* record over the limit transactions if needed. */
-				if (latency_limit && latency > latency_limit)
-					thread->latency_late++;
-			}
-
-			/* record the time it took in the log */
-			if (logfile)
-				doLog(thread, st, logfile, &now, agg, false);
+			if (progress || throttle_delay || latency_limit || logfile)
+				doTxStats(thread, st, &now, false, logfile, agg);
+			else
+				thread->stats.cnt++;
 		}
=20
 		if (commands[st->state]->type =3D=3D SQL_COMMAND)
@@ -1391,7 +1386,7 @@ top:
 			return clientDone(st, false);
 		}
 		INSTR_TIME_SET_CURRENT(end);
-		INSTR_TIME_ACCUM_DIFF(*conn_time, end, start);
+		INSTR_TIME_ACCUM_DIFF(thread->conn_time, end, start);
 	}
=20
 	/*
@@ -1734,22 +1729,41 @@ top:
 			else	/* succeeded */
 				st->listen =3D true;
 		}
+
+		/* after a meta command, immediately proceed with next command */
 		goto top;
 	}
=20
 	return true;
 }
=20
+static void
+doStats(StatsData *stats, bool skipped, double lat, double lag)
+{
+	stats->cnt++;
+
+	if (skipped)
+	{
+		/* no latency to record on skipped transactions */
+		stats->skipped++;
+	}
+	else
+	{
+		addToSimpleStats(&stats->latency, lat);
+
+		/* and possibly the same for schedule lag */
+		if (throttle_delay)
+			addToSimpleStats(&stats->lag, lag);
+	}
+}
+
 /*
  * print log entry after completing one transaction.
  */
 static void
-doLog(TState *thread, CState *st, FILE *logfile, instr_time *now, AggVals =
*agg,
-	  bool skipped)
+doLog(TState *thread, CState *st, FILE *logfile, instr_time *now,
+	  StatsData *agg, bool skipped, double latency, double lag)
 {
-	double		lag;
-	double		latency;
-
 	/*
 	 * Skip the log entry if sampling is enabled and this row doesn't belong
 	 * to the random sample.
@@ -1758,15 +1772,6 @@ doLog(TState *thread, CState *st, FILE *logfile, ins=
tr_time *now, AggVals *agg,
 		pg_erand48(thread->random_state) > sample_rate)
 		return;
=20
-	if (INSTR_TIME_IS_ZERO(*now))
-		INSTR_TIME_SET_CURRENT(*now);
-
-	latency =3D (double) (INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled);
-	if (skipped)
-		lag =3D latency;
-	else
-		lag =3D (double) (INSTR_TIME_GET_MICROSEC(st->txn_begin) - st->txn_sched=
uled);
-
 	/* should we aggregate the results or not? */
 	if (agg_interval > 0)
 	{
@@ -1776,39 +1781,7 @@ doLog(TState *thread, CState *st, FILE *logfile, ins=
tr_time *now, AggVals *agg,
 		 */
 		if (agg->start_time + agg_interval >=3D INSTR_TIME_GET_DOUBLE(*now))
 		{
-			agg->cnt +=3D 1;
-			if (skipped)
-			{
-				/*
-				 * there is no latency to record if the transaction was
-				 * skipped
-				 */
-				agg->skipped +=3D 1;
-			}
-			else
-			{
-				agg->sum_latency +=3D latency;
-				agg->sum2_latency +=3D latency * latency;
-
-				/* first in this aggregation interval */
-				if ((agg->cnt =3D=3D 1) || (latency < agg->min_latency))
-					agg->min_latency =3D latency;
-
-				if ((agg->cnt =3D=3D 1) || (latency > agg->max_latency))
-					agg->max_latency =3D latency;
-
-				/* and the same for schedule lag */
-				if (throttle_delay)
-				{
-					agg->sum_lag +=3D lag;
-					agg->sum2_lag +=3D lag * lag;
-
-					if ((agg->cnt =3D=3D 1) || (lag < agg->min_lag))
-						agg->min_lag =3D lag;
-					if ((agg->cnt =3D=3D 1) || (lag > agg->max_lag))
-						agg->max_lag =3D lag;
-				}
-			}
+			doStats(agg, skipped, latency, lag);
 		}
 		else
 		{
@@ -1823,52 +1796,34 @@ doLog(TState *thread, CState *st, FILE *logfile, in=
str_time *now, AggVals *agg,
 				 * usage), so we don't need to handle this in a special way
 				 * (see below).
 				 */
-				fprintf(logfile, "%ld %d %.0f %.0f %.0f %.0f",
+				fprintf(logfile, "%ld " INT64_FORMAT " %.0f %.0f %.0f %.0f",
 						agg->start_time,
 						agg->cnt,
-						agg->sum_latency,
-						agg->sum2_latency,
-						agg->min_latency,
-						agg->max_latency);
+						agg->latency.sum,
+						agg->latency.sum2,
+						agg->latency.min,
+						agg->latency.max);
 				if (throttle_delay)
 				{
 					fprintf(logfile, " %.0f %.0f %.0f %.0f",
-							agg->sum_lag,
-							agg->sum2_lag,
-							agg->min_lag,
-							agg->max_lag);
+							agg->lag.sum,
+							agg->lag.sum2,
+							agg->lag.min,
+							agg->lag.max);
 					if (latency_limit)
-						fprintf(logfile, " %d", agg->skipped);
+						fprintf(logfile, " " INT64_FORMAT, agg->skipped);
 				}
 				fputc('\n', logfile);
=20
-				/* move to the next inteval */
-				agg->start_time =3D agg->start_time + agg_interval;
+				/* move to the next interval */
+				agg->start_time +=3D agg_interval;
=20
 				/* reset for "no transaction" intervals */
-				agg->cnt =3D 0;
-				agg->skipped =3D 0;
-				agg->min_latency =3D 0;
-				agg->max_latency =3D 0;
-				agg->sum_latency =3D 0;
-				agg->sum2_latency =3D 0;
-				agg->min_lag =3D 0;
-				agg->max_lag =3D 0;
-				agg->sum_lag =3D 0;
-				agg->sum2_lag =3D 0;
+				initStats(agg, 0.0);
 			}
=20
 			/* reset the values to include only the current transaction. */
-			agg->cnt =3D 1;
-			agg->skipped =3D skipped ? 1 : 0;
-			agg->min_latency =3D latency;
-			agg->max_latency =3D latency;
-			agg->sum_latency =3D skipped ? 0.0 : latency;
-			agg->sum2_latency =3D skipped ? 0.0 : latency * latency;
-			agg->min_lag =3D lag;
-			agg->max_lag =3D lag;
-			agg->sum_lag =3D lag;
-			agg->sum2_lag =3D lag * lag;
+			doStats(agg, skipped, latency, lag);
 		}
 	}
 	else
@@ -1878,21 +1833,21 @@ doLog(TState *thread, CState *st, FILE *logfile, in=
str_time *now, AggVals *agg,
=20
 		/* This is more than we really ought to know about instr_time */
 		if (skipped)
-			fprintf(logfile, "%d %d skipped %d %ld %ld",
+			fprintf(logfile, "%d " INT64_FORMAT " skipped %d %ld %ld",
 					st->id, st->cnt, st->use_file,
 					(long) now->tv_sec, (long) now->tv_usec);
 		else
-			fprintf(logfile, "%d %d %.0f %d %ld %ld",
+			fprintf(logfile, "%d " INT64_FORMAT " %.0f %d %ld %ld",
 					st->id, st->cnt, latency, st->use_file,
 					(long) now->tv_sec, (long) now->tv_usec);
 #else
=20
 		/* On Windows, instr_time doesn't provide a timestamp anyway */
 		if (skipped)
-			fprintf(logfile, "%d %d skipped %d 0 0",
+			fprintf(logfile, "%d " INT64_FORMAT " skipped %d 0 0",
 					st->id, st->cnt, st->use_file);
 		else
-			fprintf(logfile, "%d %d %.0f %d 0 0",
+			fprintf(logfile, "%d " INT64_FORMAT " %.0f %d 0 0",
 					st->id, st->cnt, latency, st->use_file);
 #endif
 		if (throttle_delay)
@@ -1901,6 +1856,42 @@ doLog(TState *thread, CState *st, FILE *logfile, ins=
tr_time *now, AggVals *agg,
 	}
 }
=20
+/*
+ * end of transaction statistics
+ */
+static void
+doTxStats(TState *thread, CState *st, instr_time *now,
+		  bool skipped, FILE *logfile, StatsData *agg)
+{
+	double		latency =3D 0.0,
+				lag =3D 0.0;
+
+	if ((!skipped || agg_interval) && INSTR_TIME_IS_ZERO(*now))
+		INSTR_TIME_SET_CURRENT(*now);
+
+	if (!skipped)
+	{
+		/* compute latency & lag if needed */
+		latency =3D INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled;
+		lag =3D INSTR_TIME_GET_MICROSEC(st->txn_begin) - st->txn_scheduled;
+	}
+
+	if (progress || throttle_delay || latency_limit)
+	{
+		doStats(&thread->stats, skipped, latency, lag);
+
+		/* record over the limit transactions if needed. */
+		if (latency_limit && latency > latency_limit)
+			thread->latency_late++;
+	}
+	else
+		thread->stats.cnt++;
+
+	if (use_log)
+		doLog(thread, st, logfile, now, agg, skipped, latency, lag);
+}
+
+
 /* discard connections */
 static void
 disconnect_all(CState *state, int length)
@@ -2297,6 +2288,7 @@ process_commands(char *buf, const char *source, const=
 int lineno)
 	my_commands->command_num =3D num_commands++;
 	my_commands->type =3D 0;		/* until set */
 	my_commands->argc =3D 0;
+	initSimpleStats(&my_commands->stats);
=20
 	if (*p =3D=3D '\\')
 	{
@@ -2641,7 +2633,7 @@ process_builtin(const char *tb, const char *source)
 static void
 listAvailableScripts(void)
 {
-	int		i;
+	int			i;
=20
 	fprintf(stderr, "Available builtin scripts:\n");
 	for (i =3D 0; i < N_BUILTIN; i++)
@@ -2689,22 +2681,29 @@ addScript(const char *name, Command **commands)
 	num_scripts++;
 }
=20
+static void
+printSimpleStats(char *prefix, SimpleStats *ss)
+{
+	/* print NaN if no transactions where executed */
+	double		latency =3D ss->sum / ss->count;
+	double		stddev =3D sqrt(ss->sum2 / ss->count - latency * latency);
+
+	printf("%s average =3D %.3f ms\n", prefix, 0.001 * latency);
+	printf("%s stddev =3D %.3f ms\n", prefix, 0.001 * stddev);
+}
+
 /* print out results */
 static void
-printResults(int64 normal_xacts, int nclients,
-			 TState *threads, int nthreads,
-			 instr_time total_time, instr_time conn_total_time,
-			 int64 total_latencies, int64 total_sqlats,
-			 int64 throttle_lag, int64 throttle_lag_max,
-			 int64 throttle_latency_skipped, int64 latency_late)
+printResults(TState *threads, StatsData *total, instr_time total_time,
+			 instr_time conn_total_time, int latency_late)
 {
 	double		time_include,
 				tps_include,
 				tps_exclude;
=20
 	time_include =3D INSTR_TIME_GET_DOUBLE(total_time);
-	tps_include =3D normal_xacts / time_include;
-	tps_exclude =3D normal_xacts / (time_include -
+	tps_include =3D total->cnt / time_include;
+	tps_exclude =3D total->cnt / (time_include -
 						(INSTR_TIME_GET_DOUBLE(conn_total_time) / nclients));
=20
 	printf("transaction type: %s\n",
@@ -2716,46 +2715,36 @@ printResults(int64 normal_xacts, int nclients,
 	if (duration <=3D 0)
 	{
 		printf("number of transactions per client: %d\n", nxacts);
-		printf("number of transactions actually processed: " INT64_FORMAT "/" IN=
T64_FORMAT "\n",
-			   normal_xacts, (int64) nxacts * nclients);
+		printf("number of transactions actually processed: " INT64_FORMAT "/%d\n=
",
+			   total->cnt, nxacts * nclients);
 	}
 	else
 	{
 		printf("duration: %d s\n", duration);
 		printf("number of transactions actually processed: " INT64_FORMAT "\n",
-			   normal_xacts);
+			   total->cnt);
 	}
=20
 	/* Remaining stats are nonsensical if we failed to execute any xacts */
-	if (normal_xacts <=3D 0)
+	if (total->cnt <=3D 0)
 		return;
=20
 	if (throttle_delay && latency_limit)
 		printf("number of transactions skipped: " INT64_FORMAT " (%.3f %%)\n",
-			   throttle_latency_skipped,
-			   100.0 * throttle_latency_skipped / (throttle_latency_skipped + norma=
l_xacts));
+			   total->skipped,
+			   100.0 * total->skipped / (total->skipped + total->cnt));
=20
 	if (latency_limit)
-		printf("number of transactions above the %.1f ms latency limit: " INT64_=
FORMAT " (%.3f %%)\n",
+		printf("number of transactions above the %.1f ms latency limit: %d (%.3f=
 %%)\n",
 			   latency_limit / 1000.0, latency_late,
-		   100.0 * latency_late / (throttle_latency_skipped + normal_xacts));
+			   100.0 * latency_late / (total->skipped + total->cnt));
=20
 	if (throttle_delay || progress || latency_limit)
-	{
-		/* compute and show latency average and standard deviation */
-		double		latency =3D 0.001 * total_latencies / normal_xacts;
-		double		sqlat =3D (double) total_sqlats / normal_xacts;
-
-		printf("latency average: %.3f ms\n"
-			   "latency stddev: %.3f ms\n",
-			   latency, 0.001 * sqrt(sqlat - 1000000.0 * latency * latency));
-	}
+		printSimpleStats("latency", &total->latency);
 	else
-	{
 		/* only an average latency computed from the duration is available */
 		printf("latency average: %.3f ms\n",
-			   1000.0 * duration * nclients / normal_xacts);
-	}
+			   1000.0 * duration * nclients / total->cnt);
=20
 	if (throttle_delay)
 	{
@@ -2766,7 +2755,7 @@ printResults(int64 normal_xacts, int nclients,
 		 * the database load, or the Poisson throttling process.
 		 */
 		printf("rate limit schedule lag: avg %.3f (max %.3f) ms\n",
-			   0.001 * throttle_lag / normal_xacts, 0.001 * throttle_lag_max);
+			   0.001 * total->lag.sum / total->cnt, 0.001 * total->lag.max);
 	}
=20
 	printf("tps =3D %f (including connections establishing)\n", tps_include);
@@ -2785,33 +2774,9 @@ printResults(int64 normal_xacts, int nclients,
 			printf(" - statement latencies in milliseconds:\n");
=20
 			for (commands =3D sql_script[i].commands; *commands !=3D NULL; commands=
++)
-			{
-				Command    *command =3D *commands;
-				int			cnum =3D command->command_num;
-				double		total_time;
-				instr_time	total_exec_elapsed;
-				int			total_exec_count;
-				int			t;
-
-				/* Accumulate per-thread data for command */
-				INSTR_TIME_SET_ZERO(total_exec_elapsed);
-				total_exec_count =3D 0;
-				for (t =3D 0; t < nthreads; t++)
-				{
-					TState	   *thread =3D &threads[t];
-
-					INSTR_TIME_ADD(total_exec_elapsed,
-								   thread->exec_elapsed[cnum]);
-					total_exec_count +=3D thread->exec_count[cnum];
-				}
-
-				if (total_exec_count > 0)
-					total_time =3D INSTR_TIME_GET_MILLISEC(total_exec_elapsed) / (double)=
 total_exec_count;
-				else
-					total_time =3D 0.0;
-
-				printf("\t%f\t%s\n", total_time, command->line);
-			}
+				printf("   %11.3f  %s\n",
+				   1000.0 * (*commands)->stats.sum / (*commands)->stats.count,
+					   (*commands)->line);
 		}
 	}
 }
@@ -2860,8 +2825,6 @@ main(int argc, char **argv)
 	};
=20
 	int			c;
-	int			nclients =3D 1;	/* default number of simulated clients */
-	int			nthreads =3D 1;	/* default number of threads */
 	int			is_init_mode =3D 0;		/* initialize mode? */
 	int			is_no_vacuum =3D 0;		/* no vacuum at all before testing? */
 	int			do_vacuum_accounts =3D 0; /* do vacuum accounts before testing? */
@@ -2878,13 +2841,8 @@ main(int argc, char **argv)
 	instr_time	start_time;		/* start up time */
 	instr_time	total_time;
 	instr_time	conn_total_time;
-	int64		total_xacts =3D 0;
-	int64		total_latencies =3D 0;
-	int64		total_sqlats =3D 0;
-	int64		throttle_lag =3D 0;
-	int64		throttle_lag_max =3D 0;
-	int64		throttle_latency_skipped =3D 0;
 	int64		latency_late =3D 0;
+	StatsData	stats;
 	char	   *desc;
=20
 	int			i;
@@ -3071,14 +3029,14 @@ main(int argc, char **argv)
 			case 'S':
 				addScript(desc,
 						  process_builtin(findBuiltin("select-only", &desc),
-										 desc));
+										  desc));
 				benchmarking_option_set =3D true;
 				internal_script_used =3D true;
 				break;
 			case 'N':
 				addScript(desc,
 						  process_builtin(findBuiltin("simple-update", &desc),
-										 desc));
+										  desc));
 				benchmarking_option_set =3D true;
 				internal_script_used =3D true;
 				break;
@@ -3311,8 +3269,6 @@ main(int argc, char **argv)
 	 * changed after fork.
 	 */
 	main_pid =3D (int) getpid();
-	progress_nclients =3D nclients;
-	progress_nthreads =3D nthreads;
=20
 	if (nclients > 1)
 	{
@@ -3454,32 +3410,10 @@ main(int argc, char **argv)
 		thread->random_state[0] =3D random();
 		thread->random_state[1] =3D random();
 		thread->random_state[2] =3D random();
-		thread->throttle_latency_skipped =3D 0;
 		thread->latency_late =3D 0;
+		initStats(&thread->stats, 0.0);
=20
 		nclients_dealt +=3D thread->nstate;
-
-		if (is_latencies)
-		{
-			/* Reserve memory for the thread to store per-command latencies */
-			int			t;
-
-			thread->exec_elapsed =3D (instr_time *)
-				pg_malloc(sizeof(instr_time) * num_commands);
-			thread->exec_count =3D (int *)
-				pg_malloc(sizeof(int) * num_commands);
-
-			for (t =3D 0; t < num_commands; t++)
-			{
-				INSTR_TIME_SET_ZERO(thread->exec_elapsed[t]);
-				thread->exec_count[t] =3D 0;
-			}
-		}
-		else
-		{
-			thread->exec_elapsed =3D NULL;
-			thread->exec_count =3D NULL;
-		}
 	}
=20
 	/* all clients must be assigned to a thread */
@@ -3522,11 +3456,11 @@ main(int argc, char **argv)
 #endif   /* ENABLE_THREAD_SAFETY */
=20
 	/* wait for threads and accumulate results */
+	initStats(&stats, 0.0);
 	INSTR_TIME_SET_ZERO(conn_total_time);
 	for (i =3D 0; i < nthreads; i++)
 	{
 		TState	   *thread =3D &threads[i];
-		int			j;
=20
 #ifdef ENABLE_THREAD_SAFETY
 		if (threads[i].thread =3D=3D INVALID_THREAD)
@@ -3539,21 +3473,13 @@ main(int argc, char **argv)
 		(void) threadRun(thread);
 #endif   /* ENABLE_THREAD_SAFETY */
=20
-		/* thread level stats */
-		throttle_lag +=3D thread->throttle_lag;
-		throttle_latency_skipped +=3D threads->throttle_latency_skipped;
+		/* aggregate thread level stats */
+		mergeSimpleStats(&stats.latency, &thread->stats.latency);
+		mergeSimpleStats(&stats.lag, &thread->stats.lag);
+		stats.cnt +=3D thread->stats.cnt;
+		stats.skipped +=3D thread->stats.skipped;
 		latency_late +=3D thread->latency_late;
-		if (throttle_lag_max > thread->throttle_lag_max)
-			throttle_lag_max =3D thread->throttle_lag_max;
 		INSTR_TIME_ADD(conn_total_time, thread->conn_time);
-
-		/* client-level stats */
-		for (j =3D 0; j < thread->nstate; j++)
-		{
-			total_xacts +=3D thread->state[j].cnt;
-			total_latencies +=3D thread->state[j].txn_latencies;
-			total_sqlats +=3D thread->state[j].txn_sqlats;
-		}
 	}
 	disconnect_all(state, nclients);
=20
@@ -3569,10 +3495,7 @@ main(int argc, char **argv)
 	 */
 	INSTR_TIME_SET_CURRENT(total_time);
 	INSTR_TIME_SUBTRACT(total_time, start_time);
-	printResults(total_xacts, nclients, threads, nthreads,
-				 total_time, conn_total_time, total_latencies, total_sqlats,
-				 throttle_lag, throttle_lag_max, throttle_latency_skipped,
-				 latency_late);
+	printResults(threads, &stats, total_time, conn_total_time, latency_late);
=20
 	return 0;
 }
@@ -3593,13 +3516,8 @@ threadRun(void *arg)
 	int64		thread_start =3D INSTR_TIME_GET_MICROSEC(thread->start_time);
 	int64		last_report =3D thread_start;
 	int64		next_report =3D last_report + (int64) progress * 1000000;
-	int64		last_count =3D 0,
-				last_lats =3D 0,
-				last_sqlats =3D 0,
-				last_lags =3D 0,
-				last_skipped =3D 0;
-
-	AggVals		aggs;
+	StatsData	last,
+				aggs;
=20
 	/*
 	 * Initialize throttling rate target for all of the thread's clients.  It
@@ -3609,8 +3527,6 @@ threadRun(void *arg)
 	 */
 	INSTR_TIME_SET_CURRENT(start);
 	thread->throttle_trigger =3D INSTR_TIME_GET_MICROSEC(start);
-	thread->throttle_lag =3D 0;
-	thread->throttle_lag_max =3D 0;
=20
 	INSTR_TIME_SET_ZERO(thread->conn_time);
=20
@@ -3647,7 +3563,8 @@ threadRun(void *arg)
 	INSTR_TIME_SET_CURRENT(thread->conn_time);
 	INSTR_TIME_SUBTRACT(thread->conn_time, thread->start_time);
=20
-	agg_vals_init(&aggs, thread->start_time);
+	initStats(&aggs, INSTR_TIME_GET_DOUBLE(thread->start_time));
+	last =3D aggs;
=20
 	/* send start up queries in async manner */
 	for (i =3D 0; i < nstate; i++)
@@ -3661,7 +3578,7 @@ threadRun(void *arg)
 		if (debug)
 			fprintf(stderr, "client %d executing script \"%s\"\n", st->id,
 					sql_script[st->use_file].name);
-		if (!doCustom(thread, st, &thread->conn_time, logfile, &aggs))
+		if (!doCustom(thread, st, logfile, &aggs))
 			remains--;			/* I've aborted */
=20
 		if (st->ecnt > prev_ecnt && commands[st->state]->type =3D=3D META_COMMAN=
D)
@@ -3800,7 +3717,7 @@ threadRun(void *arg)
 			if (st->con && (FD_ISSET(PQsocket(st->con), &input_mask)
 							|| commands[st->state]->type =3D=3D META_COMMAND))
 			{
-				if (!doCustom(thread, st, &thread->conn_time, logfile, &aggs))
+				if (!doCustom(thread, st, logfile, &aggs))
 					remains--;	/* I've aborted */
 			}
=20
@@ -3825,11 +3742,7 @@ threadRun(void *arg)
 			if (now >=3D next_report)
 			{
 				/* generate and show report */
-				int64		count =3D 0,
-							lats =3D 0,
-							sqlats =3D 0,
-							lags =3D 0,
-							skipped =3D 0;
+				StatsData	cur;
 				int64		run =3D now - last_report;
 				double		tps,
 							total_run,
@@ -3850,25 +3763,24 @@ threadRun(void *arg)
 				 * (If a read from a 64-bit integer is not atomic, you might
 				 * get a "torn" read and completely bogus latencies though!)
 				 */
-				for (i =3D 0; i < progress_nclients; i++)
+				initStats(&cur, 0.0);
+				for (i =3D 0; i < nthreads; i++)
 				{
-					count +=3D state[i].cnt;
-					lats +=3D state[i].txn_latencies;
-					sqlats +=3D state[i].txn_sqlats;
-				}
-
-				for (i =3D 0; i < progress_nthreads; i++)
-				{
-					skipped +=3D thread[i].throttle_latency_skipped;
-					lags +=3D thread[i].throttle_lag;
+					mergeSimpleStats(&cur.latency, &thread[i].stats.latency);
+					mergeSimpleStats(&cur.lag, &thread[i].stats.lag);
+					cur.cnt +=3D thread[i].stats.cnt;
+					cur.skipped +=3D thread[i].stats.skipped;
 				}
=20
 				total_run =3D (now - thread_start) / 1000000.0;
-				tps =3D 1000000.0 * (count - last_count) / run;
-				latency =3D 0.001 * (lats - last_lats) / (count - last_count);
-				sqlat =3D 1.0 * (sqlats - last_sqlats) / (count - last_count);
+				tps =3D 1000000.0 * (cur.cnt - last.cnt) / run;
+				latency =3D 0.001 * (cur.latency.sum - last.latency.sum) /
+					(cur.cnt - last.cnt);
+				sqlat =3D 1.0 * (cur.latency.sum2 - last.latency.sum2)
+					/ (cur.cnt - last.cnt);
 				stdev =3D 0.001 * sqrt(sqlat - 1000000.0 * latency * latency);
-				lag =3D 0.001 * (lags - last_lags) / (count - last_count);
+				lag =3D 0.001 * (cur.lag.sum - last.lag.sum) /
+					(cur.cnt - last.cnt);
=20
 				if (progress_timestamp)
 					sprintf(tbuf, "%.03f s",
@@ -3885,16 +3797,12 @@ threadRun(void *arg)
 					fprintf(stderr, ", lag %.3f ms", lag);
 					if (latency_limit)
 						fprintf(stderr, ", " INT64_FORMAT " skipped",
-								skipped - last_skipped);
+								cur.skipped - last.skipped);
 				}
 				fprintf(stderr, "\n");
=20
-				last_count =3D count;
-				last_lats =3D lats;
-				last_sqlats =3D sqlats;
-				last_lags =3D lags;
+				last =3D cur;
 				last_report =3D now;
-				last_skipped =3D skipped;
=20
 				/*
 				 * Ensure that the next report is in the future, in case

--sm4nu43k4a2Rpi4c
Content-Type: text/plain
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
MIME-Version: 1.0


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

--sm4nu43k4a2Rpi4c--