Wrong result with pgbench -C option?

Hi,

I ran pgbench with -C option. Here is an output.

% pgbench -C  -c 10 -t 100  bench
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
number of clients: 10
number of transactions per client: 100
number of transactions actually processed: 1000/1000
tps = 83.209663 (including connections establishing)
tps = 83.209663 (excluding connections establishing)

The first tps was equal to the second tps. I think it is wrong because
pgbench with -C option connects per transaction.

The attached patch calculates total connection time. Here is an output
with revised pgbench.

% ./pgbench -C  -c 10 -t 100  bench
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
number of clients: 10
number of transactions per client: 100
number of transactions actually processed: 1000/1000
tps = 108.410991 (including connections establishing)
tps = 228.657561 (excluding connections establishing)

Regards,
--
Yoshiyuki Asaba
y-asaba@sraoss.co.jp
Index: pgbench.c
===================================================================
RCS file: /projects/cvsroot/pgsql/contrib/pgbench/pgbench.c,v
retrieving revision 1.74
diff -c -r1.74 pgbench.c
*** pgbench.c	15 Nov 2007 21:14:31 -0000	1.74
--- pgbench.c	6 Dec 2007 03:04:35 -0000
***************
*** 185,190 ****
--- 185,223 ----
  	"SELECT abalance FROM accounts WHERE aid = :aid;\n"
  };
  
+ /* Connection overhead time */
+ static struct timeval conn_total_time = {0, 0};
+ 
+ /* Calculate total time */
+ static void
+ addTime(struct timeval *t1, struct timeval *t2, struct timeval *result)
+ {
+ 	int sec = t1->tv_sec + t2->tv_sec;
+ 	int usec = t1->tv_usec + t2->tv_usec;
+ 	if (usec >= 1000000)
+ 	{
+ 		usec -= 1000000;
+ 		sec++;
+ 	}
+ 	result->tv_sec = sec;
+ 	result->tv_usec = usec;
+ }
+ 
+ /* Calculate time difference */
+ static void
+ diffTime(struct timeval *t1, struct timeval *t2, struct timeval *result)
+ {
+ 	int sec = t1->tv_sec - t2->tv_sec;
+ 	int usec = t1->tv_usec - t2->tv_usec;
+ 	if (usec < 0)
+ 	{
+ 		usec += 1000000;
+ 		sec--;
+ 	}
+ 	result->tv_sec = sec;
+ 	result->tv_usec = usec;
+ }
+ 
  static void
  usage(void)
  {
***************
*** 543,548 ****
--- 576,584 ----
  
  	if (st->con == NULL)
  	{
+ 		struct timeval t1, t2, t3;
+ 
+ 		gettimeofday(&t1, NULL);
  		if ((st->con = doConnect()) == NULL)
  		{
  			fprintf(stderr, "Client %d aborted in establishing connection.\n",
***************
*** 552,557 ****
--- 588,596 ----
  			st->con = NULL;
  			return;
  		}
+ 		gettimeofday(&t2, NULL);
+ 		diffTime(&t2, &t1, &t3);
+ 		addTime(&conn_total_time, &t3, &conn_total_time);
  	}
  
  	if (use_log && st->state == 0)
***************
*** 1162,1169 ****
  static void
  printResults(
  			 int ttype, CState * state,
! 			 struct timeval * tv1, struct timeval * tv2,
! 			 struct timeval * tv3)
  {
  	double		t1,
  				t2;
--- 1201,1207 ----
  static void
  printResults(
  			 int ttype, CState * state,
! 			 struct timeval * start_time, struct timeval * end_time)
  {
  	double		t1,
  				t2;
***************
*** 1174,1183 ****
  	for (i = 0; i < nclients; i++)
  		normal_xacts += state[i].cnt;
  
! 	t1 = (tv3->tv_sec - tv1->tv_sec) * 1000000.0 + (tv3->tv_usec - tv1->tv_usec);
  	t1 = normal_xacts * 1000000.0 / t1;
  
! 	t2 = (tv3->tv_sec - tv2->tv_sec) * 1000000.0 + (tv3->tv_usec - tv2->tv_usec);
  	t2 = normal_xacts * 1000000.0 / t2;
  
  	if (ttype == 0)
--- 1212,1222 ----
  	for (i = 0; i < nclients; i++)
  		normal_xacts += state[i].cnt;
  
! 	t1 = (end_time->tv_sec - start_time->tv_sec) * 1000000.0 + (end_time->tv_usec - start_time->tv_usec);
  	t1 = normal_xacts * 1000000.0 / t1;
  
! 	t2 = (end_time->tv_sec - start_time->tv_sec - conn_total_time.tv_sec) * 1000000.0 +
! 		(end_time->tv_usec - start_time->tv_usec - conn_total_time.tv_usec);
  	t2 = normal_xacts * 1000000.0 / t2;
  
  	if (ttype == 0)
***************
*** 1213,1222 ****
  
  	CState	   *state;			/* status of clients */
  
! 	struct timeval tv1;			/* start up time */
! 	struct timeval tv2;			/* after establishing all connections to the
! 								 * backend */
! 	struct timeval tv3;			/* end time */
  
  	int			i;
  
--- 1252,1259 ----
  
  	CState	   *state;			/* status of clients */
  
! 	struct timeval start_time;			/* start up time */
! 	struct timeval end_time;			/* end time */
  
  	int			i;
  
***************
*** 1533,1546 ****
  	PQfinish(con);
  
  	/* set random seed */
! 	gettimeofday(&tv1, NULL);
! 	srandom((unsigned int) tv1.tv_usec);
  
  	/* get start up time */
! 	gettimeofday(&tv1, NULL);
  
  	if (is_connect == 0)
  	{
  		/* make connections to the database */
  		for (i = 0; i < nclients; i++)
  		{
--- 1570,1585 ----
  	PQfinish(con);
  
  	/* set random seed */
! 	gettimeofday(&start_time, NULL);
! 	srandom((unsigned int) start_time.tv_usec);
  
  	/* get start up time */
! 	gettimeofday(&start_time, NULL);
  
  	if (is_connect == 0)
  	{
+ 		struct timeval t, now;
+ 
  		/* make connections to the database */
  		for (i = 0; i < nclients; i++)
  		{
***************
*** 1548,1558 ****
  			if ((state[i].con = doConnect()) == NULL)
  				exit(1);
  		}
  	}
  
- 	/* time after connections set up */
- 	gettimeofday(&tv2, NULL);
- 
  	/* process bultin SQL scripts */
  	switch (ttype)
  	{
--- 1587,1598 ----
  			if ((state[i].con = doConnect()) == NULL)
  				exit(1);
  		}
+ 		/* time after connections set up */
+ 		gettimeofday(&now, NULL);
+ 		diffTime(&now, &start_time, &t);
+ 		addTime(&conn_total_time, &t, &conn_total_time);
  	}
  
  	/* process bultin SQL scripts */
  	switch (ttype)
  	{
***************
*** 1599,1606 ****
  		{						/* all done ? */
  			disconnect_all(state);
  			/* get end time */
! 			gettimeofday(&tv3, NULL);
! 			printResults(ttype, state, &tv1, &tv2, &tv3);
  			if (LOGFILE)
  				fclose(LOGFILE);
  			exit(0);
--- 1639,1646 ----
  		{						/* all done ? */
  			disconnect_all(state);
  			/* get end time */
! 			gettimeofday(&end_time, NULL);
! 			printResults(ttype, state, &start_time, &end_time);
  			if (LOGFILE)
  				fclose(LOGFILE);
  			exit(0);