Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commit8c9dd69

Browse files
committed
Change the way latency is calculated with pgbench --rate option.
The reported latency values now include the "schedule lag" time, that is,the time between the transaction's scheduled start time and the time itactually started. This relates better to a model where requests arrive at acertain rate, and we are interested in the response time to the end user orapplication, rather than the response time of the database itself.Also, when --rate is used, include the schedule lag time in the log output.The --rate option is new in 9.4, so backpatch to 9.4. It seems better tomake this change in 9.4, while we're still in the beta period, than ship a9.4 version that calculates the values differently than 9.5.
1 parent958a828 commit8c9dd69

File tree

2 files changed

+146
-77
lines changed

2 files changed

+146
-77
lines changed

‎contrib/pgbench/pgbench.c

Lines changed: 114 additions & 50 deletions
Original file line numberDiff line numberDiff line change
@@ -204,10 +204,10 @@ typedef struct
204204
* sent */
205205
intsleeping;/* 1 indicates that the client is napping */
206206
boolthrottling;/* whether nap is for throttling */
207-
int64until;/* napping until (usec) */
208207
Variable*variables;/* array of variable definitions */
209208
intnvariables;
210-
instr_timetxn_begin;/* used for measuring transaction latencies */
209+
int64txn_scheduled;/* scheduled start time of transaction (usec) */
210+
instr_timetxn_begin;/* used for measuring schedule lag times */
211211
instr_timestmt_begin;/* used for measuring statement latencies */
212212
int64txn_latencies;/* cumulated latencies */
213213
int64txn_sqlats;/* cumulated square latencies */
@@ -278,12 +278,17 @@ typedef struct
278278

279279
longstart_time;/* when does the interval start */
280280
intcnt;/* number of transactions */
281-
doublemin_duration;/* min/max durations */
282-
doublemax_duration;
283-
doublesum;/* sum(duration), sum(duration^2) - for
281+
282+
doublemin_latency;/* min/max latencies */
283+
doublemax_latency;
284+
doublesum_latency;/* sum(latency), sum(latency^2) - for
284285
* estimates */
285-
doublesum2;
286+
doublesum2_latency;
286287

288+
doublemin_lag;
289+
doublemax_lag;
290+
doublesum_lag;/* sum(lag) */
291+
doublesum2_lag;/* sum(lag*lag) */
287292
}AggVals;
288293

289294
staticCommand**sql_files[MAX_FILES];/* SQL script files */
@@ -892,12 +897,18 @@ agg_vals_init(AggVals *aggs, instr_time start)
892897
{
893898
/* basic counters */
894899
aggs->cnt=0;/* number of transactions */
895-
aggs->sum=0;/* SUM(duration) */
896-
aggs->sum2=0;/* SUM(duration*duration) */
900+
aggs->sum_latency=0;/* SUM(latency) */
901+
aggs->sum2_latency=0;/* SUM(latency*latency) */
897902

898903
/* min and max transaction duration */
899-
aggs->min_duration=0;
900-
aggs->max_duration=0;
904+
aggs->min_latency=0;
905+
aggs->max_latency=0;
906+
907+
/* schedule lag counters */
908+
aggs->sum_lag=0;
909+
aggs->sum2_lag=0;
910+
aggs->min_lag=0;
911+
aggs->max_lag=0;
901912

902913
/* start of the current interval */
903914
aggs->start_time=INSTR_TIME_GET_DOUBLE(start);
@@ -940,7 +951,7 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
940951

941952
thread->throttle_trigger+=wait;
942953

943-
st->until=thread->throttle_trigger;
954+
st->txn_scheduled=thread->throttle_trigger;
944955
st->sleeping=1;
945956
st->throttling= true;
946957
st->is_throttled= true;
@@ -956,13 +967,13 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
956967

957968
INSTR_TIME_SET_CURRENT(now);
958969
now_us=INSTR_TIME_GET_MICROSEC(now);
959-
if (st->until <=now_us)
970+
if (st->txn_scheduled <=now_us)
960971
{
961972
st->sleeping=0;/* Done sleeping, go ahead with next command */
962973
if (st->throttling)
963974
{
964975
/* Measure lag of throttled transaction relative to target */
965-
int64lag=now_us-st->until;
976+
int64lag=now_us-st->txn_scheduled;
966977

967978
thread->throttle_lag+=lag;
968979
if (lag>thread->throttle_lag_max)
@@ -976,6 +987,11 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
976987

977988
if (st->listen)
978989
{/* are we receiver? */
990+
instr_timenow;
991+
boolnow_valid= false;
992+
993+
INSTR_TIME_SET_ZERO(now);/* initialize to keep compiler quiet */
994+
979995
if (commands[st->state]->type==SQL_COMMAND)
980996
{
981997
if (debug)
@@ -995,10 +1011,13 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
9951011
*/
9961012
if (is_latencies)
9971013
{
998-
instr_timenow;
9991014
intcnum=commands[st->state]->command_num;
10001015

1001-
INSTR_TIME_SET_CURRENT(now);
1016+
if (!now_valid)
1017+
{
1018+
INSTR_TIME_SET_CURRENT(now);
1019+
now_valid= true;
1020+
}
10021021
INSTR_TIME_ACCUM_DIFF(thread->exec_elapsed[cnum],
10031022
now,st->stmt_begin);
10041023
thread->exec_count[cnum]++;
@@ -1007,12 +1026,16 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10071026
/* transaction finished: record latency under progress or throttling */
10081027
if ((progress||throttle_delay)&&commands[st->state+1]==NULL)
10091028
{
1010-
instr_timediff;
10111029
int64latency;
10121030

1013-
INSTR_TIME_SET_CURRENT(diff);
1014-
INSTR_TIME_SUBTRACT(diff,st->txn_begin);
1015-
latency=INSTR_TIME_GET_MICROSEC(diff);
1031+
if (!now_valid)
1032+
{
1033+
INSTR_TIME_SET_CURRENT(now);
1034+
now_valid= true;
1035+
}
1036+
1037+
latency=INSTR_TIME_GET_MICROSEC(now)-st->txn_scheduled;
1038+
10161039
st->txn_latencies+=latency;
10171040

10181041
/*
@@ -1030,9 +1053,8 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10301053
*/
10311054
if (logfile&&commands[st->state+1]==NULL)
10321055
{
1033-
instr_timenow;
1034-
instr_timediff;
1035-
doubleusec;
1056+
doublelag;
1057+
doublelatency;
10361058

10371059
/*
10381060
* write the log entry if this row belongs to the random sample,
@@ -1041,10 +1063,13 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10411063
if (sample_rate==0.0||
10421064
pg_erand48(thread->random_state) <=sample_rate)
10431065
{
1044-
INSTR_TIME_SET_CURRENT(now);
1045-
diff=now;
1046-
INSTR_TIME_SUBTRACT(diff,st->txn_begin);
1047-
usec= (double)INSTR_TIME_GET_MICROSEC(diff);
1066+
if (!now_valid)
1067+
{
1068+
INSTR_TIME_SET_CURRENT(now);
1069+
now_valid= true;
1070+
}
1071+
latency= (double) (INSTR_TIME_GET_MICROSEC(now)-st->txn_scheduled);
1072+
lag= (double) (INSTR_TIME_GET_MICROSEC(st->txn_begin)-st->txn_scheduled);
10481073

10491074
/* should we aggregate the results or not? */
10501075
if (agg_interval>0)
@@ -1056,15 +1081,27 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10561081
if (agg->start_time+agg_interval >=INSTR_TIME_GET_DOUBLE(now))
10571082
{
10581083
agg->cnt+=1;
1059-
agg->sum+=usec;
1060-
agg->sum2+=usec*usec;
1084+
agg->sum_latency+=latency;
1085+
agg->sum2_latency+=latency*latency;
10611086

10621087
/* first in this aggregation interval */
1063-
if ((agg->cnt==1)|| (usec<agg->min_duration))
1064-
agg->min_duration=usec;
1088+
if ((agg->cnt==1)|| (latency<agg->min_latency))
1089+
agg->min_latency=latency;
1090+
1091+
if ((agg->cnt==1)|| (latency>agg->max_latency))
1092+
agg->max_latency=latency;
1093+
1094+
/* and the same for schedule lag */
1095+
if (throttle_delay)
1096+
{
1097+
agg->sum_lag+=lag;
1098+
agg->sum2_lag+=lag*lag;
10651099

1066-
if ((agg->cnt==1)|| (usec>agg->max_duration))
1067-
agg->max_duration=usec;
1100+
if ((agg->cnt==1)|| (lag<agg->min_lag))
1101+
agg->min_lag=lag;
1102+
if ((agg->cnt==1)|| (lag>agg->max_lag))
1103+
agg->max_lag=lag;
1104+
}
10681105
}
10691106
else
10701107
{
@@ -1080,34 +1117,49 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10801117
* ifdef in usage), so we don't need to handle
10811118
* this in a special way (see below).
10821119
*/
1083-
fprintf(logfile,"%ld %d %.0f %.0f %.0f %.0f\n",
1120+
fprintf(logfile,"%ld %d %.0f %.0f %.0f %.0f",
10841121
agg->start_time,
10851122
agg->cnt,
1086-
agg->sum,
1087-
agg->sum2,
1088-
agg->min_duration,
1089-
agg->max_duration);
1123+
agg->sum_latency,
1124+
agg->sum2_latency,
1125+
agg->min_latency,
1126+
agg->max_latency);
1127+
if (throttle_delay)
1128+
fprintf(logfile," %.0f %.0f %.0f %.0f",
1129+
agg->sum_lag,
1130+
agg->sum2_lag,
1131+
agg->min_lag,
1132+
agg->max_lag);
1133+
fputc('\n',logfile);
10901134

10911135
/* move to the next inteval */
10921136
agg->start_time=agg->start_time+agg_interval;
10931137

10941138
/* reset for "no transaction" intervals */
10951139
agg->cnt=0;
1096-
agg->min_duration=0;
1097-
agg->max_duration=0;
1098-
agg->sum=0;
1099-
agg->sum2=0;
1140+
agg->min_latency=0;
1141+
agg->max_latency=0;
1142+
agg->sum_latency=0;
1143+
agg->sum2_latency=0;
1144+
agg->min_lag=0;
1145+
agg->max_lag=0;
1146+
agg->sum_lag=0;
1147+
agg->sum2_lag=0;
11001148
}
11011149

11021150
/*
11031151
* and now update the reset values (include the
11041152
* current)
11051153
*/
11061154
agg->cnt=1;
1107-
agg->min_duration=usec;
1108-
agg->max_duration=usec;
1109-
agg->sum=usec;
1110-
agg->sum2=usec*usec;
1155+
agg->min_latency=latency;
1156+
agg->max_latency=latency;
1157+
agg->sum_latency=latency;
1158+
agg->sum2_latency=latency*latency;
1159+
agg->min_lag=lag;
1160+
agg->max_lag=lag;
1161+
agg->sum_lag=lag;
1162+
agg->sum2_lag=lag*lag;
11111163
}
11121164
}
11131165
else
@@ -1119,18 +1171,21 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11191171
* This is more than we really ought to know about
11201172
* instr_time
11211173
*/
1122-
fprintf(logfile,"%d %d %.0f %d %ld %ld\n",
1123-
st->id,st->cnt,usec,st->use_file,
1174+
fprintf(logfile,"%d %d %.0f %d %ld %ld",
1175+
st->id,st->cnt,latency,st->use_file,
11241176
(long)now.tv_sec, (long)now.tv_usec);
11251177
#else
11261178

11271179
/*
11281180
* On Windows, instr_time doesn't provide a timestamp
11291181
* anyway
11301182
*/
1131-
fprintf(logfile,"%d %d %.0f %d 0 0\n",
1183+
fprintf(logfile,"%d %d %.0f %d 0 0",
11321184
st->id,st->cnt,usec,st->use_file);
11331185
#endif
1186+
if (throttle_delay)
1187+
fprintf(logfile," %.0f",lag);
1188+
fputc('\n',logfile);
11341189
}
11351190
}
11361191
}
@@ -1219,8 +1274,17 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
12191274

12201275
/* Record transaction start time under logging, progress or throttling */
12211276
if ((logfile||progress||throttle_delay)&&st->state==0)
1277+
{
12221278
INSTR_TIME_SET_CURRENT(st->txn_begin);
12231279

1280+
/*
1281+
* When not throttling, this is also the transaction's scheduled start
1282+
* time.
1283+
*/
1284+
if (!throttle_delay)
1285+
st->txn_scheduled=INSTR_TIME_GET_MICROSEC(st->txn_begin);
1286+
}
1287+
12241288
/* Record statement start time if per-command latencies are requested */
12251289
if (is_latencies)
12261290
INSTR_TIME_SET_CURRENT(st->stmt_begin);
@@ -1489,7 +1553,7 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
14891553
usec *=1000000;
14901554

14911555
INSTR_TIME_SET_CURRENT(now);
1492-
st->until=INSTR_TIME_GET_MICROSEC(now)+usec;
1556+
st->txn_scheduled=INSTR_TIME_GET_MICROSEC(now)+usec;
14931557
st->sleeping=1;
14941558

14951559
st->listen=1;
@@ -3108,7 +3172,7 @@ threadRun(void *arg)
31083172
now_usec=INSTR_TIME_GET_MICROSEC(now);
31093173
}
31103174

3111-
this_usec=st->until-now_usec;
3175+
this_usec=st->txn_scheduled-now_usec;
31123176
if (min_usec>this_usec)
31133177
min_usec=this_usec;
31143178
}

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp