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

Commit2d6c0f1

Browse files
committed
pgbench: Elaborate latency reporting.
Isolate transaction latency (elapsed time between submitting firstcommand and receiving response to last command) from client-side delayspertaining to the --rate schedule. Under --rate, report schedule lag asdefined in the documentation. Report latency standard deviationwhenever we collect the measurements to do so. All of these changesaffect --progress messages and the final report.Fabien COELHO, reviewed by Pavel Stehule.
1 parent8e00a38 commit2d6c0f1

File tree

2 files changed

+115
-18
lines changed

2 files changed

+115
-18
lines changed

‎contrib/pgbench/pgbench.c

Lines changed: 110 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -172,6 +172,7 @@ intagg_interval;/* log aggregates instead of individual
172172
* transactions */
173173
intprogress=0;/* thread progress report every this seconds */
174174
intprogress_nclients=0;/* number of clients for progress report */
175+
intprogress_nthreads=0;/* number of threads for progress report */
175176
boolis_connect;/* establish connection for each transaction */
176177
boolis_latencies;/* report per-command latencies */
177178
intmain_pid;/* main process id used in log filename */
@@ -214,6 +215,8 @@ typedef struct
214215
intnvariables;
215216
instr_timetxn_begin;/* used for measuring transaction latencies */
216217
instr_timestmt_begin;/* used for measuring statement latencies */
218+
int64txn_latencies;/* cumulated latencies */
219+
int64txn_sqlats;/* cumulated square latencies */
217220
boolis_throttled;/* whether transaction throttling is done */
218221
intuse_file;/* index in sql_files for this client */
219222
boolprepared[MAX_FILES];
@@ -243,6 +246,8 @@ typedef struct
243246
{
244247
instr_timeconn_time;
245248
intxacts;
249+
int64latencies;
250+
int64sqlats;
246251
int64throttle_lag;
247252
int64throttle_lag_max;
248253
}TResult;
@@ -1006,6 +1011,26 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10061011
thread->exec_count[cnum]++;
10071012
}
10081013

1014+
/* transaction finished: record latency under progress or throttling */
1015+
if ((progress||throttle_delay)&&commands[st->state+1]==NULL)
1016+
{
1017+
instr_timediff;
1018+
int64latency;
1019+
1020+
INSTR_TIME_SET_CURRENT(diff);
1021+
INSTR_TIME_SUBTRACT(diff,st->txn_begin);
1022+
latency=INSTR_TIME_GET_MICROSEC(diff);
1023+
st->txn_latencies+=latency;
1024+
/*
1025+
* XXX In a long benchmark run of high-latency transactions, this
1026+
* int64 addition eventually overflows. For example, 100 threads
1027+
* running 10s transactions will overflow it in 2.56 hours. With
1028+
* a more-typical OLTP workload of .1s transactions, overflow
1029+
* would take 256 hours.
1030+
*/
1031+
st->txn_sqlats+=latency*latency;
1032+
}
1033+
10091034
/*
10101035
* if transaction finished, record the time it took in the log
10111036
*/
@@ -1195,8 +1220,8 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11951220
gototop;
11961221
}
11971222

1198-
/* Record transaction start timeif logging is enabled */
1199-
if (logfile&&st->state==0)
1223+
/* Record transaction start timeunder logging, progress or throttling */
1224+
if ((logfile||progress||throttle_delay)&&st->state==0)
12001225
INSTR_TIME_SET_CURRENT(st->txn_begin);
12011226

12021227
/* Record statement start time if per-command latencies are requested */
@@ -2105,6 +2130,7 @@ static void
21052130
printResults(intttype,intnormal_xacts,intnclients,
21062131
TState*threads,intnthreads,
21072132
instr_timetotal_time,instr_timeconn_total_time,
2133+
int64total_latencies,int64total_sqlats,
21082134
int64throttle_lag,int64throttle_lag_max)
21092135
{
21102136
doubletime_include,
@@ -2144,6 +2170,22 @@ printResults(int ttype, int normal_xacts, int nclients,
21442170
normal_xacts);
21452171
}
21462172

2173+
if (throttle_delay||progress)
2174+
{
2175+
/* compute and show latency average and standard deviation */
2176+
doublelatency=0.001*total_latencies /normal_xacts;
2177+
doublesqlat= (double)total_sqlats /normal_xacts;
2178+
printf("latency average: %.3f ms\n"
2179+
"latency stddev: %.3f ms\n",
2180+
latency,0.001*sqrt(sqlat-1000000.0*latency*latency));
2181+
}
2182+
else
2183+
{
2184+
/* only an average latency computed from the duration is available */
2185+
printf("latency average: %.3f ms\n",
2186+
1000.0*duration*nclients /normal_xacts);
2187+
}
2188+
21472189
if (throttle_delay)
21482190
{
21492191
/*
@@ -2152,7 +2194,7 @@ printResults(int ttype, int normal_xacts, int nclients,
21522194
* transaction. The measured lag may be caused by thread/client load,
21532195
* the database load, or the Poisson throttling process.
21542196
*/
2155-
printf("averagerate limit schedule lag: %.3fms(max %.3f ms)\n",
2197+
printf("rate limit schedule lag:avg%.3f (max %.3f) ms\n",
21562198
0.001*throttle_lag /normal_xacts,0.001*throttle_lag_max);
21572199
}
21582200

@@ -2263,7 +2305,9 @@ main(int argc, char **argv)
22632305
instr_timestart_time;/* start up time */
22642306
instr_timetotal_time;
22652307
instr_timeconn_total_time;
2266-
inttotal_xacts;
2308+
inttotal_xacts=0;
2309+
int64total_latencies=0;
2310+
int64total_sqlats=0;
22672311
int64throttle_lag=0;
22682312
int64throttle_lag_max=0;
22692313

@@ -2617,6 +2661,7 @@ main(int argc, char **argv)
26172661
*/
26182662
main_pid= (int)getpid();
26192663
progress_nclients=nclients;
2664+
progress_nthreads=nthreads;
26202665

26212666
if (nclients>1)
26222667
{
@@ -2825,7 +2870,6 @@ main(int argc, char **argv)
28252870
}
28262871

28272872
/* wait for threads and accumulate results */
2828-
total_xacts=0;
28292873
INSTR_TIME_SET_ZERO(conn_total_time);
28302874
for (i=0;i<nthreads;i++)
28312875
{
@@ -2841,6 +2885,8 @@ main(int argc, char **argv)
28412885
TResult*r= (TResult*)ret;
28422886

28432887
total_xacts+=r->xacts;
2888+
total_latencies+=r->latencies;
2889+
total_sqlats+=r->sqlats;
28442890
throttle_lag+=r->throttle_lag;
28452891
if (r->throttle_lag_max>throttle_lag_max)
28462892
throttle_lag_max=r->throttle_lag_max;
@@ -2854,7 +2900,8 @@ main(int argc, char **argv)
28542900
INSTR_TIME_SET_CURRENT(total_time);
28552901
INSTR_TIME_SUBTRACT(total_time,start_time);
28562902
printResults(ttype,total_xacts,nclients,threads,nthreads,
2857-
total_time,conn_total_time,throttle_lag,throttle_lag_max);
2903+
total_time,conn_total_time,total_latencies,total_sqlats,
2904+
throttle_lag,throttle_lag_max);
28582905

28592906
return0;
28602907
}
@@ -2875,7 +2922,7 @@ threadRun(void *arg)
28752922
int64thread_start=INSTR_TIME_GET_MICROSEC(thread->start_time);
28762923
int64last_report=thread_start;
28772924
int64next_report=last_report+progress*1000000;
2878-
int64last_count=0;
2925+
int64last_count=0,last_lats=0,last_sqlats=0,last_lags=0;
28792926

28802927
AggValsaggs;
28812928

@@ -3075,21 +3122,40 @@ threadRun(void *arg)
30753122
if (now >=next_report)
30763123
{
30773124
/* generate and show report */
3078-
int64count=0;
3125+
int64count=0,lats=0,sqlats=0;
3126+
int64lags=thread->throttle_lag;
30793127
int64run=now-last_report;
3080-
doubletps,total_run,latency;
3128+
doubletps,total_run,latency,sqlat,stdev,lag;
30813129

30823130
for (i=0 ;i<nstate ;i++)
3131+
{
30833132
count+=state[i].cnt;
3133+
lats+=state[i].txn_latencies;
3134+
sqlats+=state[i].txn_sqlats;
3135+
}
30843136

30853137
total_run= (now-thread_start) /1000000.0;
30863138
tps=1000000.0* (count-last_count) /run;
3087-
latency=1000.0*nstate /tps;
3139+
latency=0.001* (lats-last_lats) / (count-last_count);
3140+
sqlat=1.0* (sqlats-last_sqlats) / (count-last_count);
3141+
stdev=0.001*sqrt(sqlat-1000000.0*latency*latency);
3142+
lag=0.001* (lags-last_lags) / (count-last_count);
30883143

3089-
fprintf(stderr,"progress %d: %.1f s, %.1f tps, %.3f ms lat\n",
3090-
thread->tid,total_run,tps,latency);
3144+
if (throttle_delay)
3145+
fprintf(stderr,
3146+
"progress %d: %.1f s, %.1f tps, "
3147+
"lat %.3f ms stddev %.3f, lag %.3f ms\n",
3148+
thread->tid,total_run,tps,latency,stdev,lag);
3149+
else
3150+
fprintf(stderr,
3151+
"progress %d: %.1f s, %.1f tps, "
3152+
"lat %.3f ms stddev %.3f\n",
3153+
thread->tid,total_run,tps,latency,stdev);
30913154

30923155
last_count=count;
3156+
last_lats=lats;
3157+
last_sqlats=sqlats;
3158+
last_lags=lags;
30933159
last_report=now;
30943160
next_report+=progress*1000000;
30953161
}
@@ -3105,21 +3171,42 @@ threadRun(void *arg)
31053171
if (now >=next_report)
31063172
{
31073173
/* generate and show report */
3108-
int64count=0;
3174+
int64count=0,lats=0,sqlats=0,lags=0;
31093175
int64run=now-last_report;
3110-
doubletps,total_run,latency;
3176+
doubletps,total_run,latency,sqlat,lag,stdev;
31113177

31123178
for (i=0 ;i<progress_nclients ;i++)
3179+
{
31133180
count+=state[i].cnt;
3181+
lats+=state[i].txn_latencies;
3182+
sqlats+=state[i].txn_sqlats;
3183+
}
3184+
3185+
for (i=0 ;i<progress_nthreads ;i++)
3186+
lags+=thread[i].throttle_lag;
31143187

31153188
total_run= (now-thread_start) /1000000.0;
31163189
tps=1000000.0* (count-last_count) /run;
3117-
latency=1000.0*progress_nclients /tps;
3190+
latency=0.001* (lats-last_lats) / (count-last_count);
3191+
sqlat=1.0* (sqlats-last_sqlats) / (count-last_count);
3192+
stdev=0.001*sqrt(sqlat-1000000.0*latency*latency);
3193+
lag=0.001* (lags-last_lags) / (count-last_count);
31183194

3119-
fprintf(stderr,"progress: %.1f s, %.1f tps, %.3f ms lat\n",
3120-
total_run,tps,latency);
3195+
if (throttle_delay)
3196+
fprintf(stderr,
3197+
"progress: %.1f s, %.1f tps, "
3198+
"lat %.3f ms stddev %.3f, lag %.3f ms\n",
3199+
total_run,tps,latency,stdev,lag);
3200+
else
3201+
fprintf(stderr,
3202+
"progress: %.1f s, %.1f tps, "
3203+
"lat %.3f ms stddev %.3f\n",
3204+
total_run,tps,latency,stdev);
31213205

31223206
last_count=count;
3207+
last_lats=lats;
3208+
last_sqlats=sqlats;
3209+
last_lags=lags;
31233210
last_report=now;
31243211
next_report+=progress*1000000;
31253212
}
@@ -3131,8 +3218,14 @@ threadRun(void *arg)
31313218
INSTR_TIME_SET_CURRENT(start);
31323219
disconnect_all(state,nstate);
31333220
result->xacts=0;
3221+
result->latencies=0;
3222+
result->sqlats=0;
31343223
for (i=0;i<nstate;i++)
3224+
{
31353225
result->xacts+=state[i].cnt;
3226+
result->latencies+=state[i].txn_latencies;
3227+
result->sqlats+=state[i].txn_sqlats;
3228+
}
31363229
result->throttle_lag=thread->throttle_lag;
31373230
result->throttle_lag_max=thread->throttle_lag_max;
31383231
INSTR_TIME_SET_CURRENT(end);

‎doc/src/sgml/pgbench.sgml

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -412,7 +412,11 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
412412
<term><option>--progress=</option><replaceable>sec</></term>
413413
<listitem>
414414
<para>
415-
Show progress report every <literal>sec</> seconds.
415+
Show progress report every <literal>sec</> seconds. The report
416+
includes the time since the beginning of the run, the tps since the
417+
last report, and the transaction latency average and standard
418+
deviation since the last report. Under throttling (<option>-R</>), it
419+
also includes the average schedule lag time since the last report.
416420
</para>
417421
</listitem>
418422
</varlistentry>

0 commit comments

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