pgbench_statementlatency.patch

diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c
index c830dee..ba63280 100644
*** a/contrib/pgbench/pgbench.c
--- b/contrib/pgbench/pgbench.c
*************** typedef struct
*** 172,177 ****
--- 172,178 ----
  	Variable   *variables;		/* array of variable definitions */
  	int			nvariables;
  	instr_time	txn_begin;		/* used for measuring latencies */
+ 	instr_time	stmt_begin;			/* used for measuring statement latencies */
  	int			use_file;		/* index in sql_files for this client */
  	bool		prepared[MAX_FILES];
  } CState;
*************** typedef struct
*** 219,224 ****
--- 220,227 ----
  	int			type;			/* command type (SQL_COMMAND or META_COMMAND) */
  	int			argc;			/* number of commands */
  	char	   *argv[MAX_ARGS]; /* command list */
+ 	double		elapsed;		/* total time spent executing this command */
+ 	int			cnt;			/* number of times executed */
  } Command;
  
  static Command **sql_files[MAX_FILES];	/* SQL script files */
*************** top:
*** 763,768 ****
--- 766,774 ----
  	{							/* are we receiver? */
  		if (commands[st->state]->type == SQL_COMMAND)
  		{
+ 			instr_time now;
+ 			instr_time diff;
+ 			
  			if (debug)
  				fprintf(stderr, "client %d receiving\n", st->id);
  			if (!PQconsumeInput(st->con))
*************** top:
*** 772,777 ****
--- 778,790 ----
  			}
  			if (PQisBusy(st->con))
  				return true;	/* don't have the whole result yet */
+ 				
+ 			/* Command finished, record the time it took */
+ 			INSTR_TIME_SET_CURRENT(now);
+ 			diff = now;
+ 			INSTR_TIME_SUBTRACT(diff, st->stmt_begin);
+ 			commands[st->state]->elapsed += (double) INSTR_TIME_GET_MICROSEC(diff);
+ 			++(commands[st->state]->cnt);
  		}
  
  		/*
*************** top:
*** 864,869 ****
--- 877,884 ----
  		const Command *command = commands[st->state];
  		int			r;
  
+ 		INSTR_TIME_SET_CURRENT(st->stmt_begin);
+ 
  		if (querymode == QUERY_SIMPLE)
  		{
  			char	   *sql;
*************** process_commands(char *buf)
*** 1380,1385 ****
--- 1395,1402 ----
  	}
  
  	my_commands->argc = 0;
+ 	my_commands->elapsed = 0.0;
+ 	my_commands->cnt = 0;
  
  	if (*p == '\\')
  	{
*************** printResults(int ttype, int normal_xacts
*** 1660,1665 ****
--- 1677,1683 ----
  				tps_include,
  				tps_exclude;
  	char	   *s;
+ 	int			i;
  
  	time_include = INSTR_TIME_GET_DOUBLE(total_time);
  	tps_include = normal_xacts / time_include;
*************** printResults(int ttype, int normal_xacts
*** 1694,1699 ****
--- 1712,1729 ----
  	}
  	printf("tps = %f (including connections establishing)\n", tps_include);
  	printf("tps = %f (excluding connections establishing)\n", tps_exclude);
+ 	
+ 	for(i=0; i < num_files; ++i) {
+ 		Command** command;
+ 		printf("command latencies (file %d)\n", i);
+ 		for(command = sql_files[i]; *command != NULL; ++command) {
+ 			if ((*command)->type == SQL_COMMAND)
+ 				printf("\t%f msec\t%s\n",
+ 					(*command)->elapsed / ((*command)->cnt * 1000.0),
+ 					(*command)->argv[0]
+ 				);
+ 		}
+ 	}
  }