Showing slow AppVeyor tests (CI timeouts)

[abitrolly]

I've made the script to get the slowest tests from AppVeyor log, because the check fails to complete within 1 hour limit.

#!/usr/bin/env python3
"""
[00:01:03] 3/1266 (0.24%) C:\Python38\python.exe SCons\CacheDirTests.py
[00:01:03] ..s......
[00:01:03] ----------------------------------------------------------------------
[00:01:03] Ran 9 tests in 0.072s
[00:01:03]
[00:01:03] OK (skipped=1)
[00:01:03]
[00:01:03] Test execution time: 0.4 seconds
"""

import re
import sys

start = re.compile('\d+/\d+ \([.\d%]+\) (?P<path>.*)$')
end = re.compile('Test execution time: (?P<time>.*) seconds$')

with open('log.txt') as log:
    for line in log:
        m = start.search(line)
        if m is not None:
            path = m['path']
            for r in range(1000):
                line2 = next(log)
                em = end.search(line2)
                if em is not None:
                    time = em['time']
                    print(time + ', ' + path)
                    break
            else:
                sys.exit("FAIL: No time for test " + path)

It can be used from Linux command line to get a sorted CSV, which I attach here.
log.csv

./scons-tests-time-data.py | sort --numeric --reverse > log.csv

And here is the first 20 entries from it.

98.1, C:\Python38\python.exe test\Repository\Program.py
79.9, C:\Python38\python.exe test\KeyboardInterrupt.py
66.7, C:\Python38\python.exe test\Repository\StaticLibrary.py
66.7, C:\Python38\python.exe test\Libs\SharedLibraryIxes.py
52.9, C:\Python38\python.exe test\MSVS\vs-14.2-exec.py
48.3, C:\Python38\python.exe test\import.py
47.5, C:\Python38\python.exe test\Parallel\multiple-parents.py
45.6, C:\Python38\python.exe test\ninja\iterative_speedup.py
41.1, C:\Python38\python.exe test\Repository\variants.py
33.4, C:\Python38\python.exe SCons\SConfTests.py
29.7, C:\Python38\python.exe test\implicit-cache\basic.py
26.8, C:\Python38\python.exe test\MSVC\MSVC_SDK_VERSION.py
26.1, C:\Python38\python.exe test\QT\source-from-ui.py
23.8, C:\Python38\python.exe test\Actions\function.py
23.6, C:\Python38\python.exe test\MSVC\MSVC_UWP_APP.py
23.1, C:\Python38\python.exe test\MSVC\msvc.py
22.5, C:\Python38\python.exe test\Variables\PathVariable.py
22.2, C:\Python38\python.exe test\Variables\Variables.py
22.1, C:\Python38\python.exe test\VariantDir\VariantDir.py
21.8, C:\Python38\python.exe test\NodeOps.py

[abitrolly]

Or the same 20 entries in CSV in barchart rendered in markdown.

98.1 ████████████████████ test\Repository\Program.py
79.9 ████████████████ test\KeyboardInterrupt.py
66.7 █████████████ test\Repository\StaticLibrary.py
66.7 █████████████ test\Libs\SharedLibraryIxes.py
52.9 ██████████ test\MSVS\vs-14.2-exec.py
48.3 █████████ test\import.py
47.5 █████████ test\Parallel\multiple-parents.py
45.6 █████████ test\ninja\iterative_speedup.py
41.1 ████████ test\Repository\variants.py
33.4 ██████ SCons\SConfTests.py
29.7 ██████ test\implicit-cache\basic.py
26.8 █████ test\MSVC\MSVC_SDK_VERSION.py
26.1 █████ test\QT\source-from-ui.py
23.8 ████ test\Actions\function.py
23.6 ████ test\MSVC\MSVC_UWP_APP.py
23.1 ████ test\MSVC\msvc.py
22.5 ████ test\Variables\PathVariable.py
22.2 ████ test\Variables\Variables.py
22.1 ████ test\VariantDir\VariantDir.py
21.8 ████ test\NodeOps.py

And scripts that made it.

python scons-tests-csv2md.py > log.md 
cat log.md | head -n 20 | wl-copy

tuples = []
with open('log.csv') as log:
    for line in log:
        time, cmd = line.split(',')
        sec = float(time)
        test = cmd.split(maxsplit=1)[1]
        tuples.append((sec, test))

tuples.sort()
tuples.reverse()

maxv = max(tuples)[0]
barw = 20
char = '█'  # '░'
url = 'https://github.com/SCons/scons/blob/master/'

md = True

for s, t in tuples:
    bar = char*int((s*barw)/maxv)
    link = 'https://github.com/SCons/scons/blob/master/' + t.strip().replace("\\", "/")
    mdlink = '[' + t.strip() + '](' + link + ')'
    text = mdlink if md else t.strip()
    print(f'{s} {bar} {text}')

[mwichmann]

Seems useful. We aren't having too many appveyor timeout problems these days - usually sometime external is going on - but the Windows tests are still too slow, no question. The run that includes code coverage checks normally take in the range of 45 minutes.

[abitrolly]

Did anybody try to profile them for bottlenecks? 98 seconds for a test that doesn't seem large looks like a lot.

[mwichmann]

On WIndows, instantiating the SCons construction environment is expensive, thus lots of run(....args...) calls, and lots of SConstruct file creations (indicating one is about to call run) are hints that things that are likely to be slow. Some speedup can be gained by doing a sped-up call to DefaultEnvironment to avoid it also behind the scenes doing a full environment setup. Looking at the top of your list-of-shame, test/Repository/Program.py calls run 22 times - so that's always going to be expensive, This isn't always the culprit, but is a point of possible improvement - the problem is it's a bit of manual work that people don't tend to get around to unless they're touching a test for other reasons anyway. As an experiment, I put DefaultEnvironment(tools=[]) in each SConstruct, and the run time for that one drops (on my old slow Windows box)) from 97.6 to 31.7. The gains aren't always that notable, of course. There's a cache of detected msvc info that can be enabled by setting SCONS_CACHE_MSVC_CONFIG to true - that mostly exists for the test suite, since it runs scons so many times in a short period. The Appveyor setup already does this, so no more free performance from that front :(

[abitrolly]

On WIndows, instantiating the SCons construction environment is expensive,

Would be nice to actually see real profiles from there. Might be some MSVC performance leak, indeed.