Thread: BUG #15228: pgbench custom script numbering off-by-one

The following bug has been logged on the website:

Bug reference:      15228
Logged by:          Steven Winfield
Email address:      steven.winfield@cantabcapital.com
PostgreSQL version: 10.4
Operating system:   RHEL 7.4
Description:

Hi,

There's an off-by-one error in script numbering in the human readable vs.
machine readable logs, i.e.:

echo SELECT 1 > script1.pgbench
echo SELECT 2 > script2.pgbench
pgbench -f script1.pgbench -f script2.pgbench -t 10 -l -r -n -d postgres <+
usual host/port args>

In the human readable output the scripts are numbered 1 and 2:
...
transaction type: multiple scripts
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
number of transactions per client: 10
number of transactions actually processed: 10/10
latency average = 1.546 ms
tps = 646.952556 (including connections establishing)
tps = 3325.667669 (excluding connections establishing)
SQL script 1: script1.pgbench
 - weight: 1 (targets 50.0% of total)
 - 5 transactions (50.0% of total, tps = 323.476278)
 - latency average = 0.298 ms
 - latency stddev = 0.195 ms
 - statement latencies in milliseconds:
         0.298  SELECT 1
SQL script 2: script2.pgbench
 - weight: 1 (targets 50.0% of total)
 - 5 transactions (50.0% of total, tps = 323.476278)
 - latency average = 0.186 ms
 - latency stddev = 0.003 ms
 - statement latencies in milliseconds:
         0.187  SELECT 2

...but in the 4th column of the log files written by pgbench they are
numbered 0 and 1:

0 0 686 0 1528121961 383002
0 1 229 0 1528121961 383228
0 2 202 0 1528121961 383430
0 3 188 1 1528121961 383618
0 4 187 1 1528121961 383806
0 5 188 0 1528121961 383993
0 6 181 1 1528121961 384174
0 7 187 1 1528121961 384361
0 8 189 1 1528121961 384550
0 9 185 0 1528121961 384735

It would be nice if these two outputs agreed.

Thanks,
Steve.

=?utf-8?q?PG_Bug_reporting_form?= <noreply@postgresql.org> writes:
> There's an off-by-one error in script numbering in the human readable vs.
> machine readable logs, i.e.:
> ...
> In the human readable output the scripts are numbered 1 and 2:
> ...
> ...but in the 4th column of the log files written by pgbench they are
> numbered 0 and 1:

Hmm, yeah, it's inconsistent, but I wonder whether it's worth the pain
to fix.  I'd be quite hesitant to change the log output because that'd
likely break peoples' analysis scripts.  So possibly we could resolve
it by using 0-based numbering in the human-readable output, but that
would confuse things too perhaps.

Maybe we should just document it.

            regards, tom lane

> So possibly we could resolve
> it by using 0-based numbering in the human-readable output, but that
> would confuse things too perhaps.
>
> Maybe we should just document it.


Changing the human readable log, plus documentation, might be fair game for a new major version.
If so, I think the only changes required are:


src/bin/pgbench/pgbench.c

@@ -4659,7 +4659,7 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
printf("SQL script %d: %s\n"
" - weight: %d (targets %.1f%% of total)\n"
" - " INT64_FORMAT " transactions (%.1f%% of total, tps = %f)\n",
- i + 1, sql_script[i].desc,
+ i, sql_script[i].desc,
sql_script[i].weight,
100.0 * sql_script[i].weight / total_weight,
sstats->cnt,


doc/src/sgml/ref/pgbench.sgml

@@ -860,7 +860,9 @@ pgbench <optional> <replaceable>options</replaceable> </optional> <replaceable>d
benchmark scenarios by replacing the default transaction script
(described above) with a transaction script read from a file
(<option>-f</option> option). In this case a <quote>transaction</quote>
- counts as one execution of a script file.
+ counts as one execution of a script file. Script files are numbered
+ according to the order in which they appear on the command line,
+ beginning with zero.
</para>

<para>


What do you think?

Steve.

---

This email is confidential. If you are not the intended recipient, please advise us immediately and delete this message. The registered name of Cantab- part of GAM Systematic is Cantab Capital Partners LLP. See - http://www.gam.com/en/Legal/Email+disclosures+EU for further information on confidentiality, the risks of non-secure electronic communication, and certain disclosures which we are required to make in accordance with applicable legislation and regulations. If you cannot access this link, please notify us by reply message and we will send the contents to you.

GAM Holding AG and its subsidiaries (Cantab – GAM Systematic) will collect and use information about you in the course of your interactions with us. Full details about the data types we collect and what we use this for and your related rights is set out in our online privacy policy at https://www.gam.com/en/legal/privacy-policy. Please familiarise yourself with this policy and check it from time to time for updates as it supplements this notice

---

Hello Steven,

There were some hesitations when developing this feature for 9.6, with a 
transition from starting from 0 to 1 on submission v9, without clear 
outside input in the discussion to which was better, if any.

The rational for starting from 1 in the stdout report is that I felt, and 
still feel, that it is more user/human friendly this way.

The 0-numbering for the log was pre-existing and as tools/scripts exist to 
process that, changing it is best avoided, and it is for machines anyway.

So my 0.02€:

IMO the minimum fuss is to let it as a feature, which it is, and just 
explicitely document it, so I'm on Tom's line here. See attached patch as 
an attempt to do that. Could be backpatched up to 9.6.

I could also be okay with starting from 0 as well, sure, but I like 
human-friendlyness so I would not bother.

>> So possibly we could resolve it by using 0-based numbering in the 
>> human-readable output, but that would confuse things too perhaps.
>>
>> Maybe we should just document it.
>
> Changing the human readable log, plus documentation, might be fair game 
> for a new major version. If so, I think the only changes required are:

Sure.

-- 
Fabien.