Re: [lmi] Automated GUI testing, revisited

[Greg Chicares]

On 2014-11-14 02:53Z, Vadim Zeitlin wrote:
> On Wed, 12 Nov 2014 12:18:19 +0000 Greg Chicares <address@hidden> wrote:
> 
> GC> On 2014-11-12 01:55Z, Greg Chicares wrote:
> GC> [...]
> GC> > Vadim--I believe I copied 'wx_test.conf' from an old email that
> GC> > you had sent. Was "time_disk=11000" an actual measurement? For
> GC> > single tasks, your machine should be faster than mine; so I'm
> GC> > wondering whether we're running the same test.
> GC> > 
> GC> > My "456ms" above looks a lot like "time_run" in 'wx_test.conf':
> GC> >   time_run=434
> GC> >   time_disk=11000
> GC> >   time_spreadsheet=710
> GC> > (I mention that without further investigation on my part).

I still haven't changed those config-file numbers at all....

> GC> Here's more information, from another run:
> GC> 
> GC> 11:49:25: Run case for census_1: 416ms elapsed (expected -4.15%)
> GC> 11:49:25:     benchmark_census: ERROR (Assertion 
> 'std::fabs(diff_in_percents) < 10' failed
> GC> (expected 11000ms, but actually took 416ms, i.e. -96.22%).
> GC> [file /lmi/src/lmi/wx_test_benchmark_census.cpp, line 101] )
> GC> 
> GC> Doesn't this suggest that the "ERROR" comparison is incorrect?

And here's another run, which reflects the menu-accelerator change:
  http://svn.savannah.nongnu.org/viewvc?view=rev&root=lmi&revision=6036

22:29:03: Run case for census_1: 443ms elapsed (expected +2.07%)
22:29:03: Print to disk for census_1: 443ms elapsed (expected -95.97%)

This seems equivalent to the earlier results quoted above, in that
the "elapsed" times are implausibly equal.

>  Sorry if I'm missing something, but I don't see anything wrong with it.

I don't see how it's plausible for "Run case" and "Print to disk" to
take exactly the same amount of time, over and over.

> GC> I can match "expected -4.15%" this way:
> GC>   (416-434)/434 = -0.04147...
> GC> so that seems right.
> 
>  Yes.
> 
> GC> Assuming that "416ms" is my "time_run",
> 
>  Just to be clear: this is true assuming you mean "the actual time taken by
> running the test" by "your time_run". This is not the same as "time_run
> from your config file" which is "the expected time for running the test".

Yes. The config file says it should take
    434 ms for "Run case", and
  11000 ms for "Print to disk".
The latest measurements say  that the actual time is  443 ms for both.
My earlier measurements said that the actual time was 416 ms for both.
What I'm not seeing is how both operations could take the same
amount of time: both 416 ms in one trial, and both 443 ms in another.

>  Sorry if this seems completely tautological, but I'm just trying to
> understand where could the misunderstanding be coming from and so would
> like to make all the terms as precise as possible.
> 
> GC> I can match "i.e. -96.22%" this way:
> GC>   (416-11000)/11000 = -0.96218...
> GC> but it seems incorrect to compare observed "time_run" to
> GC> expected "time_disk", if that's what's really being done.
> 
>  No, by some coincidence (?) printing the case to disk also takes 416ms on
> your machine.

That's what the test seems to say, but the times should differ greatly.

> I think this is wrong and that the test actually did detect a
> problem as IME the time for printing the test is much longer than for just
> running it. I'm not sure if you're running the version in which
> Ctrl-Shift-K is used for printing to disk or one in which it was already
> changed to Ctrl-Shift-I, the latter would explain it.

Yet I have made that change:
  
http://svn.savannah.nongnu.org/viewvc/lmi/trunk/wx_test_pdf_create.cpp?root=lmi&r1=6036&r2=6035&pathrev=6036&diff_format=u
     // Print the census to disk.
-    ui.Char('k', wxMOD_CONTROL | wxMOD_SHIFT);  // "Census|Print case to disk"
+    ui.Char('i', wxMOD_CONTROL | wxMOD_SHIFT);  // "Census|Print case to disk"
     wxYield();

[Oops, I need to update that: it's called "Print case to PDF" now.]

Actually, I had made it earlier. But now I've committed it, so svn
gave it a current timestamp. And then I rebuilt, and 'make' did
recompile it. Now I rerun it, and get:

23:10:46: Run case for census_1: 414ms elapsed (expected -4.61%)
23:10:46: Print to disk for census_1: 414ms elapsed (expected -96.24%)

Let me run it manually and report timings from the status bar:
    426 ms Census | Run case
  14274 ms Census | Print case to PDF

So it appears that the program thinks the actual time taken for running
these two commands is the same, whereas the config-file expected times
and the manually-observed times are very different. I know--when all
else fails, read the source--but it looks correct at a quick glance,
and I'm trying not to dig too deeply into it now because I'm technically
on "vacation" again, so I'm not getting paid for this and I ought to be
twiddling my OpenBSD installation instead.

I should mention that I have a local patch that is intended only to
prevent this from aborting the test; but, AFAICT, it cannot account
for this perceived anomaly:

Index: wx_test_benchmark_census.cpp
===================================================================
--- wx_test_benchmark_census.cpp        (revision 6034)
+++ wx_test_benchmark_census.cpp        (working copy)
@@ -88,7 +88,7 @@
                     / static_cast<double>(time_expected);

             delta.Printf("%+.2f%%", diff_in_percents);
-
+#if 0
             LMI_ASSERT_WITH_MSG
                 (std::fabs(diff_in_percents) < 10
                 ,wxString::Format
@@ -99,6 +99,7 @@
                     ,delta
                     )
                 );
+#endif // 0
             }
         else
             {