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] + ); + } + } }