Running on multiple CPUs significantly slower

Issue #424 on hold
Trevor Bekolay
created an issue

Before today, with pytest-xdist, py.test -n X would result in significant speedups. Today, it's significantly slower.

$ py.test
================================== test session starts ===========================
platform linux2 -- Python 2.7.6 -- pytest-2.5.1
plugins: xdist
collected 81 items 
.................................................................................
=============================== 81 passed in 32.63 seconds =======================

$ py.test -n 2
================================== test session starts ============================
platform linux2 -- Python 2.7.6 -- pytest-2.5.1
plugins: xdist
gw0 [81] / gw1 [81]
scheduling tests via LoadScheduling
.................................................................................
============================== 81 passed in 252.04 seconds =======================

The only thing that's changed since yesterday is that I did an apt update that installed a new version of Python 2.7. I'm on Debian unstable (sid). All of the Python2.7 packages were updated from version 2.7.6-4 to 2.7.6-5. Is it possible that one of those updates broke thing? I recreated my virtualenvs, but I'm still experiencing slowdown.

Comments (16)

  1. Ronny Pfannschmidt

    Hi Trevor,

    We cant reproduce the problem on our end and and would like to get more information initially we need at least exact versions of:

    • execnet
    • pytest-xdist
    • virtualenv

    also the project you are running the tests on would be helpfull.

  2. Trevor Bekolay reporter

    The project in question is https://github.com/ctn-waterloo/nengo. I'm running the tests on a fresh clone of the master branch.

    Inside my virtualenv, pip freeze gives these version numbers:

    • execnet==1.1
    • pytest-xdist==1.9
    • virtualenv==1.11

    The durations, first without -n.

    $ py.test --durations=20
    ================================== test session starts ===================================
    platform linux2 -- Python 2.7.6 -- pytest-2.5.1
    plugins: pep8, xdist, cache
    collected 146 items 
    
    nengo/tests/test_builder.py .
    nengo/tests/test_connection.py ..........
    nengo/tests/test_context.py ...
    nengo/tests/test_ensemble.py ....................
    nengo/tests/test_ensemble_array.py ......
    nengo/tests/test_examples.py ..................................................................
    nengo/tests/test_helper_piecewise.py .......
    nengo/tests/test_helper_whitenoise.py ..
    nengo/tests/test_model.py ..
    nengo/tests/test_network_basalganglia.py .
    nengo/tests/test_network_circularconv.py ....
    nengo/tests/test_network_integrator.py ...
    nengo/tests/test_network_oscillator.py ...
    nengo/tests/test_node.py ....
    nengo/tests/test_nonlinearities.py ....
    nengo/tests/test_probe.py ...
    nengo/tests/test_simulator.py .......
    
    =============================== slowest 20 test durations ================================
    9.72s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/nef_summary.ipynb]
    8.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/lorenz_attractor.ipynb]
    7.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/ensemble_array.ipynb]
    6.63s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/inhibitory_gating.ipynb]
    5.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/multiplication.ipynb]
    5.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/combining.ipynb]
    5.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/matrix_multiplication.ipynb]
    4.72s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/many_neurons.ipynb]
    4.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_oscillator.ipynb]
    3.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/integrator.ipynb]
    3.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/2d_representation.ipynb]
    3.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/addition.ipynb]
    3.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/squaring.ipynb]
    3.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/oscillator.ipynb]
    3.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/template_integrator.ipynb]
    3.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_integrator2.ipynb]
    3.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_integrator.ipynb]
    2.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/communication_channel.ipynb]
    2.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/two_neurons.ipynb]
    2.62s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/delay_node.ipynb]
    ============================== 146 passed in 150.61 seconds ==============================
    

    With -n 2.

    $ py.test -n 2 --durations=20
    ================================== test session starts ===================================
    platform linux2 -- Python 2.7.6 -- pytest-2.5.1
    plugins: pep8, xdist, cache
    gw0 [146] / gw1 [146]
    scheduling tests via LoadScheduling
    ..................................................................................................................................................
    =============================== slowest 20 test durations ================================
    53.66s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/lorenz_attractor.ipynb]
    44.36s call     nengo/tests/test_connection.py::test_neurons_to_ensemble[nl_nodirect0]
    37.68s call     nengo/tests/test_network_circularconv.py::test_circularconv[nl1]
    34.55s call     nengo/tests/test_connection.py::test_neurons_to_ensemble[nl_nodirect1]
    31.87s call     nengo/tests/test_ensemble_array.py::test_multidim[nl0]
    31.64s call     nengo/tests/test_ensemble_array.py::test_matrix_mul[nl1]
    30.64s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/combining.ipynb]
    30.35s call     nengo/tests/test_ensemble.py::test_product[nl0]
    29.94s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/ensemble_array.ipynb]
    26.58s call     nengo/tests/test_ensemble.py::test_product[nl1]
    25.08s call     nengo/tests/test_network_oscillator.py::test_oscillator[nl1]
    24.26s call     nengo/tests/test_ensemble_array.py::test_multidim[nl1]
    23.94s call     nengo/tests/test_ensemble.py::test_vector[nl0]
    18.04s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_oscillator.ipynb]
    16.74s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/nef_summary.ipynb]
    15.96s call     nengo/tests/test_connection.py::test_neurons_to_neurons[nl_nodirect0]
    14.72s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/multiplication.ipynb]
    13.35s call     nengo/tests/test_ensemble.py::test_vector[nl1]
    13.21s call     nengo/tests/test_ensemble_array.py::test_matrix_mul[nl0]
    12.24s call     nengo/tests/test_connection.py::test_neurons_to_neurons[nl_nodirect1]
    ============================== 146 passed in 354.74 seconds ==============================
    

    And, since I have 8 cores, with -n 8:

    $ py.test -n 8 --durations=20
    ================================== test session starts ===================================
    platform linux2 -- Python 2.7.6 -- pytest-2.5.1
    plugins: pep8, xdist, cache
    gw0 [146] / gw1 [146] / gw2 [146] / gw3 [146] / gw4 [146] / gw5 [146] / gw6 [146] / gw7 [146]
    scheduling tests via LoadScheduling
    ..................................F............................................F.......................F...F................F......F....F.........
    ======================================== FAILURES ========================================
    ... snip (failures were caused by tests that have explicit timeouts) ...
    =============================== slowest 20 test durations ================================
    830.46s call     nengo/tests/test_network_circularconv.py::test_circularconv[nl1]
    746.23s call     nengo/tests/test_connection.py::test_neurons_to_ensemble[nl_nodirect1]
    737.51s call     nengo/tests/test_connection.py::test_neurons_to_ensemble[nl_nodirect0]
    581.66s call     nengo/tests/test_network_circularconv.py::test_circularconv[nl0]
    486.70s call     nengo/tests/test_network_basalganglia.py::test_basic
    365.03s call     nengo/tests/test_ensemble_array.py::test_matrix_mul[nl1]
    352.95s call     nengo/tests/test_ensemble_array.py::test_matrix_mul[nl0]
    329.93s call     nengo/tests/test_ensemble_array.py::test_multidim[nl1]
    328.55s call     nengo/tests/test_ensemble_array.py::test_matrix_mul[nl2]
    327.59s call     nengo/tests/test_ensemble_array.py::test_multidim[nl0]
    312.03s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/nef_summary.ipynb]
    270.49s call     nengo/tests/test_ensemble.py::test_product[nl0]
    264.96s call     nengo/tests/test_ensemble.py::test_product[nl1]
    262.11s call     nengo/tests/test_network_oscillator.py::test_oscillator[nl2]
    215.58s call     nengo/tests/test_ensemble_array.py::test_multidim[nl2]
    209.01s call     nengo/tests/test_network_circularconv.py::test_circularconv[nl2]
    201.51s call     nengo/tests/test_ensemble.py::test_vector[nl0]
    192.94s call     nengo/tests/test_ensemble.py::test_vector[nl1]
    145.86s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/matrix_multiplication.ipynb]
    122.56s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/ensemble_array.ipynb]
    ======================== 7 failed, 139 passed in 1602.41 seconds =========================
    
  3. Trevor Bekolay reporter

    I did a bit more digging. I tried running these tests on my home machine, which is also Debian sid, but hasn't been updated recently, and so is still running Python 2.7.5. Here are the results.

    $ py.test --durations=20
    ================================== test session starts ===================================
    platform linux2 -- Python 2.7.5 -- pytest-2.5.1
    plugins: xdist
    collected 146 items 
    
    nengo/tests/test_builder.py .
    nengo/tests/test_connection.py ..........
    nengo/tests/test_context.py ...
    nengo/tests/test_ensemble.py ....................
    nengo/tests/test_ensemble_array.py ......
    nengo/tests/test_examples.py ..................................................................
    nengo/tests/test_helper_piecewise.py .......
    nengo/tests/test_helper_whitenoise.py ..
    nengo/tests/test_model.py ..
    nengo/tests/test_network_basalganglia.py .
    nengo/tests/test_network_circularconv.py ....
    nengo/tests/test_network_integrator.py ...
    nengo/tests/test_network_oscillator.py ...
    nengo/tests/test_node.py ....
    nengo/tests/test_nonlinearities.py ....
    nengo/tests/test_probe.py ...
    nengo/tests/test_simulator.py .......
    
    =============================== slowest 20 test durations ================================
    10.43s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/lorenz_attractor.ipynb]
    6.52s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/nef_summary.ipynb]
    6.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/inhibitory_gating.ipynb]
    6.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/ensemble_array.ipynb]
    5.52s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/many_neurons.ipynb]
    4.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/matrix_multiplication.ipynb]
    3.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/multiplication.ipynb]
    3.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_oscillator.ipynb]
    3.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/combining.ipynb]
    3.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/addition.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/template_integrator.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/oscillator.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/squaring.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_integrator2.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/communication_channel.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/integrator.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_integrator.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/delay_node.ipynb]
    2.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/2d_representation.ipynb]
    2.21s call     nengo/tests/test_network_circularconv.py::test_circularconv[nl0]
    ============================== 146 passed in 124.54 seconds ==============================
    

    With -n 2 I get the expected speedup:

    $ py.test -n 2 --durations=20
    ================================== test session starts ===================================
    platform linux2 -- Python 2.7.5 -- pytest-2.5.1
    plugins: xdist
    gw0 [146] / gw1 [146]
    scheduling tests via LoadScheduling
    ..................................................................................................................................................
    =============================== slowest 20 test durations ================================
    10.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/lorenz_attractor.ipynb]
    6.52s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/nef_summary.ipynb]
    6.43s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/ensemble_array.ipynb]
    6.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/inhibitory_gating.ipynb]
    5.52s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/many_neurons.ipynb]
    4.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/matrix_multiplication.ipynb]
    4.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/multiplication.ipynb]
    3.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_oscillator.ipynb]
    3.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/combining.ipynb]
    3.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/addition.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/squaring.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/oscillator.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/delay_node.ipynb]
    2.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_integrator.ipynb]
    2.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_integrator2.ipynb]
    2.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/integrator.ipynb]
    2.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/2d_representation.ipynb]
    2.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/template_integrator.ipynb]
    2.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/communication_channel.ipynb]
    2.15s call     nengo/tests/test_network_circularconv.py::test_circularconv[nl0]
    ============================== 146 passed in 64.53 seconds ===============================
    

    Finally, with -n 6, even more speedup.

    $ py.test -n 6 --durations=20
    ================================== test session starts ===================================
    platform linux2 -- Python 2.7.5 -- pytest-2.5.1
    plugins: xdist
    gw0 [146] / gw1 [146] / gw2 [146] / gw3 [146] / gw4 [146] / gw5 [146]
    scheduling tests via LoadScheduling
    ..................................................................................................................................................
    =============================== slowest 20 test durations ================================
    12.43s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/lorenz_attractor.ipynb]
    7.53s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/nef_summary.ipynb]
    7.52s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/inhibitory_gating.ipynb]
    7.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/ensemble_array.ipynb]
    6.52s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/many_neurons.ipynb]
    5.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/matrix_multiplication.ipynb]
    4.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_oscillator.ipynb]
    4.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/multiplication.ipynb]
    3.51s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/addition.ipynb]
    3.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/template_integrator.ipynb]
    3.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/combining.ipynb]
    2.98s call     nengo/tests/test_network_circularconv.py::test_circularconv[nl0]
    2.53s call     nengo/tests/test_connection.py::test_neurons_to_ensemble[nl_nodirect0]
    2.51s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/communication_channel.ipynb]
    2.43s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/controlled_integrator2.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/squaring.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/2d_representation.ipynb]
    2.42s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/integrator.ipynb]
    2.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/two_neurons.ipynb]
    2.41s call     nengo/tests/test_examples.py::test_noexceptions[/home/tbekolay/Code/nengo/examples/oscillator.ipynb]
    ============================== 146 passed in 32.90 seconds ===============================
    

    So, I don't think that the issue is specific to this particular project. I believe that the issue has to do with some recent changes in Python 2.7.6. Tests ran normally in Debian version 2.7.6-4, but became slower in Debian version 2.7.6-5. The changelog notes that in 2.7.6-5, they updated from the Python 2.7 branch as 2013-12-30 to the same branch at 2014-01-11. Are there any commits within that date range that might affect something that pytest-xdist uses?

  4. Anatoly Bubenkov

    I think we should look more into your tests than into test runners :) So as now it's clear that your tests are slower with latest python2.7, You need to look into your code (tests are ok i guess) and try to understand why they can be slower. Algorithm can be: - look to changelog (again) - review your tests - review issues on IPython, because it looks like it's the problem - try create issue on IPython project?

  5. Holger Krekel

    @Anatoly Bubenkov why do you think it couldn't be something in pytest-xdist/execnet's interactions with the python version?

    A good way to verify is to run an empty test suite on the offending python version:

    import pytest
    @pytest.mark.parametrize("arg", range(1000))
    def test_arg(arg):
          import time ; time.sleep(0.01)
    

    and see how it behaves with/without -n. If it gives expected speedups, then it's maybe more likely something in the tests and what they are calling, is causing problems.

  6. Anatoly Bubenkov

    that's exactly what i meant, probably wasn't clear enough, sorry for that 2 topic starter, please provide proof of slowing down the tests because of new version of python when -n is used. Tests should be just plain sleep or even pass, nothing like ipython.

  7. Holger Krekel

    There is a new pytest-xdist and underlying execnet release. @Trevor Bekolay , could you check if the problems persist and if so, try if a simpler test suite also gives the problems on your platform? Without replication or further feedback we will otherwise need to close the issue. Thanks, holger

  8. Trevor Bekolay reporter

    With the new version, the problem persists for my test cases, but a simple test suite (the time.sleep one above) gives the expected speedup, so it has something to do with our test cases. I'll look into this further and make another issue if I can come up with a good minimal example to reproduce the problem. Thanks for your help!

  9. Trevor Bekolay reporter

    Interestingly, I did another sid upgrade today and this issue no longer occurs. More interestingly, it is fixed in both Python 2.7 and 3.3 despite the upgrade only upgrading Python 3.3. A bit of an unsatisfying resolution, but a resolution nonetheless!

  10. Trevor Bekolay reporter

    I'm quite confident the issue isn't IPython related, as when I ran with -n 8 on files that did not import IPython, the issue remained. If I knew the library that was responsible for the slowdown I would report it, but I can't say with any confidence which package is responsible.

  11. Log in to comment