[py-dev] Performance tests with py.test

[Bogdan Opanchuk]

Hi Holger,

On Sun, Apr 1, 2012 at 12:21 PM, holger krekel <holger at merlinux.eu> wrote:

> do you want to consider performance regressions as a failure?

Not really. I just need some table with performance results that I
could get for different systems/versions and compare them. Besides,
performance regressions can be implemented using existing
functionality, because they do not have some continuous result
associated with them — only pass/fail.

> Could you maybe provide a simple example test file and make up
> some example output that you'd like to see?

Sure. Consider the following test file:

-----
import pytest

def test_matrixmul():
    pass

@pytest.mark.perf('seconds')
def test_reduce():
    # <some lengthy preparation that I do not want to time>
    # <actual work>
    return 1.0

@pytest.mark.perf('GFLOPS')
def test_fft():
    # <again, some lengthy preparation that I do not want to time>
    # <actual work>
    return 1.0, 1e10
-----

Here "test_matrixmul()" is a normal pass/fail test, "test_reduce()" is
marked as performance test that returns execution time, and
"test_fft()" is marked as a test that returns execution time + the
number of operations (thus allowing us to calculate GFLOPS value).

I have put together a clunky solution (see the end of this letter)
using existing hooks that gives me more or less what I want to see:

$ py.test -v
...
test_test.py:3: test_matrixmul PASSED
test_test.py:6: test_reduce 1.0 s
test_test.py:10: test_fft 10.0 GFLOPS
...

The only problem here is that I have to explicitly increase verbosity
level. I'd prefer 'perf' marked tests show their result even for
default verbosity, but I haven't found a way to do it yet.

> Meanwhile, if you haven't already you might want to look at the output
> of "py.test --durations=10" and see about its implementation (mostly
> contained in _pytest/runner.py, grep for 'duration').

Yes, I know about it, but it is not quite what I need:
- it measures the time of the whole testcase, while I usually need to
time only specific part
- it does not allow me to measure anything more complicated (e.g.
GFLOPS, as another variant I may want to see the error value)
- it prints its report after all the tests are finished, while it is
much more convenient to see testcase result as soon as it is finished
(my performance tests may run for quite a long time)

So, the solution I have now is shown below. "pytest_pyfunc_call()"
implementation annoys me the most, because I had to copy-paste it from
python.py, so it exposes some py.test internals and can easily break
when something (seemingly hidden) inside the library is changed.

-----
def pytest_configure(config):
    config.pluginmanager.register(PerfPlugin(config), '_perf')

class PerfPlugin(object):

    def __init__(self, config):
        pass

    def pytest_pyfunc_call(self, __multicall__, pyfuncitem):
        # collect testcase return result
        testfunction = pyfuncitem.obj
        if pyfuncitem._isyieldedfunction():
            res = testfunction(*pyfuncitem._args)
        else:
            funcargs = pyfuncitem.funcargs
            res = testfunction(**funcargs)
        pyfuncitem.result = res

    def pytest_report_teststatus(self, __multicall__, report):
        outcome, letter, msg = __multicall__.execute()

        # if we have some result attached to the testcase, print it
instead of 'PASSED'
        if hasattr(report, 'result'):
            msg = report.result

        return outcome, letter, msg

    def pytest_runtest_makereport(self, __multicall__, item, call):
        report = __multicall__.execute()

        # if the testcase has passed, and has 'perf' marker, process its results
        if call.when == 'call' and report.passed and
hasattr(item.function, 'perf'):
            perf = item.function.perf
            perftype = perf.args[0]
            if perftype == 'seconds':
                report.result = str(item.result) + " s"
            else:
                seconds, operations = item.result
                report.result = str(operations / seconds / 1e9) + " GFLOPS"

        return report
-----