Extracting runtimes from TestDirectory logs

[olexandr-konovalov]

I've discovered that this functionality is broken for a while in the master branch. In the stable branch, the log has

...
testing: /mnt/disk2/hudson-slave/workspace/GAP-stable/GAPCOPTS/64build/GAPGMP/\
nogmp/GAPTARGET/standard/label/64bit/GAP-git-stable-snapshot/tst/primsan.tst
primsan.tst            89646        1399788    (next ~ 2021 sec)
testing: /mnt/disk2/hudson-slave/workspace/GAP-stable/GAPCOPTS/64build/GAPGMP/\
nogmp/GAPTARGET/standard/label/64bit/GAP-git-stable-snapshot/tst/bugfix.tst
bugfix.tst           1900219          80617    (next ~ 1750 sec)
testing: /mnt/disk2/hudson-slave/workspace/GAP-stable/GAPCOPTS/64build/GAPGMP/\
nogmp/GAPTARGET/standard/label/64bit/GAP-git-stable-snapshot/tst/grpconst.tst
grpconst.tst         1104244         187952
-------------------------------------------
total                  48357        3623339

so I can extract the runtime with

grep "^${GTEST}" `ls dev/log/teststandard1_*` | sed -e 's/  */ /g' | cut -f 3 -d ' ' >> dev/log/plot${GTEST}1.txt

where GTEST is in arithlst hash2 primsan xgap grppcnrm grpmat grpperm matrix grplatt bugfix grpprmcs grpconst to build plots in Jenkins to track the performance of selected tests.

Now in the master branch the log looks like

testing: /mnt/disk2/hudson-slave/workspace/GAP-dev/GAPCOPTS/64build/GAPGMP/nog\
mp/GAPTARGET/standard/label/64bit/GAP-git-snapshot/tst/teststandard/grpperm.ts\
t
1799980000              6039         298039   ( next ~345 sec )
testing: /mnt/disk2/hudson-slave/workspace/GAP-dev/GAPCOPTS/64build/GAPGMP/nog\
mp/GAPTARGET/standard/label/64bit/GAP-git-snapshot/tst/teststandard/helpsys.ts\
t
2178880000              2317         940175   ( next ~662 sec )
testing: /mnt/disk2/hudson-slave/workspace/GAP-dev/GAPCOPTS/64build/GAPGMP/nog\
mp/GAPTARGET/standard/label/64bit/GAP-git-snapshot/tst/teststandard/arithlst.t\
st
2776240000              5659         490570   ( next ~2009 sec )
testing: /mnt/disk2/hudson-slave/workspace/GAP-dev/GAPCOPTS/64build/GAPGMP/nog\
mp/GAPTARGET/standard/label/64bit/GAP-git-snapshot/tst/teststandard/primsan.ts\
t
9058150000              6337        1429254
-------------------------------------------
total                   6451        3693479

Since there is no name of the test file in the same line with the runtime, it's no longer possible to extract the runtime in the same way (also, I do not understand what's the meaning of the third number which appears in that line).

One approach would be to fix this by adding the filename to the line in question. Another could consider going further and providing a way to save, accumulate and compare such data, triggering an alert in case of significant performance regressions. There were some ideas about that in the past.

[ChrisJefferson]

There is no good reason for this change, I'll fix it.

[stevelinton]

It would be sensible for TestDirectory to offer an API for accessing the performance information from a run. Also, if possible, a list of files which failed testing.

[olexandr-konovalov]

@ChrisJefferson Yes, please - while we may think of an API later, restoring the old output would help immediately.

Since TestDirectory tests all files in the same directory, the output could be made more concise by typing the full path just once in the header of the log file, and then printing only the filename without path.

[fingolfin]

Output on master now looks like this:

      78 msec for xfuncs.tst
testing: /Users/mhorn/Projekte/GAP/gap.github/tst/testinstall/xgap.tst
     593 msec for xgap.tst
testing: /Users/mhorn/Projekte/GAP/gap.github/tst/testinstall/zlattice.tst
      88 msec for zlattice.tst
testing: /Users/mhorn/Projekte/GAP/gap.github/tst/testinstall/zmodnz.tst
     117 msec for zmodnz.tst
testing: /Users/mhorn/Projekte/GAP/gap.github/tst/testinstall/zmodnze.tst
      94 msec for zmodnze.tst
-----------------------------------
total     50307 msec

#I  No errors detected while testing

So it should be again possible to extract the individual file runtimes from this.

Of course we also change TestDirectory to somehow return a list with an entry for each .tst file that was executed (full path) and its runtime. If anybody would like to have that, I suggest opening a separate feature request issue for that.

[fingolfin]

@alex-konovalov what's the status of this?

[fingolfin]

@alex-konovalov What's the status of this? If this is broken, can you please point out where the (currently broken) code for extracting the timings is (which repository, file, which function name etc.) so that somebody who'd be willing to help with this could contribute?

[olexandr-konovalov]

It is https://github.com/gap-system/gap-distribution/blob/master/testing/plots.sh but quite tied to Jenkins setup, so I am not sure that it will be useful to somebody.

[fingolfin]

We are not using the Jenkins setup anymore