Pytest more than twice slower than Nosetest on trivial test with huge library to load #7111

petRUShka · 2020-04-23T09:54:32Z

a detailed description of the bug or suggestion
output of pip list from the virtual environment you are using
pytest and operating system versions
minimal example if possible

Suppose we have installed huge library like SageMath. Let consider trivial test file:

from sage.all_cmdline import *   # import sage library


class TestClass:
        def test_method(self):
                assert True

It runs for about 1.5 sec with Nosetest

$ time nosetests test.py
.
----------------------------------------------------------------------
Ran 1 test in 0.000s

OK
nosetests test.py  1.38s user 0.14s system 97% cpu 1.567 total

Whereas with pytest it runs for ~4.5 sec!

$ time pytest test.py
platform linux -- Python 3.8.2, pytest-5.4.1, py-1.8.1, pluggy-0.13.1
rootdir: /home/user/pytest, inifile: pytest.ini
plugins: profiling-1.7.0
collecting 1 item 

/usr/lib/python3.8/site-packages/sage/misc/sage_unittest.py:20:
PytestCollectionWarning: cannot collect test class 'TestSuite' because it has a __init__ constructor (from: test.py)

  class TestSuite(object):
collected 1 item

test.py .                                                                                                                                               [100%]

====================================================================== 1 passed in 3.26s ======================================================================
pytest test.py  3.86s user 0.46s system 101% cpu 4.253 total

It looks (according to the warning) like pytest collects some tests from the library itself or may be something else.

P.S. Arch linux with latest upgrades.

This is pytest version 5.4.1, imported from /usr/lib/python3.8/site-packages/pytest/__init__.py
setuptools registered plugins:
  pytest-profiling-1.7.0 at /usr/lib/python3.8/site-packages/pytest_profiling.py

Pip list: http://dpaste.com/34FAXBR

The text was updated successfully, but these errors were encountered:

bluetech · 2020-04-24T12:41:25Z

Which command do you use to run pytest?

petRUShka · 2020-04-24T13:06:37Z

@bluetech It was time pytest test.py, sorry forget to add to original post. Fixed it.

petRUShka · 2020-04-24T13:09:10Z

To comparison just from sage.all_cmdline import * took ~ 1 sec:

$ time python test.py
python test.py  0.80s user 0.08s system 98% cpu 0.900 total

bluetech · 2020-04-24T18:44:49Z

I don't think pytest should look into /usr/lib/python3.8/site-packages in this manner, so this is strange.

If you can provide a minimal reproduction (i.e. a fresh venv with just what's needed installed and a test file, and the commands you run), I'll take a look. I also use Arch Linux and can install Sagemath if needed, even though IIRC it is was quite massive!

petRUShka · 2020-04-24T20:02:17Z

I'm not familiar with venv so I have trouble with it:

pacman -S community/sagemath
python -m venv test_venv
cd test_venv
ln -s /usr/lib/python3.8/site-packages/sage lib/python3.8/site-packages/
ln -s /usr/lib/python3.8/site-packages/cysignals/ ./lib/python3.8/site-packages/
ln -s /usr/lib/python3.8/site-packages/gmpy2/ ./lib/python3.8/site-packages/
ln -s /usr/lib/python3.8/site-packages/cypari2 ./lib/python3.8/site-packages/
ln -s /usr/lib/python3.8/site-packages/psutil ./lib/python3.8/site-packages/
ln -s /usr/lib/python3.8/site-packages/pexpect ./lib/python3.8/site-packages/
ln -s /usr/lib/python3.8/site-packages/ptyprocess ./lib/python3.8/site-packages/
ln -s /usr/bin/sage-maxima.lisp ./bin/
ln -s /usr/lib/python3.8/site-packages/ppl ./lib/python3.8/site-packages/
ln -s /usr/lib/python3.8/site-packages/IPython ./lib/python3.8/site-packages/
ln -s /usr/lib/python3.8/site-packages/traitlets ./lib/python3.8/site-packages/
ln -s /usr/lib/python3.8/site-packages/ipython_genutils ./lib/python3.8/site-packages/
ln -s /usr/lib/python3.8/site-packages/decorator ./lib/python3.8/site-packages/
ln -s /usr/lib/python3.8/site-packages/decorator-4.4.2-py3.8.egg-info ./lib/python3.8/site-packages/
source bin/activate
pip install nose
pip install pytest
cat << EOF > test.py
from sage.all_cmdline import *   # import sage library


class TestClass:
        def test_method(self):
                assert True
EOF

I cannot fix an error of import:

ModuleNotFoundError: No module named 'decorator'

P.S. I can create Vagrantfile for you.

petRUShka · 2020-04-25T08:45:35Z

Possibly it is convinient to use vagrant together with VirtualBox. Vagrant is a tool for managing and configuring virtualised development environments. All of it is in Arch repositories and OSS.

I've created Vagrantfile with provision shell-script:

    sudo pacman -Sy reflector --noconfirm
    sudo reflector --verbose --latest 5 --sort rate --save /etc/pacman.d/mirrorlist
    sudo pacman -Syu python sagemath python-pytest python-nose --noconfirm

    cat << EOF > test.py
from sage.all_cmdline import *   # import sage library


class TestClass:
        def test_method(self):
                assert True
EOF

So it installs on virutal machine reflector (to sort pacman mirrors and turn off dead ones) then it installs SageMath, pytest and nosetest. Last part is -- creating test.py file.

So on this bare ArchLinux installation with minimal dependencies for our needs.

In order to use it you should:

sudo pacman -Sy vagrant virtualbox --noconfirm
mkdir test_vagrant
cd test_vagrant
curl http://dpaste.com/0V5Q4SE.txt > Vagrantfile
vagrant up
vagrant provision
vagrant ssh

Inside virtual environment you can compare runtime and output for 3 commands:

time python test.py
time nosetests test.py
time pytest test.py

My output:

[vagrant@archlinux ~]$ time python test.py

real    0m0.862s
user    0m0.441s
sys     0m0.369s

[vagrant@archlinux ~]$ time nosetests test.py
.
----------------------------------------------------------------------
Ran 1 test in 0.000s

OK

real    0m0.850s
user    0m0.741s
sys     0m0.100s

Full output of pytest: http://dpaste.com/3PM71XB, short version:

[vagrant@archlinux ~]$ time pytest test.py
===================================================================== test session starts =====================================================================
platform linux -- Python 3.8.2, pytest-5.4.1, py-1.8.1, pluggy-0.13.1
rootdir: /home/vagrant
collected 1 item                                                                                                                                              

test.py .                                                                                                                                               [100%]

====================================================================== warnings summary =======================================================================
<A lot of warnings I've ommited>

/usr/lib/python3.8/site-packages/_pytest/fixtures.py:1420
  /usr/lib/python3.8/site-packages/_pytest/fixtures.py:1420: DeprecationWarning: 
  Importing tests from here is deprecated. If you need to use it, please import it directly from sage.tests
  See https://trac.sagemath.org/27337 for details.
    marker = getfixturemarker(obj)


:0
  :0: PytestCollectionWarning: cannot collect 'tests' because it is not a function.

/usr/lib/python3.8/site-packages/sage/misc/sage_unittest.py:20
  /usr/lib/python3.8/site-packages/sage/misc/sage_unittest.py:20: PytestCollectionWarning: cannot collect test class 'TestSuite' because it has a __init__ constructor (from: test.py)
    class TestSuite(object):

-- Docs: https://docs.pytest.org/en/latest/warnings.html

=============================================================== 1 passed, 36 warnings in 2.57s ================================================================

real    0m3.071s
user    0m2.096s
sys     0m0.797s

Still 3-4 times longer than nosetests and some noisy output.

nicoddemus · 2020-04-25T16:54:38Z

If you change:

from sage.all_cmdline import *

To:

import sage.all_cmdline

What happens? I suspect that star import is importing a lot of classes which look like tests to pytest.

EDIT: I bet that's it, all_cmdline imports all which brings a ton of symbols. It doesn't explain why nose is not as slow though. 🤔

petRUShka · 2020-04-25T17:31:14Z

This code is actually what sage -preparse generate

from sage.all_cmdline import *

If I change it to

import sage.all_cmdline

I have almost same time with nosetests and slightly less with python.

[vagrant@archlinux ~]$ time python test.py

real    0m0.744s                                                                                                                                               user    0m0.638s
sys     0m0.103s
[vagrant@archlinux ~]$ time nosetests test.py
.
----------------------------------------------------------------------                                                                                         Ran 1 test in 0.000s                                                           

OK
 
real    0m0.863s                                                                                                                                               user    0m0.751s                                                               
sys     0m0.094s

In case of pytest it give significant speedup and less noisy output:

[vagrant@archlinux ~]$ time python test.py
============================= test session starts ==============================
platform linux -- Python 3.8.2, pytest-5.4.1, py-1.8.1, pluggy-0.13.1
rootdir: /home/vagrant
collected 1 item

test.py .                                                                [100%]

=============================== warnings summary ===============================
/usr/lib/python3.8/site-packages/sage/databases/conway.py:33
  /usr/lib/python3.8/site-packages/sage/databases/conway.py:33: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated since Python 3.3, and in 3.9 it will stop working
    class DictInMapping(collections.Mapping):

/usr/lib/python3.8/site-packages/sage/matrix/matrix_space.py:46
/usr/lib/python3.8/site-packages/sage/matrix/matrix_space.py:46
  /usr/lib/python3.8/site-packages/sage/matrix/matrix_space.py:46: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated since Python 3.3, and in 3.9 it will stop working
    from . import matrix_modn_sparse

/usr/lib/python3.8/site-packages/sage/plot/colors.py:1465
  /usr/lib/python3.8/site-packages/sage/plot/colors.py:1465: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated since Python 3.3, and in 3.9 it will stop working
    class Colormaps(collections.MutableMapping):

/usr/lib/python3.8/site-packages/sage/combinat/ranker.py:22
  /usr/lib/python3.8/site-packages/sage/combinat/ranker.py:22: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated since Python 3.3, and in 3.9 it will stop working
    from collections import Iterable, Sequence

/usr/lib/python3.8/site-packages/sage/geometry/cone.py:690
  /usr/lib/python3.8/site-packages/sage/geometry/cone.py:690: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated since Python 3.3, and in 3.9 it will stop working
    collections.Hashable,

/usr/lib/python3.8/site-packages/sage/geometry/cone.py:1333
  /usr/lib/python3.8/site-packages/sage/geometry/cone.py:1333: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated since Python 3.3, and in 3.9 it will stop working
    collections.Container):

/usr/lib/python3.8/site-packages/sage/geometry/fan.py:1069
  /usr/lib/python3.8/site-packages/sage/geometry/fan.py:1069: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated since Python 3.3, and in 3.9 it will stop working
    collections.Callable,

-- Docs: https://docs.pytest.org/en/latest/warnings.html
======================== 1 passed, 8 warnings in 0.64s =========================

real    0m1.007s
user    0m0.866s
sys     0m0.133s

But still little bit slower and more noisy. And if you are using SageMath with it's preparsing you don't have much choice what to import. And you are right we don't have answer why nose is ok on original code.

nicoddemus · 2020-04-25T17:50:11Z

Hi @petRUShka,

This code is actually what sage -preparse generate

I'm not familiar with sage, what does -prepase do? Generate an empty test suite for you to fill up?

But still little bit slower

Although pytest certainly could use some optimization work, we need to remember that pytest has many more features, so it is expected for it to be slower than nose.

and more noisy

The verbose output is that pytest shows deprecation warnings by default, which is considered a good thing for test runners to do (unittest also started doing this). However you can silence this completely with -p no:warnings on the command-line if you really want to. For even quieter output you can also pass -q. If you want those settings to be permanent, you can create a pytest.ini file:

[pytest]
addopts = -p no:warnings -q

I've cloned the repository, and indeed there are 4294 matches for class Test. I didn't look too much into it but indeed it seems most/all are classes with start with Test. I suspect they are all being brought into the namespace of your test because of the * import, and pytest collects them all as tests because they start with Test, but in the end they don't contain any test methods so it is all a waste of time.

A few options then:

Don't use the * import; this will avoid bringing all those Test* classes into your namespace, and many others. It is in general not considered a good practice in Python anyway to use *.
You can change the default used by pytest to identify a "test class", for example in your pytest.ini:

[pytest]
python_classes = *Suite

Then you need to change the name of your test class in your example from TestClass to ClassSuite suite or something similar.

See python_classes option.

petRUShka · 2020-04-25T17:57:57Z

I'm not familiar with sage, what does -prepase do? Generate an empty test suite for you to fill up?

SageMath code is basically Python code with some minor additions and it is preparsing to Python. You can do it automatically with sage my_file.sage or with

sage -preparse my_file.sage
python my_file.sage.py

Thanks so much for your advises!

By the way is it desirable behavior of pytest to collect tests from import? It looks like kind of unwanted way of things.

nicoddemus · 2020-04-25T18:20:01Z

By the way is it desirable behavior of pytest to collect tests from import? It looks like kind of unwanted way of things.

That's pretty much how every test framework for python works AFAIK, including nose and unittest.

nicoddemus · 2020-04-25T18:20:22Z

@petRUShka can you close the issue if you don't have further questions? Thanks!

petRUShka · 2020-04-25T18:25:35Z

That's pretty much how every test framework for python works AFAIK, including nose and unittest.

If it is so why nose much faster on that code than pytest?

Is it true that speed difference above is by design?

nicoddemus · 2020-04-25T18:37:27Z

If it is so why nose much faster on that code than pytest?

Not sure, someone would need to investigate... but pytest has more overhead during collection because of plugins/fixtures/etc, while nose is much simpler. That many classes being collected might explain the difference. But this is really a hunch.

In other words, both nose and pytest are collecting the same 4.7k+ classes, but because pytest has more overhead, it shows.

But one thing to keep in mind, in a real test suite with 4.7k+ test classes, that difference becomes negligible. Here we are comparing the overhead using a single test, which all it does is assert True. In a real test suite (where most of the time is spent on the tests themselves) I'm sure the difference (if any) would be minimal: nose took 1 second to collect all test cases, pytest took 4.5, but now the suite will take several minutes to complete, so the difference is not important in the end.

petRUShka · 2020-04-25T18:57:47Z

Difference is quite significant on red-green-red cycle with one particular test you are working on. But possibly your advises will help! Thanks a lot.

nicoddemus · 2020-04-26T02:27:50Z

Difference is quite significant on red-green-red cycle with one particular test you are working on.

Ahhh definitely. In that case my previous advice should help, as you stated.

Thanks!

petRUShka changed the title ~~Pytest mor than twice slower than Nosetest on trivial test with huge library to load~~ Pytest more than twice slower than Nosetest on trivial test with huge library to load Apr 23, 2020

bluetech added status: needs information reporter needs to provide more information; can be closed after 2 or more weeks of inactivity type: performance performance or memory problem/improvement labels Apr 24, 2020

nicoddemus closed this as completed Apr 26, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Pytest more than twice slower than Nosetest on trivial test with huge library to load #7111

Pytest more than twice slower than Nosetest on trivial test with huge library to load #7111

petRUShka commented Apr 23, 2020 •

edited

bluetech commented Apr 24, 2020

petRUShka commented Apr 24, 2020

petRUShka commented Apr 24, 2020

bluetech commented Apr 24, 2020

petRUShka commented Apr 24, 2020

petRUShka commented Apr 25, 2020

nicoddemus commented Apr 25, 2020

petRUShka commented Apr 25, 2020 •

edited

nicoddemus commented Apr 25, 2020

petRUShka commented Apr 25, 2020

nicoddemus commented Apr 25, 2020

nicoddemus commented Apr 25, 2020

petRUShka commented Apr 25, 2020

nicoddemus commented Apr 25, 2020 •

edited

petRUShka commented Apr 25, 2020

nicoddemus commented Apr 26, 2020

Pytest more than twice slower than Nosetest on trivial test with huge library to load #7111

Pytest more than twice slower than Nosetest on trivial test with huge library to load #7111

Comments

petRUShka commented Apr 23, 2020 • edited

bluetech commented Apr 24, 2020

petRUShka commented Apr 24, 2020

petRUShka commented Apr 24, 2020

bluetech commented Apr 24, 2020

petRUShka commented Apr 24, 2020

petRUShka commented Apr 25, 2020

nicoddemus commented Apr 25, 2020

petRUShka commented Apr 25, 2020 • edited

nicoddemus commented Apr 25, 2020

petRUShka commented Apr 25, 2020

nicoddemus commented Apr 25, 2020

nicoddemus commented Apr 25, 2020

petRUShka commented Apr 25, 2020

nicoddemus commented Apr 25, 2020 • edited

petRUShka commented Apr 25, 2020

nicoddemus commented Apr 26, 2020

petRUShka commented Apr 23, 2020 •

edited

petRUShka commented Apr 25, 2020 •

edited

nicoddemus commented Apr 25, 2020 •

edited