Test::Smoke::Reporter reports misleading average smoketime

[jkeenan]

Under some circumstances, Test::Smoke::Reporter can generate a report file which reports a confusing average smoketime. Consider this report:

https://perl5.test-smoke.org/report/5039564

The 7th line in this web report reads:

    smoketime 5 hours 41 minutes (average 18 minutes 60 seconds)

Locally, the first 5 lines in the corresponding .rpt file (available upon request) are:

$ zcat rpt2559024c1da43be0ea37c8240f09d402f0c82acc.rpt.gz |head -5
Automated smoke report for branch davem/rc3 5.39.3 patch 2559024c1da43be0ea37c8240f09d402f0c82acc v5.39.2-98-g2559024c1d
perlmonger.nycbug.org: Intel(R) Xeon(R) CPU E31220 @ 3.10GHz (amd64/4 cpu)
    on        freebsd - 13.2-RELEASE-p1
    using     clang -Qunused-arguments -Accflags=-DPERL_RC_STACK version FreeBSD Clang 14.0.5 (https://github.com/llvm/llvm-project.git llvmorg-14.0.5-0-gc12386ae247c)
    smoketime 5 hours 41 minutes (average 18 minutes 60 seconds)

Two hunches:

1. I suspect that that should actually read (average 19 minutes).

2. I suspect that one could find this problem at the points where minutes roll over into hours and hours roll over into days -- but I haven't yet investigated these cases.

Here is a program, time_in_hhmm.pl, which reproduces the problem. As its name suggests, it is a simple wrapper around Test::Smoke::Reporter::time_in_hhmm(), intended to demonstrate what happens with a variable total elapsed running time and a (here fixed) count of Test::Smoke runs (each consisting of a perlio and a stdio run through the test suite).

$ cat time_in _hhmm.pl

#!/usr/bin/env perl
use 5.14.0;
use warnings;

sub time_in_hhmm {
    my $diff = shift;

    # Only show decimal point for diffs < 5 minutes
    my $digits = $diff =~ /\./ ? $diff < 5*60 ? 3 : 0 : 0;
    my $days = int( $diff / (24*60*60) );
    $diff -= 24*60*60 * $days;
    my $hour = int( $diff / (60*60) );
    $diff -= 60*60 * $hour;
    my $mins = int( $diff / 60 );
    $diff -=  60 * $mins;
    $diff = sprintf "%.${digits}f", $diff;

    my @parts;
    $days and push @parts, sprintf "%d day%s",   $days, $days == 1 ? "" : 's';
    $hour and push @parts, sprintf "%d hour%s",  $hour, $hour == 1 ? "" : 's';
    $mins and push @parts, sprintf "%d minute%s",$mins, $mins == 1 ? "" : 's';
    $diff && !$days && !$hour and push @parts, "$diff seconds";

    return join " ", @parts;
}

sub compose_time_strings {
    # Provide total elapsed time in seconds as calculated at line 254 T:S:R
    # and utilized at line 530 T:S:R
    # Provide count of test runs (each of which consists of 1 run of test
    # suite under perlio and one under stdio).  We will standardize this at
    # 18.
    my ($elapsed, $count) = @_;
    my $rptavg = $count ? $elapsed / $count : 0;
    my $time_msg  = time_in_hhmm( $elapsed );
    my $savg_msg  = time_in_hhmm( $rptavg  );
    return "smoketime $time_msg (average $savg_msg)";
}

sub output {
    my $elapsed = shift;
    say "$elapsed : ", compose_time_strings( $elapsed, 18 );
}

output($_) for (20491..20550);

Running this program through a 60-second range approximating the elapsed time of the report cited above, I got this output:

$ perl time_in_hhmm.pl
20491 : smoketime 5 hours 41 minutes (average 18 minutes 58 seconds)
20492 : smoketime 5 hours 41 minutes (average 18 minutes 58 seconds)
20493 : smoketime 5 hours 41 minutes (average 18 minutes 58 seconds)
20494 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20495 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20496 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20497 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20498 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20499 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20500 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20501 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20502 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20503 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20504 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20505 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20506 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20507 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20508 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20509 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20510 : smoketime 5 hours 41 minutes (average 18 minutes 59 seconds)
20511 : smoketime 5 hours 41 minutes (average 18 minutes 60 seconds)
20512 : smoketime 5 hours 41 minutes (average 18 minutes 60 seconds)
20513 : smoketime 5 hours 41 minutes (average 18 minutes 60 seconds)
20514 : smoketime 5 hours 41 minutes (average 18 minutes 60 seconds)
20515 : smoketime 5 hours 41 minutes (average 18 minutes 60 seconds)
20516 : smoketime 5 hours 41 minutes (average 18 minutes 60 seconds)
20517 : smoketime 5 hours 41 minutes (average 18 minutes 60 seconds)
20518 : smoketime 5 hours 41 minutes (average 18 minutes 60 seconds)
20519 : smoketime 5 hours 41 minutes (average 18 minutes 60 seconds)
20520 : smoketime 5 hours 42 minutes (average 19 minutes)
20521 : smoketime 5 hours 42 minutes (average 19 minutes)
20522 : smoketime 5 hours 42 minutes (average 19 minutes)
20523 : smoketime 5 hours 42 minutes (average 19 minutes)
20524 : smoketime 5 hours 42 minutes (average 19 minutes)
20525 : smoketime 5 hours 42 minutes (average 19 minutes)
20526 : smoketime 5 hours 42 minutes (average 19 minutes)
20527 : smoketime 5 hours 42 minutes (average 19 minutes)
20528 : smoketime 5 hours 42 minutes (average 19 minutes)
20529 : smoketime 5 hours 42 minutes (average 19 minutes)
20530 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20531 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20532 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20533 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20534 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20535 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20536 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20537 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20538 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20539 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20540 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20541 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20542 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20543 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20544 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20545 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20546 : smoketime 5 hours 42 minutes (average 19 minutes 1 seconds)
20547 : smoketime 5 hours 42 minutes (average 19 minutes 2 seconds)
20548 : smoketime 5 hours 42 minutes (average 19 minutes 2 seconds)
20549 : smoketime 5 hours 42 minutes (average 19 minutes 2 seconds)
20550 : smoketime 5 hours 42 minutes (average 19 minutes 2 seconds)

About this smoke:
    smoking-perl: 5.32.1
  smoker-version: 1.78/0.046
       timestamp: 2023-09-09T01:25:40Z
          tester: jkeenan

What should we do about this?

Thank you very much. Jim Keenan

[abeltje]

Hi Jim,

Thanks for reporting this. The problem is the sprintf() at the end of time_in_hhmm(), it wil round-up for all values that have a fraction-bit >= 5 I will fix it, as it looks nicer to have 19 minutes than 18 minutes 60 seconds, but it's no biggie.

it will be in the next release...

Thanks again, -- Abe.