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

Commit16827d4

Browse files
committed
pgbench: fix stats reporting when some transactions are skipped.
pgbench can skip some transactions when both -R and -L options are used.Previously, this resulted in slightly silly statistics both in progressreports and final output, because the skipped transactions were countedas executed for TPS and related stats. Discount skipped xacts in TPSnumbers, and also when figuring the percentage of xacts exceeding thelatency limit.Also, don't print per-script skipped-transaction counts when there isonly one script. That's redundant with the overall count, and it'sinconsistent with the fact that we don't print other per-script statswhen there's only one script. Clean up some unnecessary interactionsbetween what should be independent options that were due to thatdecision.While at it, avoid division-by-zero in cases where no transactions wereexecuted. While on modern platforms this would generally result inprinting "NaN" rather than a crash, that isn't spelled consistentlyacross platforms and it would confuse many people. Skip the relevantoutput entirely when practical, else print zeroes.Fabien Coelho, reviewed by Steve Singer, additional hacking by meDiscussion:https://postgr.es/m/26654.1505232433@sss.pgh.pa.us
1 parent4176126 commit16827d4

File tree

3 files changed

+65
-44
lines changed

3 files changed

+65
-44
lines changed

‎doc/src/sgml/ref/pgbench.sgml

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1363,8 +1363,7 @@ latency average = 15.844 ms
13631363
latency stddev = 2.715 ms
13641364
tps = 618.764555 (including connections establishing)
13651365
tps = 622.977698 (excluding connections establishing)
1366-
script statistics:
1367-
- statement latencies in milliseconds:
1366+
statement latencies in milliseconds:
13681367
0.002 \set aid random(1, 100000 * :scale)
13691368
0.005 \set bid random(1, 1 * :scale)
13701369
0.002 \set tid random(1, 10 * :scale)

‎src/bin/pgbench/pgbench.c

Lines changed: 63 additions & 41 deletions
Original file line numberDiff line numberDiff line change
@@ -3664,27 +3664,32 @@ addScript(ParsedScript script)
36643664
staticvoid
36653665
printSimpleStats(constchar*prefix,SimpleStats*ss)
36663666
{
3667-
/* print NaN if no transactions where executed */
3668-
doublelatency=ss->sum /ss->count;
3669-
doublestddev=sqrt(ss->sum2 /ss->count-latency*latency);
3667+
if (ss->count>0)
3668+
{
3669+
doublelatency=ss->sum /ss->count;
3670+
doublestddev=sqrt(ss->sum2 /ss->count-latency*latency);
36703671

3671-
printf("%s average = %.3f ms\n",prefix,0.001*latency);
3672-
printf("%s stddev = %.3f ms\n",prefix,0.001*stddev);
3672+
printf("%s average = %.3f ms\n",prefix,0.001*latency);
3673+
printf("%s stddev = %.3f ms\n",prefix,0.001*stddev);
3674+
}
36733675
}
36743676

36753677
/* print out results */
36763678
staticvoid
36773679
printResults(TState*threads,StatsData*total,instr_timetotal_time,
3678-
instr_timeconn_total_time,intlatency_late)
3680+
instr_timeconn_total_time,int64latency_late)
36793681
{
36803682
doubletime_include,
36813683
tps_include,
36823684
tps_exclude;
3685+
int64ntx=total->cnt-total->skipped;
36833686

36843687
time_include=INSTR_TIME_GET_DOUBLE(total_time);
3685-
tps_include=total->cnt /time_include;
3686-
tps_exclude=total->cnt / (time_include-
3687-
(INSTR_TIME_GET_DOUBLE(conn_total_time) /nclients));
3688+
3689+
/* tps is about actually executed transactions */
3690+
tps_include=ntx /time_include;
3691+
tps_exclude=ntx /
3692+
(time_include- (INSTR_TIME_GET_DOUBLE(conn_total_time) /nclients));
36883693

36893694
/* Report test parameters. */
36903695
printf("transaction type: %s\n",
@@ -3697,13 +3702,13 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
36973702
{
36983703
printf("number of transactions per client: %d\n",nxacts);
36993704
printf("number of transactions actually processed: "INT64_FORMAT"/%d\n",
3700-
total->cnt-total->skipped,nxacts*nclients);
3705+
ntx,nxacts*nclients);
37013706
}
37023707
else
37033708
{
37043709
printf("duration: %d s\n",duration);
37053710
printf("number of transactions actually processed: "INT64_FORMAT"\n",
3706-
total->cnt);
3711+
ntx);
37073712
}
37083713

37093714
/* Remaining stats are nonsensical if we failed to execute any xacts */
@@ -3716,9 +3721,9 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
37163721
100.0*total->skipped /total->cnt);
37173722

37183723
if (latency_limit)
3719-
printf("number of transactions above the %.1f ms latency limit:%d (%.3f %%)\n",
3720-
latency_limit /1000.0,latency_late,
3721-
100.0*latency_late /total->cnt);
3724+
printf("number of transactions above the %.1f ms latency limit:"INT64_FORMAT"/"INT64_FORMAT" (%.3f %%)\n",
3725+
latency_limit /1000.0,latency_late,ntx,
3726+
(ntx>0) ?100.0*latency_late /ntx :0.0);
37223727

37233728
if (throttle_delay||progress||latency_limit)
37243729
printSimpleStats("latency",&total->latency);
@@ -3745,47 +3750,55 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
37453750
printf("tps = %f (excluding connections establishing)\n",tps_exclude);
37463751

37473752
/* Report per-script/command statistics */
3748-
if (per_script_stats||latency_limit||is_latencies)
3753+
if (per_script_stats||is_latencies)
37493754
{
37503755
inti;
37513756

37523757
for (i=0;i<num_scripts;i++)
37533758
{
3754-
if (num_scripts>1)
3759+
if (per_script_stats)
3760+
{
3761+
StatsData*sstats=&sql_script[i].stats;
3762+
37553763
printf("SQL script %d: %s\n"
37563764
" - weight: %d (targets %.1f%% of total)\n"
37573765
" - "INT64_FORMAT" transactions (%.1f%% of total, tps = %f)\n",
37583766
i+1,sql_script[i].desc,
37593767
sql_script[i].weight,
37603768
100.0*sql_script[i].weight /total_weight,
3761-
sql_script[i].stats.cnt,
3762-
100.0*sql_script[i].stats.cnt /total->cnt,
3763-
sql_script[i].stats.cnt /time_include);
3764-
else
3765-
printf("script statistics:\n");
3769+
sstats->cnt,
3770+
100.0*sstats->cnt /total->cnt,
3771+
(sstats->cnt-sstats->skipped) /time_include);
37663772

3767-
if (latency_limit)
3768-
printf(" - number of transactions skipped: "INT64_FORMAT" (%.3f%%)\n",
3769-
sql_script[i].stats.skipped,
3770-
100.0*sql_script[i].stats.skipped /sql_script[i].stats.cnt);
3773+
if (throttle_delay&&latency_limit&&sstats->cnt>0)
3774+
printf(" - number of transactions skipped: "INT64_FORMAT" (%.3f%%)\n",
3775+
sstats->skipped,
3776+
100.0*sstats->skipped /sstats->cnt);
37713777

3772-
if (num_scripts>1)
3773-
printSimpleStats(" - latency",&sql_script[i].stats.latency);
3778+
printSimpleStats(" - latency",&sstats->latency);
3779+
}
37743780

37753781
/* Report per-command latencies */
37763782
if (is_latencies)
37773783
{
37783784
Command**commands;
37793785

3780-
printf(" - statement latencies in milliseconds:\n");
3786+
if (per_script_stats)
3787+
printf(" - statement latencies in milliseconds:\n");
3788+
else
3789+
printf("statement latencies in milliseconds:\n");
37813790

37823791
for (commands=sql_script[i].commands;
37833792
*commands!=NULL;
37843793
commands++)
3794+
{
3795+
SimpleStats*cstats=&(*commands)->stats;
3796+
37853797
printf(" %11.3f %s\n",
3786-
1000.0* (*commands)->stats.sum /
3787-
(*commands)->stats.count,
3798+
(cstats->count>0) ?
3799+
1000.0*cstats->sum /cstats->count :0.0,
37883800
(*commands)->line);
3801+
}
37893802
}
37903803
}
37913804
}
@@ -3984,7 +3997,6 @@ main(int argc, char **argv)
39843997
break;
39853998
case'r':
39863999
benchmarking_option_set= true;
3987-
per_script_stats= true;
39884000
is_latencies= true;
39894001
break;
39904002
case's':
@@ -4861,7 +4873,8 @@ threadRun(void *arg)
48614873
{
48624874
/* generate and show report */
48634875
StatsDatacur;
4864-
int64run=now-last_report;
4876+
int64run=now-last_report,
4877+
ntx;
48654878
doubletps,
48664879
total_run,
48674880
latency,
@@ -4876,7 +4889,7 @@ threadRun(void *arg)
48764889
* XXX: No locking. There is no guarantee that we get an
48774890
* atomic snapshot of the transaction count and latencies, so
48784891
* these figures can well be off by a small amount. The
4879-
* progressisreport's purpose is to give a quick overview of
4892+
* progress report's purpose is to give a quick overview of
48804893
* how the test is going, so that shouldn't matter too much.
48814894
* (If a read from a 64-bit integer is not atomic, you might
48824895
* get a "torn" read and completely bogus latencies though!)
@@ -4890,15 +4903,21 @@ threadRun(void *arg)
48904903
cur.skipped+=thread[i].stats.skipped;
48914904
}
48924905

4906+
/* we count only actually executed transactions */
4907+
ntx= (cur.cnt-cur.skipped)- (last.cnt-last.skipped);
48934908
total_run= (now-thread_start) /1000000.0;
4894-
tps=1000000.0* (cur.cnt-last.cnt) /run;
4895-
latency=0.001* (cur.latency.sum-last.latency.sum) /
4896-
(cur.cnt-last.cnt);
4897-
sqlat=1.0* (cur.latency.sum2-last.latency.sum2)
4898-
/ (cur.cnt-last.cnt);
4899-
stdev=0.001*sqrt(sqlat-1000000.0*latency*latency);
4900-
lag=0.001* (cur.lag.sum-last.lag.sum) /
4901-
(cur.cnt-last.cnt);
4909+
tps=1000000.0*ntx /run;
4910+
if (ntx>0)
4911+
{
4912+
latency=0.001* (cur.latency.sum-last.latency.sum) /ntx;
4913+
sqlat=1.0* (cur.latency.sum2-last.latency.sum2) /ntx;
4914+
stdev=0.001*sqrt(sqlat-1000000.0*latency*latency);
4915+
lag=0.001* (cur.lag.sum-last.lag.sum) /ntx;
4916+
}
4917+
else
4918+
{
4919+
latency=sqlat=stdev=lag=0;
4920+
}
49024921

49034922
if (progress_timestamp)
49044923
{
@@ -4915,7 +4934,10 @@ threadRun(void *arg)
49154934
(long)tv.tv_sec, (long) (tv.tv_usec /1000));
49164935
}
49174936
else
4937+
{
4938+
/* round seconds are expected, but the thread may be late */
49184939
snprintf(tbuf,sizeof(tbuf),"%.1f s",total_run);
4940+
}
49194941

49204942
fprintf(stderr,
49214943
"progress: %s, %.1f tps, lat %.3f ms stddev %.3f",

‎src/bin/pgbench/t/001_pgbench_with_server.pl

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -427,7 +427,7 @@ sub pgbench
427427
0,
428428
[qr{processed: [01]/10},
429429
qr{type: .*/001_pgbench_sleep},
430-
qr{above the 1.0 ms latency limit: [01]} ],
430+
qr{above the 1.0 ms latency limit: [01]/} ],
431431
[qr{^$}i],
432432
'pgbench late throttling',
433433
{'001_pgbench_sleep'=>q{\sleep 2ms} });

0 commit comments

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