Re: [lmi] Valyuta performance degredation?

[Vadim Zeitlin]

On Fri, 8 Jan 2021 23:05:42 +0000 Greg Chicares <gchicares@sbcglobal.net> wrote:

GC> $ git show 96d02bc3
GC> |Date:   2021-01-07T09:28:26+00:00
GC> |
GC> |    Record timings
GC> |
GC> |    Some degradation is observed, especially for solves. This needs to be
GC> |    investigated.
GC> 
GC> Extreme TL;DR: don't worry, it's nothing.
GC> 
GC> This 19x6 matrix tabulates the mean timing for each of the
GC> six 'make cli_timing' measurements, for the last nineteen
GC> 'git log --ancestry-path' commits on branch valyuta/004
GC> (i.e., the range from 96d02bc3 (above) back to the earlier
GC> commit that led to the "degredation" comment).
GC> 
GC> 0.02261 0.03921 0.03577 0.006163 0.0219 0.02016
GC> 0.02262 0.03873 0.03542 0.006216 0.02192 0.0202
GC> 0.02252 0.03882 0.03544 0.006213 0.02192 0.02026
GC> 0.02235 0.0389 0.03541 0.006165 0.02186 0.02024
GC> 0.02241 0.03875 0.03532 0.006146 0.02178 0.02014
GC> 0.02117 0.03823 0.03484 0.006149 0.02154 0.01992
GC> 0.02121 0.0383 0.03497 0.006198 0.02173 0.01998
GC> 0.02163 0.0385 0.035 0.00618 0.02172 0.01997
GC> 0.02125 0.03834 0.03504 0.006173 0.02165 0.02112
GC> 0.02148 0.03852 0.03502 0.006191 0.02172 0.02
GC> 0.02181 0.03847 0.03504 0.006217 0.02175 0.02001
GC> 0.0218 0.03848 0.03511 0.006233 0.02174 0.02005
GC> 0.02191 0.03842 0.03492 0.006157 0.02171 0.02005
GC> 0.02195 0.0385 0.03519 0.006223 0.0218 0.02006
GC> 0.02162 0.03873 0.03524 0.006171 0.02179 0.02007
GC> 0.02127 0.0384 0.035 0.006122 0.02162 0.02004
GC> 0.02162 0.0385 0.03523 0.006186 0.02191 0.02001
GC> 0.02284 0.04086 0.04092 0.006528 0.02178 0.02022
GC> 0.02172 0.03867 0.03518 0.006147 0.0219 0.02011
GC> 
GC> and entry [17][2] (index origin zero), 0.04092, is
GC> apparently just a random outlier; other than that, and
GC> perhaps [17][1],

 It seems indeed clear that something affected the timings in the row 17,
as all the values in it are greater than the trend, including those two but
also [17][0] which is noticeably above it. Other than that, there is also
[8][5], where a small but unmistakable bump can be seen as well.

GC> the pattern is very smooth and shows no actual trend.

 But I concur with this statement.

GC> (I present it this way because it's very easy to paste into a
GC> spreadsheet for graphing.)

 Out of curiosity, does your spreadsheet program support pasting
space-separated values? I had to replace spaces with tabs before being able
to plot the lines interactively (not that it's a big deal, of course). OTOH
it can be fed directly to gnuplot.

GC> I offer these observations:
GC> 
GC> First of all, here's the script that generated these numbers:
GC> 
GC> --8<----8<----8<----8<----8<----8<----8<----8<----8<----8<--
GC> #!/bin/sh
GC> 
GC> set -ev
GC> 
GC> rm -f timings
GC> git checkout -- Speed_gcc_x86_64-pc-linux-gnu
GC> git switch valyuta/004
GC> make $coefficiency uninstall
GC> 
GC> # for z in cf62b4482 506051ae d4e02914 7930f692 43c85673 96d02bc3 ; do
GC> for z in $(git log --oneline --ancestry-path --pretty='format:%h' 
cf62b4482^..96d02bc3) ; do
GC>   echo "...switching to commit ${z}:"
GC>   git switch --detach $z
GC> #  rm /opt/lmi/gcc_x86_64-pc-linux-gnu/build/ship/*.d
GC>   make clean
GC>   make $coefficiency install >log_${z} 2>&1
GC>   make cli_timing
GC>   echo $z >> timings
GC>   cat Speed_gcc_x86_64-pc-linux-gnu >> timings
GC>   git checkout -- Speed_gcc_x86_64-pc-linux-gnu
GC>   echo "...back to master:"
GC>   git switch -
GC> # in case that didn't work:
GC>   git switch valyuta/004
GC> done
GC> 
GC> echo "Completed."
GC> -->8---->8---->8---->8---->8---->8---->8---->8---->8---->8--
GC> 
GC> In English: accumulate timings in file 'timings', for each
GC> of numerous commits. Set the stage by uninstalling and
GC> removing the 'Speed_*' file that will be repeatedly
GC> generated. Do this for
GC>   $env |grep LMI_                                                  
GC>   LMI_COMPILER=gcc
GC>   LMI_TRIPLET=x86_64-pc-linux-gnu
GC> because it compiles quickly.
GC> 
GC> Importantly, use commits in [cf62b4482, 96d02bc3]. At first
GC> (in a commented-out line), I had used every tenth commit in
GC> `git log -51`, which led to confusing results: for commits
GC> in the middle, timings were of a different complexion, and
GC> I think that's because `git log -51` includes some stuff
GC> along a merge path that's irrelevant here; '--ancestry-path'
GC> seems like the perfect thing to use here.

 Yes, indeed.

GC> Some of the script lines are best explained by showing the
GC> errors they prevented:
GC> 
GC> This line:
GC>   git checkout -- Speed_gcc_x86_64-pc-linux-gnu
GC> prevents:
GC> 
GC> ...switching to commit cf62b4482:
GC> error: Your local changes to the following files would be overwritten by 
checkout:
GC>         Speed_gcc_x86_64-pc-linux-gnu
GC> Please commit your changes or stash them before you switch branches.

 To be honest I don't really understand why do we need to have a git branch
for this file. I'd just put it in ".." and avoid switching branches
unnecessarily.

GC> This line:
GC>   git switch valyuta/004
GC> works around this problem:
GC> 
GC> /opt/lmi/src/lmi[0]$git switch -
GC> fatal: a branch is expected, got commit 
'd4e029146c6a385820b8952deeabc82558541603'
GC> 
GC> although I had thought 'git switch -' should just work.

 I think "-" only works for switching to a previous branch, but not when
the previous HEAD was detached.

GC> This line:
GC>   make clean
GC> avoid tragic outcomes like:
GC> 
GC> /opt/lmi/src/lmi[0]$make cli_timing
GC> vector::reserve
GC> 
GC> /opt/lmi/src/lmi[0]$make cli_timing                     
GC> Segmentation fault
GC> 
GC> I thought that was impossible, because 'git switch' seems to
GC> 'touch' each file it changes, so that 'make' should just work;
GC> but that's not what I observed. What am I missing?

 I think you've replied to your question just below: make doesn't handle
traveling back in time neither (I used to have a meta-make tool called
tmake 20+ years ago but I've missed the opportunity to call it tachyon
make, if only I knew I'd need this feature now...).

 The simplest fix would be to just add --reverse to the git-log command
above, I don't see any reason to prefer going back in time and I'd even say
that the plots would look more natural if we didn't do it.

GC> This line:
GC>   #  rm /opt/lmi/gcc_x86_64-pc-linux-gnu/build/ship/*.d
GC> attempted to work around another problem that I hadn't
GC> expected to see. I traced it to the autodependency '.d'
GC> files in /opt/lmi/gcc*/build/ship/ , which don't seem to
GC> travel back in time very well.

 This should be fixed by going forward in time too, I believe.


 Reading this email finally gives me an opportunity to ask you a question I
wanted to ask since quite some time, looking at your performance
explorations: do you think it could make sense to collect such kind of
statistics automatically? Running the script above is probably not that
much trouble, but wouldn't it be nice if we already had all these numbers?
As we're now running CI builds on GitHub anyhow, it should be pretty simple
to build "cli_timing" target in them too and store the result somewhere.
Then we could have something like the graphs on this page

        https://rhysd.github.io/github-action-benchmark/dev/bench/

for lmi too. Would this be useful to have?

 Thanks,
VZ

pgpA7LtrjOKbc.pgp
Description: PGP signature