Mutation testing with testmon is slow

boxed commented 7 years ago

I'm not sure this is a bug or even something that we can do anything about, but I'd like to have a conversation with you guys about...

So my situation is this: I am using a mutation testing system I wrote (https://github.com/boxed/mutmut) to test a project at work (https://github.com/trioptima/tri.form) and if I use testmon it's significantly slower to run through a mutation test run. So if you're not familiar with mutation testing it's basically running the test suite hundreds of times after making minute changes to the code. This seems like a great use case for testmon, but I end up something like 30% slower than just running pytest directly.

I've tried profiling a single run of testmon by:

running testmon from scratch
making a small mutation inside some function
running testmon with profiler on

...but I couldn't make heads or tails of the profiling output. I guess I might have to run the entire thing through a profiler to get any useful data, but that's a bit annoying since mutmut spawns a new process every time.

I've also implemented a bit of a hack for testmon into mutmut: there's a reference run first without mutations and I save the testmon cache for that run, and then before every mutation I copy back the initial cache. This should mean I trigger fewer test runs, but it didn't make much of a difference.

I have some ideas now:

avoid starting a new process somehow
tell testmon exactly where a change happened (because I know) so it can make the diff faster
do the work to collect the hundreds of profiling runs and combine them and hope something jumps out

What do you think?

blueyed commented 7 years ago

Is it slow for you already with pytest-testmon just being installed? Or only if it is used actually (pytest --testmon)?

boxed commented 7 years ago

Installed is fine. Or at least it's not as slow as with the flag.

tarpas commented 7 years ago

What's the difference between reference run with and without testmon?

As for your ideas, I don't know. I think first is finding out what the problem is.

How many test get deselected by testmon as compared to a run without testmon?

Tibor

On Wed, 6 Sep 2017 at 09:14, Anders Hovmöller notifications@github.com wrote:

Installed is fine. Or at least it's not as slow as with the flag.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/tarpas/pytest-testmon/issues/76#issuecomment-327385457, or mute the thread https://github.com/notifications/unsubscribe-auth/AAIQsH5EiA1XcJwBqoiQXFeDl1hyy5NYks5sfjhGgaJpZM4PNSxA .

boxed commented 7 years ago

Tests seems to get deselected properly what I can tell. That is, a lot of tests are deselected.

Here's some data from a profiling run:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
313905/487    8.791    0.000 2022.214    4.152 {built-in method builtins.exec}
      487    0.006    0.000 2022.206    4.152 run_tests.py:1(<module>)
1855128/24344    1.294    0.000 1959.128    0.080 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py:336(_hookexec)
1855128/24344    3.410    0.000 1959.108    0.080 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py:333(<lambda>)
2705278/24344   14.721    0.000 1959.023    0.080 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py:598(execute)
      487    0.005    0.000 1958.083    4.021 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/config.py:39(main)
1791405/968    3.021    0.000 1958.070    2.023 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py:743(__call__)
850150/47277    3.120    0.000 1941.424    0.041 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py:238(_wrapped_call)
850150/47277    1.217    0.000 1935.149    0.041 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py:263(__init__)
      481    0.001    0.000 1508.998    3.137 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/main.py:138(pytest_cmdline_main)
      481    0.017    0.000 1508.996    3.137 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/main.py:99(wrap_session)
      481    0.003    0.000 1490.797    3.099 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/main.py:142(_main)
      481    0.258    0.001 1419.584    2.951 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/main.py:158(pytest_runtestloop)
    43904    0.291    0.000 1414.823    0.032 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/runner.py:64(pytest_runtest_protocol)
    43904    0.402    0.000 1405.871    0.032 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/runner.py:72(runtestprotocol)
   131264    1.039    0.000 1405.412    0.011 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/runner.py:161(call_and_report)
   133669    0.432    0.000  777.003    0.006 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/runner.py:190(__init__)
   131264    0.561    0.000  723.191    0.006 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/runner.py:179(call_runtest_hook)
   131264    0.329    0.000  720.340    0.005 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/runner.py:182(<lambda>)
     2465    0.015    0.000  655.487    0.266 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/_code/code.py:416(getrepr)
     2465    0.020    0.000  655.465    0.266 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/_code/code.py:657(repr_excinfo)
     2601    0.082    0.000  655.233    0.252 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/_code/code.py:607(repr_traceback)
    16187    0.320    0.000  655.125    0.040 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/_code/code.py:564(repr_traceback_entry)
     2432    3.587    0.001  655.030    0.269 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/main.py:446(_repr_failure_py)
    16187    0.569    0.000  645.566    0.040 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/_code/code.py:490(_getentrysource)
   131264    1.303    0.000  644.947    0.005 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/runner.py:288(pytest_runtest_makereport)
     2399    0.008    0.000  641.716    0.267 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/python.py:578(repr_failure)
     2399    0.019    0.000  641.707    0.267 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/python.py:571(_repr_failure_py)
    16187    0.368    0.000  630.266    0.039 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/_code/code.py:195(getsource)
    18748    0.681    0.000  564.278    0.030 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/_code/source.py:341(getstatementrange_ast)
335417/28898    2.504    0.000  505.138    0.017 <frozen importlib._bootstrap>:958(_find_and_load)
335417/28898    1.770    0.000  504.249    0.017 <frozen importlib._bootstrap>:931(_find_and_load_unlocked)
    18345   60.285    0.003  486.570    0.027 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/_code/source.py:318(get_statement_startend2)
317897/29611    2.026    0.000  484.241    0.016 <frozen importlib._bootstrap>:641(_load_unlocked)
289129/30032    1.139    0.000  469.970    0.016 <frozen importlib._bootstrap_external>:672(exec_module)
374115/31028    0.305    0.000  469.050    0.015 <frozen importlib._bootstrap>:197(_call_with_frames_removed)
    43456    0.125    0.000  464.044    0.011 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/runner.py:109(pytest_runtest_call)
    43456    0.164    0.000  463.183    0.011 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/python.py:1169(runtest)
    43456    0.341    0.000  459.296    0.011 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/python.py:133(pytest_pyfunc_call)
      487    0.006    0.000  449.038    0.922 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/config.py:144(_prepareconfig)
      487    0.001    0.000  449.004    0.922 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/config.py:955(pytest_cmdline_parse)
      487    0.011    0.000  449.003    0.922 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/config.py:1114(parse)
      487    0.026    0.000  447.031    0.918 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/config.py:1076(_preparse)
 80082615   62.167    0.000  380.337    0.000 /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/ast.py:215(walk)
 80070114   36.379    0.000  308.640    0.000 {method 'extend' of 'collections.deque' objects}
202859/161324    0.547    0.000  293.479    0.002 {built-in method builtins.__import__}
160110195  127.792    0.000  272.261    0.000 /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/ast.py:178(iter_child_nodes)
462542072/462265183   95.847    0.000  227.080    0.000 {built-in method builtins.isinstance}
  1720236    3.073    0.000  225.360    0.000 /Users/boxed/Projects/tri.form/venv/lib/python3.6/re.py:286(_compile)
  1473258    0.734    0.000  222.734    0.000 /Users/boxed/Projects/tri.form/venv/lib/python3.6/re.py:231(compile)
    43456    0.112    0.000  220.937    0.005 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/runner.py:104(pytest_runtest_setup)
   120308    0.928    0.000  220.288    0.002 /Users/boxed/Projects/tri.form/venv/lib/python3.6/sre_compile.py:557(compile)
    43456    0.264    0.000  220.182    0.005 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/runner.py:487(prepare)
    43456    0.170    0.000  219.526    0.005 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/python.py:1173(setup)
    43456    0.093    0.000  218.295    0.005 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/fixtures.py:224(fillfixtures)
    43456    0.681    0.000  218.202    0.005 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/_pytest/fixtures.py:381(_fillfixtures)

I think the lines

 80082615   62.167    0.000  380.337    0.000 /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/ast.py:215(walk)
 80070114   36.379    0.000  308.640    0.000 {method 'extend' of 'collections.deque' objects}
...
160110195  127.792    0.000  272.261    0.000 /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/ast.py:178(iter_child_nodes)

Look a bit suspicious, but I'm not sure. Weird that testmon doesn't appear in the profile stats until:

      487    0.013    0.000   30.767    0.063 /Users/boxed/Projects/tri.form/venv/lib/python3.6/site-packages/testmon/pytest_testmon.py:3(<module>)

boxed commented 7 years ago

Here's the full pstats file:

combined.profile.zip

tarpas commented 7 years ago

Can you test the difference in performance between reference run with and without testmon?

Anders, I'll probably not have time to take a look at this in the coming months, sorry about that. However I have some very interesting idea of a new way to use unit tests, so hopefully that will bring more interest to testmon later.

boxed commented 7 years ago

I mentioned the diff in performance above: roughly 30% slower with testmon. Or did you mean something else?

tarpas / pytest-testmon

Mutation testing with testmon is slow #76