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

Commit02e3bcc

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 parent75717ce commit02e3bcc

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
@@ -210,10 +210,10 @@ typedef struct
210210
* sent */
211211
intsleeping;/* 1 indicates that the client is napping */
212212
boolthrottling;/* whether nap is for throttling */
213-
int64until;/* napping until (usec) */
214213
Variable*variables;/* array of variable definitions */
215214
intnvariables;
216-
instr_timetxn_begin;/* used for measuring transaction latencies */
215+
int64txn_scheduled;/* scheduled start time of transaction (usec) */
216+
instr_timetxn_begin;/* used for measuring schedule lag times */
217217
instr_timestmt_begin;/* used for measuring statement latencies */
218218
int64txn_latencies;/* cumulated latencies */
219219
int64txn_sqlats;/* cumulated square latencies */
@@ -284,12 +284,17 @@ typedef struct
284284

285285
longstart_time;/* when does the interval start */
286286
intcnt;/* number of transactions */
287-
doublemin_duration;/* min/max durations */
288-
doublemax_duration;
289-
doublesum;/* sum(duration), sum(duration^2) - for
287+
288+
doublemin_latency;/* min/max latencies */
289+
doublemax_latency;
290+
doublesum_latency;/* sum(latency), sum(latency^2) - for
290291
* estimates */
291-
doublesum2;
292+
doublesum2_latency;
292293

294+
doublemin_lag;
295+
doublemax_lag;
296+
doublesum_lag;/* sum(lag) */
297+
doublesum2_lag;/* sum(lag*lag) */
293298
}AggVals;
294299

295300
staticCommand**sql_files[MAX_FILES];/* SQL script files */
@@ -968,12 +973,18 @@ agg_vals_init(AggVals *aggs, instr_time start)
968973
{
969974
/* basic counters */
970975
aggs->cnt=0;/* number of transactions */
971-
aggs->sum=0;/* SUM(duration) */
972-
aggs->sum2=0;/* SUM(duration*duration) */
976+
aggs->sum_latency=0;/* SUM(latency) */
977+
aggs->sum2_latency=0;/* SUM(latency*latency) */
973978

974979
/* min and max transaction duration */
975-
aggs->min_duration=0;
976-
aggs->max_duration=0;
980+
aggs->min_latency=0;
981+
aggs->max_latency=0;
982+
983+
/* schedule lag counters */
984+
aggs->sum_lag=0;
985+
aggs->sum2_lag=0;
986+
aggs->min_lag=0;
987+
aggs->max_lag=0;
977988

978989
/* start of the current interval */
979990
aggs->start_time=INSTR_TIME_GET_DOUBLE(start);
@@ -1016,7 +1027,7 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10161027

10171028
thread->throttle_trigger+=wait;
10181029

1019-
st->until=thread->throttle_trigger;
1030+
st->txn_scheduled=thread->throttle_trigger;
10201031
st->sleeping=1;
10211032
st->throttling= true;
10221033
st->is_throttled= true;
@@ -1032,13 +1043,13 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10321043

10331044
INSTR_TIME_SET_CURRENT(now);
10341045
now_us=INSTR_TIME_GET_MICROSEC(now);
1035-
if (st->until <=now_us)
1046+
if (st->txn_scheduled <=now_us)
10361047
{
10371048
st->sleeping=0;/* Done sleeping, go ahead with next command */
10381049
if (st->throttling)
10391050
{
10401051
/* Measure lag of throttled transaction relative to target */
1041-
int64lag=now_us-st->until;
1052+
int64lag=now_us-st->txn_scheduled;
10421053

10431054
thread->throttle_lag+=lag;
10441055
if (lag>thread->throttle_lag_max)
@@ -1052,6 +1063,11 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10521063

10531064
if (st->listen)
10541065
{/* are we receiver? */
1066+
instr_timenow;
1067+
boolnow_valid= false;
1068+
1069+
INSTR_TIME_SET_ZERO(now);/* initialize to keep compiler quiet */
1070+
10551071
if (commands[st->state]->type==SQL_COMMAND)
10561072
{
10571073
if (debug)
@@ -1071,10 +1087,13 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10711087
*/
10721088
if (is_latencies)
10731089
{
1074-
instr_timenow;
10751090
intcnum=commands[st->state]->command_num;
10761091

1077-
INSTR_TIME_SET_CURRENT(now);
1092+
if (!now_valid)
1093+
{
1094+
INSTR_TIME_SET_CURRENT(now);
1095+
now_valid= true;
1096+
}
10781097
INSTR_TIME_ACCUM_DIFF(thread->exec_elapsed[cnum],
10791098
now,st->stmt_begin);
10801099
thread->exec_count[cnum]++;
@@ -1083,12 +1102,16 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10831102
/* transaction finished: record latency under progress or throttling */
10841103
if ((progress||throttle_delay)&&commands[st->state+1]==NULL)
10851104
{
1086-
instr_timediff;
10871105
int64latency;
10881106

1089-
INSTR_TIME_SET_CURRENT(diff);
1090-
INSTR_TIME_SUBTRACT(diff,st->txn_begin);
1091-
latency=INSTR_TIME_GET_MICROSEC(diff);
1107+
if (!now_valid)
1108+
{
1109+
INSTR_TIME_SET_CURRENT(now);
1110+
now_valid= true;
1111+
}
1112+
1113+
latency=INSTR_TIME_GET_MICROSEC(now)-st->txn_scheduled;
1114+
10921115
st->txn_latencies+=latency;
10931116

10941117
/*
@@ -1106,9 +1129,8 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11061129
*/
11071130
if (logfile&&commands[st->state+1]==NULL)
11081131
{
1109-
instr_timenow;
1110-
instr_timediff;
1111-
doubleusec;
1132+
doublelag;
1133+
doublelatency;
11121134

11131135
/*
11141136
* write the log entry if this row belongs to the random sample,
@@ -1117,10 +1139,13 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11171139
if (sample_rate==0.0||
11181140
pg_erand48(thread->random_state) <=sample_rate)
11191141
{
1120-
INSTR_TIME_SET_CURRENT(now);
1121-
diff=now;
1122-
INSTR_TIME_SUBTRACT(diff,st->txn_begin);
1123-
usec= (double)INSTR_TIME_GET_MICROSEC(diff);
1142+
if (!now_valid)
1143+
{
1144+
INSTR_TIME_SET_CURRENT(now);
1145+
now_valid= true;
1146+
}
1147+
latency= (double) (INSTR_TIME_GET_MICROSEC(now)-st->txn_scheduled);
1148+
lag= (double) (INSTR_TIME_GET_MICROSEC(st->txn_begin)-st->txn_scheduled);
11241149

11251150
/* should we aggregate the results or not? */
11261151
if (agg_interval>0)
@@ -1132,15 +1157,27 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11321157
if (agg->start_time+agg_interval >=INSTR_TIME_GET_DOUBLE(now))
11331158
{
11341159
agg->cnt+=1;
1135-
agg->sum+=usec;
1136-
agg->sum2+=usec*usec;
1160+
agg->sum_latency+=latency;
1161+
agg->sum2_latency+=latency*latency;
11371162

11381163
/* first in this aggregation interval */
1139-
if ((agg->cnt==1)|| (usec<agg->min_duration))
1140-
agg->min_duration=usec;
1164+
if ((agg->cnt==1)|| (latency<agg->min_latency))
1165+
agg->min_latency=latency;
1166+
1167+
if ((agg->cnt==1)|| (latency>agg->max_latency))
1168+
agg->max_latency=latency;
1169+
1170+
/* and the same for schedule lag */
1171+
if (throttle_delay)
1172+
{
1173+
agg->sum_lag+=lag;
1174+
agg->sum2_lag+=lag*lag;
11411175

1142-
if ((agg->cnt==1)|| (usec>agg->max_duration))
1143-
agg->max_duration=usec;
1176+
if ((agg->cnt==1)|| (lag<agg->min_lag))
1177+
agg->min_lag=lag;
1178+
if ((agg->cnt==1)|| (lag>agg->max_lag))
1179+
agg->max_lag=lag;
1180+
}
11441181
}
11451182
else
11461183
{
@@ -1156,34 +1193,49 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11561193
* ifdef in usage), so we don't need to handle
11571194
* this in a special way (see below).
11581195
*/
1159-
fprintf(logfile,"%ld %d %.0f %.0f %.0f %.0f\n",
1196+
fprintf(logfile,"%ld %d %.0f %.0f %.0f %.0f",
11601197
agg->start_time,
11611198
agg->cnt,
1162-
agg->sum,
1163-
agg->sum2,
1164-
agg->min_duration,
1165-
agg->max_duration);
1199+
agg->sum_latency,
1200+
agg->sum2_latency,
1201+
agg->min_latency,
1202+
agg->max_latency);
1203+
if (throttle_delay)
1204+
fprintf(logfile," %.0f %.0f %.0f %.0f",
1205+
agg->sum_lag,
1206+
agg->sum2_lag,
1207+
agg->min_lag,
1208+
agg->max_lag);
1209+
fputc('\n',logfile);
11661210

11671211
/* move to the next inteval */
11681212
agg->start_time=agg->start_time+agg_interval;
11691213

11701214
/* reset for "no transaction" intervals */
11711215
agg->cnt=0;
1172-
agg->min_duration=0;
1173-
agg->max_duration=0;
1174-
agg->sum=0;
1175-
agg->sum2=0;
1216+
agg->min_latency=0;
1217+
agg->max_latency=0;
1218+
agg->sum_latency=0;
1219+
agg->sum2_latency=0;
1220+
agg->min_lag=0;
1221+
agg->max_lag=0;
1222+
agg->sum_lag=0;
1223+
agg->sum2_lag=0;
11761224
}
11771225

11781226
/*
11791227
* and now update the reset values (include the
11801228
* current)
11811229
*/
11821230
agg->cnt=1;
1183-
agg->min_duration=usec;
1184-
agg->max_duration=usec;
1185-
agg->sum=usec;
1186-
agg->sum2=usec*usec;
1231+
agg->min_latency=latency;
1232+
agg->max_latency=latency;
1233+
agg->sum_latency=latency;
1234+
agg->sum2_latency=latency*latency;
1235+
agg->min_lag=lag;
1236+
agg->max_lag=lag;
1237+
agg->sum_lag=lag;
1238+
agg->sum2_lag=lag*lag;
11871239
}
11881240
}
11891241
else
@@ -1195,18 +1247,21 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11951247
* This is more than we really ought to know about
11961248
* instr_time
11971249
*/
1198-
fprintf(logfile,"%d %d %.0f %d %ld %ld\n",
1199-
st->id,st->cnt,usec,st->use_file,
1250+
fprintf(logfile,"%d %d %.0f %d %ld %ld",
1251+
st->id,st->cnt,latency,st->use_file,
12001252
(long)now.tv_sec, (long)now.tv_usec);
12011253
#else
12021254

12031255
/*
12041256
* On Windows, instr_time doesn't provide a timestamp
12051257
* anyway
12061258
*/
1207-
fprintf(logfile,"%d %d %.0f %d 0 0\n",
1259+
fprintf(logfile,"%d %d %.0f %d 0 0",
12081260
st->id,st->cnt,usec,st->use_file);
12091261
#endif
1262+
if (throttle_delay)
1263+
fprintf(logfile," %.0f",lag);
1264+
fputc('\n',logfile);
12101265
}
12111266
}
12121267
}
@@ -1295,8 +1350,17 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
12951350

12961351
/* Record transaction start time under logging, progress or throttling */
12971352
if ((logfile||progress||throttle_delay)&&st->state==0)
1353+
{
12981354
INSTR_TIME_SET_CURRENT(st->txn_begin);
12991355

1356+
/*
1357+
* When not throttling, this is also the transaction's scheduled start
1358+
* time.
1359+
*/
1360+
if (!throttle_delay)
1361+
st->txn_scheduled=INSTR_TIME_GET_MICROSEC(st->txn_begin);
1362+
}
1363+
13001364
/* Record statement start time if per-command latencies are requested */
13011365
if (is_latencies)
13021366
INSTR_TIME_SET_CURRENT(st->stmt_begin);
@@ -1620,7 +1684,7 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
16201684
usec *=1000000;
16211685

16221686
INSTR_TIME_SET_CURRENT(now);
1623-
st->until=INSTR_TIME_GET_MICROSEC(now)+usec;
1687+
st->txn_scheduled=INSTR_TIME_GET_MICROSEC(now)+usec;
16241688
st->sleeping=1;
16251689

16261690
st->listen=1;
@@ -3309,7 +3373,7 @@ threadRun(void *arg)
33093373
now_usec=INSTR_TIME_GET_MICROSEC(now);
33103374
}
33113375

3312-
this_usec=st->until-now_usec;
3376+
this_usec=st->txn_scheduled-now_usec;
33133377
if (min_usec>this_usec)
33143378
min_usec=this_usec;
33153379
}

0 commit comments

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