Subject: Re: Reporting script runtimes in pg_regress
To: Tom Lane <tgl@sss.pgh.pa.us>
References: <16646.1549770618@sss.pgh.pa.us>
 <E7790843-B885-492B-8537-CC9FB39D5F97@yesql.se>
 <11413.1549835730@sss.pgh.pa.us>
 <6f1657f9-c58c-ba28-0013-d36a6f6fd246@2ndquadrant.com>
 <6418.1549895430@sss.pgh.pa.us>
Cc: Daniel Gustafsson <daniel@yesql.se>, pgsql-hackers@lists.postgresql.org
From: Peter Eisentraut <peter.eisentraut@2ndquadrant.com>
Openpgp: preference=signencrypt
Autocrypt: addr=peter.eisentraut@2ndquadrant.com; prefer-encrypt=mutual;
 keydata=
 xsFNBFUUt6kBEADZd9NNTBJbHmAXXJgPGOdd6Q73l80oifIVgn2tRxP9dYkCfTlo/yLqbKTl
 JNqTcyM6XrJDnB2sMEUGYCewYZXl+9C4bBJWyNqcEI1ae9u71vEq/fknFLArJ+2wN+f7QuRx
 Q8d94ZJAiJQ5g3fNk2HVeedCQCKP5dCzU+ZLt2dbsx1PDZLjTO9gf+JswWuGFb5wY5PZVM5V
 hq66Xk7ZJzHuARacza2RT7J2fkMmQBY+kr7L98Perb0GhafnlhXB0PvUB+N3xpmggMfwuhTu
 BngS/G/r3GvemxJuFxouw8xsMqrsfdksJXA2gLXYtwRCssdPV3PO0rlD9twqDo8URfIJ5fb6
 1g/MV8aTOKjg3Q8MpJPtkwJqN4o3PvbwYdedeFnOVkkYAJdu/aX1v1BeCBDu7Hy3sF52scD3
 pQbyQSl9vUDpTLarASAxNbAV0NRJE8dp4vfW6AH1ccryGiFqw/czPK/iN0+MT8wsjAW6WW4w
 hvjm5UPA1KTwi3ZT8eT5uycuH7QpuNk7LnGGXQ6KaRALFywzkr0A0V0AvFNa+l4wstMaXaB6
 dmMXyF0/hfryqyOeu1gAdq4q0/PNC2dPgb/6uoh4eMjN6A5GXcprilhz5DulmsilY21hfSoU
 S64ODed96pKhprsOxjZiDRsN1QM5MwB+uwVWUNfsX7fIxE0BrwARAQABzSdQZXRlciBFaXNl
 bnRyYXV0IDxwZXRlckBlaXNlbnRyYXV0Lm9yZz7CwXoEEwEIACQCGwMFCwkIBwMFFQoJCAsF
 FgIDAQACHgECF4AFAlUUuKQCGQEACgkQoZ8SQ+xBJp8llw//RbGoXnF72FZTlOFsnNyxnWbF
 vViPCfdAlZl1GGK9OYCvV1dp/956HuhB0wpaGQHiBmQfOPJf/jLOPjXFYm2iEChEycrBChuE
 j4TSYemMp5BSPILYk9Uwd16kVD/+U6fQfK6H5pOhfBvbM6asMnmpY2wQuvktxHvaGlytFw84
 EzFWNZtAZfxkw28w3AhIQkKe9hJanfyDL750RcbyEr8AAHty5IErrvS7tM5vQwIeh5BF26ND
 CyKPRdZgOgMpcwFfROKBDpAt052CgWIpNdhBdfIKlkCs4/ILxmC3rT/Mb/qZiHcoMMwEu6k+
 T7vRAFZZAk62Yrr/U8/vUGKlzRZQoo86fyojCfI0ibCIc0z8rwCVY9P40G9wD9BTCZS/z8Vh
 jjpBlNnIKw2hM6hbxavKndCJjFFJD08rXrTyrLF/of18xD37vNdYooP9VATB5QjOWFRrscSZ
 4a89e+to3m7YVnd4xdXwGp47dYusoax84C8tg1gZrH38ol9dPmnKX6GZrXeS7tH9k8VeUpJ8
 HQbRThQRWAT936QpYbLConBmOtmbLmjQOGtiXPo1oK57X/7U/WBja5vWmm2q+Yxtt+3uHGVg
 DdDU4CJpXo4lX0v2n3QV5EBSW9hjdF3bNfl6GFBb1pPEhqNcMDUc7zkx/2uENdAdk/BnqMgH
 umip7b0pVfvOwU0EVRS3qQEQAJf6p0P7D+hMYUgCPkvgrcz6OJYsAYdUMUmokfqmkKwK0oJM
 ew8TNGM53ocKAgQGma5f10rwbZNPlpVPNRX5hwUmwVlcwSut0oE+JfUBH7mpysWvpF05RKIy
 q9RCoJZrAbXS7Tig56A1QD8IcM00rERZMcCOlI1+q9m4u9AOI+0LyGGSH+VvoyDHD/Jew4R2
 TmPEF8Pu7lYiNYK88Q6u0kBkc+Tz3BNlyc6fi3HxnFfp0b75HLXPSTu2SwA/0Q31wHZXwrEU
 BR9KgSn/qbgy8ydPc97i82fhiFE3cbGexfPrQSMYmDGi+dcQ0s+AMQwC3XyMC0JkHpYUuFkR
 QdlIvaIhgFUUN2Vr4xF2ADaNTNFc4DYaiPHFAgHZw+3pZWqS4uIiWgJynrEaHw4F3QWU8/JB
 iyEWDhNq4WBrRA0u914TCCAoFOOKMnRdl8eJrRQKM/5/lXbHFjjlI/LDKhLRFsuQsnJJ3331
 RjCzpHPZG5/p5KR1RHiAXa0p/DW5lXyq21hS3kjDlleoHqOxCN/cy0Jgz7qLDq1vZoCl67Sy
 RAH60c2Xu4may9SVltmot0OzWVHdrfS+85FQGp9580DaeLio7YMFKy2bfEvwQJ/c9xD2QPB+
 oSb3V8ueSznXBG5+dyfOsZFRPxceA0wA2rSWZSjxLdKxvyGTj9vsCjaDu13rABEBAAHCwV8E
 GAEIAAkFAlUUt6kCGwwACgkQoZ8SQ+xBJp+HJhAAxmSTsC5y7p9Zu+nnLpucv/h88oEx985e
 qWeXzQiwM3pfRZS+PdTH9TyzHK0KOgKoAiubk0vt+BrT91D9d0G5kVQaTctAErGBoMkTaZJT
 XVEcNphiPzysdSqvprjojMp1y7rG8AP+Xd6m0rE1LRnkRRm8HyI8vdXsuLQPITGWXDLMjaNq
 AOV3BUnzkgtjMuIYw7SCr+12ZOb5dEKvaG4kjC4kaJ/TLbuBhVANcXkC90yp0AOZLs/cB1Dj
 OAXno/RUUruJ3r27a+pFv768UAi9QWcdw58yPxreMNMLqAgsS9oTHwHfGNWcB2dJ4UW+GMLJ
 hTf9TjQ2f+N/sIx5XMQ9pYw6CAJMK29qPx6/ZayrPxf22EXf0D3zTwIEZgwfSkynFVwV25L7
 awQq60fifdMYheSxq7GbhpsixmcD+e161cCmLIt75YDt5bQ0B1yf7EmxG8n7pGZAOM6LoNsU
 fkSldba5XVwh8LuN5mK0nQBELGW6Os4TDq4REggLpfcvFC215zpuo0iCGnmE/Bns4nowqUSP
 u4tkWL+nxW4qgv8wo8HJ52jd79EJ8iqfIBoidBfy9AIUiEUApGQzWPu6yWcI8fY0rN5D+tc+
 Yw1Zt6Mm+huYJpgCRsTcfzEcahnBn521CWcWvhW1ff3KFileFMtNmnBBhMncmRKHphtTKEpN
 3jI=
Organization: 2ndQuadrant
Message-ID: <e265e2ae-e92e-5ab9-dc68-60b6cb047b3d@2ndquadrant.com>
Date: Fri, 15 Feb 2019 14:32:52 +0100
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.14; rv:52.0)
 Gecko/20100101 Thunderbird/52.9.1
MIME-Version: 1.0
In-Reply-To: <6418.1549895430@sss.pgh.pa.us>
Content-Type: text/plain; charset=utf-8
Content-Language: en-US
Content-Transfer-Encoding: 7bit
Precedence: bulk

On 2019-02-11 15:30, Tom Lane wrote:
> Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
>> Now that I see this in action, it makes the actual test results harder
>> to identify flying by.  I understand the desire to collect this timing
>> data, but that is a special use case and not relevant to the normal use
>> of the test suite, which is to see whether the test passes.  Can we make
>> this optional please?
> 
> Well, I want the buildfarm to produce this info, so it's hard to see
> how to get that without the timings being included by default.  I take
> your point that it makes the display look a bit cluttered, though.

Can we enable it through the buildfarm client?

Or we could write it into a separate log file.

> Would it help to put more whitespace between the status and the timing?

prove --timer produces this:

[14:21:32] t/001_basic.pl ............ ok     9154 ms ( 0.00 usr  0.01 sys +  2.28 cusr  3.40 csys =  5.69 CPU)
[14:21:41] t/002_databases.pl ........ ok    11294 ms ( 0.00 usr  0.00 sys +  2.16 cusr  3.84 csys =  6.00 CPU)
[14:21:52] t/003_extrafiles.pl ....... ok     7736 ms ( 0.00 usr  0.00 sys +  1.89 cusr  2.91 csys =  4.80 CPU)
[14:22:00] t/004_pg_xlog_symlink.pl .. ok     9035 ms ( 0.00 usr  0.00 sys +  2.03 cusr  3.02 csys =  5.05 CPU)
[14:22:09] t/005_same_timeline.pl .... ok     8048 ms ( 0.00 usr  0.00 sys +  0.92 cusr  1.29 csys =  2.21 CPU)

which seems quite readable.  So maybe something like this:

     identity                     ... ok      238 ms
     partition_join               ... ok      429 ms
     partition_prune              ... ok      786 ms
     reloptions                   ... ok       94 ms
     hash_part                    ... ok       78 ms
     indexing                     ... ok     1298 ms
     partition_aggregate          ... ok      727 ms
     partition_info               ... ok      110 ms
test event_trigger                ... ok      128 ms
test fast_default                 ... ok      173 ms
test stats                        ... ok      637 ms

which would be

-           status(_(" (%.0f ms)"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
+           status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));

(times two).

If we're going to keep this, should we enable the prove --timer option as well?

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services