pytest really slow with python3 on windows

[acerv]

Hello everyone,

my application has 320 tests, half created with unittest suite and half created with pytest.
Now I'm currently porting everything to python 3.7.5, so I started to test the application on python3.

The current setup is the following:
python 2.7: pytest 4.6.6
python 3.7: pytest 5.2.1

When it comes to linux, there's no substantial difference between python2.7 and python3.7: unittests complete in 8 minutes.

But when it comes to Windows, I'm having a HUGE difference between the two versions: python2.7 takes 8 minutes to complete unittests, but python3.7 takes exactly 30 minutes.

The point is that, on Windows with python3.7, the first 40% of tests take a normal amount of time, but then it starts to slow down and even really fast tests take forever.

Do you know what it could be?

Thanks,
Andrea

[blueyed]

Hard to tell, you could try profiling it: https://docs.python.org/3/library/profile.html
Also just knowing if it is CPU or I/O bound would be useful to know already.
I guess that maybe some of your test monkey-patches something that then causes a slowdown.
For that you could bisect your tests, i.e. only run the 2nd half first and see if it still happens, then cut it in half from there.

[acerv]

I took a look the old unittests logs coming from Jenkins. It looks like there's the same issue in python27, but it's way more moderated. There it's really hard to see it.

So I was wrong: the problem comes out with both python27 and python37 and it probably started from a certain pytest version.

Here it is the cProfile output after running unittests on Windows with python3.7.5 and pytest 5.2.

report.txt% stats 40
Fri Nov  8 14:05:03 2019    report.txt

		 48886808 function calls (48568247 primitive calls) in 2731.712 seconds

   Ordered by: internal time
   List reduced from 5945 to 40 due to restriction <40>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
	 4595  494.668    0.108  494.676    0.108 {built-in method nt.listdir}
  9839/13  388.714    0.040  781.056   60.081 c:\.venv37\lib\shutil.py:369(_rmtree_unsafe)
	 9986  253.994    0.025  254.114    0.025 {method 'read' of '_io.TextIOWrapper' objects}
	25221  248.898    0.010  248.915    0.010 {built-in method nt.open}
	29831  246.374    0.008  490.989    0.016 {built-in method io.open}
	20614  158.504    0.008  158.522    0.008 {built-in method nt.stat}
	12876  154.750    0.012  154.752    0.012 {built-in method nt.unlink}
	 9840  120.518    0.012  120.518    0.012 {built-in method nt.scandir}
	 9839  120.288    0.012  120.288    0.012 {built-in method nt.rmdir}
	   97   74.874    0.772   74.874    0.772 {built-in method time.sleep}
	41301   74.359    0.002   74.359    0.002 {method 'acquire' of '_thread.lock' objects}
	 3923   57.305    0.015   57.305    0.015 {method 'read' of '_io.FileIO' objects}
	23679   55.967    0.002  716.666    0.030 c:\python\win_64\3.7.2\Lib\pathlib.py:1185(read_text)
	 3536   32.661    0.009   32.661    0.009 {method 'truncate' of '_io.FileIO' objects}
	 2884   32.497    0.011   32.497    0.011 c:\.venv37\lib\site-packages\colorama\win32.py:109(SetConsoleTextAttribute)
	 2500   23.918    0.010   23.918    0.010 {built-in method nt._isdir}
	15989   21.193    0.001   21.193    0.001 {method 'flush' of '_io.TextIOWrapper' objects}
	14939   16.523    0.001   16.537    0.001 {method 'write' of '_io.TextIOWrapper' objects}
	 1253   12.117    0.010   12.121    0.010 {built-in method nt.mkdir}
	 8100   10.070    0.001   10.070    0.001 {built-in method nt.dup2}
	  416    8.669    0.021    8.669    0.021 {built-in method nt._getfinalpathname}
	   55    8.628    0.157    8.628    0.157 {method 'connect' of '_socket.socket' objects}
	 7072    8.550    0.001    8.550    0.001 {method 'seek' of '_io.FileIO' objects}
	  512    8.139    0.016    8.139    0.016 {method 'read' of '_io.BufferedReader' objects}
   324986    8.135    0.000    8.135    0.000 {built-in method _winapi.WaitForSingleObject}
	  282    7.184    0.025   48.511    0.172 c:\.venv37\lib\site-packages\_pytest\cacheprovider.py:103(set)

[blueyed]

_rmtree_unsafe

Looks suspicious, since there have been changes in that area.
Would be good if you could git-bisect it to find what's causing it. You might explicitly want to skip commits not changing code (changelog etc) if you have to do this on CI / need a full test run to trigger it.

[acerv]

I'm not sure about that call. I just run pytest disabling cacheprovider plugin with the command:

python -m cProfile -o report.txt -m pytest -o log_cli=false -p no:cacheprovider

and this is what I got back from the report (700 seconds less):

Welcome to the profile statistics browser.
report.txt% help

Documented commands (type help <topic>):
========================================
EOF  add  callees  callers  help  quit  read  reverse  sort  stats  strip

report.txt% sort time
report.txt% stats 40
Fri Nov  8 16:28:03 2019    report.txt

		 48283218 function calls (47971800 primitive calls) in 2074.651 seconds

   Ordered by: internal time
   List reduced from 6324 to 40 due to restriction <40>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
	 4719  533.415    0.113  533.424    0.113 {built-in method nt.listdir}
	25286  269.811    0.011  269.828    0.011 {built-in method nt.open}
	10007  259.078    0.026  259.203    0.026 {method 'read' of '_io.TextIOWrapper' objects}
	29894  252.105    0.008  517.338    0.017 {built-in method io.open}
	21369  174.214    0.008  174.233    0.008 {built-in method nt.stat}
	   97   74.892    0.772   74.892    0.772 {built-in method time.sleep}
	23748   67.182    0.003  754.675    0.032 c:\python\win_64\3.7.2\Lib\pathlib.py:1185(read_text)
	 4177   66.078    0.016   66.078    0.016 {method 'read' of '_io.FileIO' objects}
   851/15   34.247    0.040   68.953    4.597 c:\.venv37\lib\shutil.py:369(_rmtree_unsafe)
	 3536   32.536    0.009   32.536    0.009 {method 'truncate' of '_io.FileIO' objects}
	 2851   31.215    0.011   31.215    0.011 c:\.venv37\lib\site-packages\colorama\win32.py:109(SetConsoleTextAttribute)
	 2500   24.553    0.010   24.553    0.010 {built-in method nt._isdir}
	15908   21.034    0.001   21.034    0.001 {method 'flush' of '_io.TextIOWrapper' objects}
	 1518   17.593    0.012   17.595    0.012 {built-in method nt.unlink}
	42553   17.445    0.000   17.445    0.000 {method 'acquire' of '_thread.lock' objects}
	14244   15.453    0.001   15.481    0.001 {method 'write' of '_io.TextIOWrapper' objects}
	 1253   13.161    0.011   13.166    0.011 {built-in method nt.mkdir}
	 8100   11.673    0.001   11.673    0.001 {built-in method nt.dup2}
	  852   10.297    0.012   10.297    0.012 {built-in method nt.scandir}
	  851   10.060    0.012   10.060    0.012 {built-in method nt.rmdir}

[acerv]

I also traced the same execution in linux to check if I'm having so many access to the storage memory, but it looks ok:

report_linux.bin% stats 30
Fri Nov  8 15:41:05 2019    report_linux.bin

		 50119799 function calls (50069719 primitive calls) in 437.503 seconds

   Ordered by: internal time
   List reduced from 4096 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
	   93   93.439    1.005   93.439    1.005 {built-in method time.sleep}
  4071455   52.131    0.000   52.131    0.000 {built-in method posix.waitpid}
	 8085   41.102    0.005   41.102    0.005 {method 'write' of '_io.TextIOWrapper' objects}
	 7158   39.026    0.005   39.026    0.005 {method 'flush' of '_io.TextIOWrapper' objects}
	 6229   21.208    0.003   21.208    0.003 {built-in method posix.lstat}
  4074254   20.485    0.000   42.235    0.000 /home/acer/.pyenv/versions/3.7.5/lib/python3.7/subprocess.py:1573(_internal_poll)
  4076820   17.143    0.000   17.143    0.000 {method 'acquire' of '_thread.lock' objects}
	 4984   13.313    0.003   13.314    0.003 {built-in method posix.stat}
  4073765   10.980    0.000   25.445    0.000 /home/acer/.pyenv/versions/3.7.5/lib/python3.7/queue.py:96(empty)

[blueyed]

Try with -s (to bypass capturing). It looks like it is due to creating many tempfiles (#6034 might help here).
How many tests are there in total?

[blueyed]

Since it only happens after a while it might be related to many entries in the directory, and/or disk filling up?
Try looking at the open file descriptors of the python process, and the location (directory) where the temporary files are created.
Also the "sleep" looks suspicious?

[acerv]

I'll give you the next results when I'm back to the workstation.

time.sleep is used inside unittests and it's ok

[acerv]

I explain better how tests are made: unittests are built in 2 different suites. There's one suite written in plain unittest (core library) and a second suite written in pytest, testing my own pytest plugins using pytester. Indeed, my application is a customization of pytest with 17 plugins.

The total amount of tests is the following:

• core: 224 tests
• plugins: 126 tests

I noticed that pytest starts to slow down when switching from plain core library unittests to the pytest plugins tests. So I run suites splitted in 2 different sessions and, in this way, pytest stops into a correct amount of time.

All suites run wiith -s option:

profile.bin% stats 30
Sat Nov  9 08:34:22 2019    profile.bin

		 34056808 function calls (33862579 primitive calls) in 1028.837 seconds

   Ordered by: internal time
   List reduced from 5030 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
	 2005  321.221    0.160  321.226    0.160 {built-in method nt.listdir}
	11759  100.258    0.009  100.275    0.009 {built-in method nt.stat}
	 7199   99.003    0.014   99.014    0.014 {built-in method nt.open}
	 2632   92.115    0.035   92.152    0.035 {method 'read' of '_io.TextIOWrapper' objects}
	 9386   90.904    0.010  187.620    0.020 {built-in method io.open}
	   90   71.312    0.792   71.312    0.792 {built-in method time.sleep}

The unittest suite:

profile.bin% stats 30
Sat Nov  9 08:38:38 2019    profile.bin

		 26180401 function calls (26126751 primitive calls) in 185.315 seconds

   Ordered by: internal time
   List reduced from 4120 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
	   88   65.318    0.742   65.318    0.742 {built-in method time.sleep}
  2169968   24.969    0.000   24.969    0.000 {built-in method _winapi.WaitForSingleObject}
	  842   24.704    0.029   24.704    0.029 {method 'flush' of '_io.TextIOWrapper' objects}
	34226   11.738    0.000   11.738    0.000 {method 'acquire' of '_thread.lock' objects}
	   49   11.519    0.235   11.786    0.241 C:\.venv37\lib\shutil.py:96(copyfile)
	 4212    5.715    0.001    5.716    0.001 {built-in method nt.stat}

The pytest plugins suite:

profile.bin% stats 30
Sat Nov  9 08:42:12 2019    profile.bin

		 26513300 function calls (26255528 primitive calls) in 108.805 seconds

   Ordered by: internal time
   List reduced from 4780 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
	  235   18.536    0.079   18.536    0.079 {method 'read' of '_io.BufferedReader' objects}
   168291   12.855    0.000   12.855    0.000 {built-in method _winapi.WaitForSingleObject}
		9    9.501    1.056    9.501    1.056 {built-in method time.sleep}
	16585    8.147    0.000    8.168    0.000 {built-in method nt.open}
	17144    8.072    0.000    8.097    0.000 {built-in method nt.stat}
	 4230    6.215    0.001    6.222    0.001 {built-in method nt.listdir}
	11849    4.336    0.000    4.336    0.000 {method 'acquire' of '_thread.lock' objects}
	20689    2.536    0.000   10.545    0.001 {built-in method io.open}
  1483950    1.901    0.000    1.901    0.000 {method 'match' of 're.Pattern' objects}
	 6257    1.709    0.000    1.767    0.000 {method 'read' of '_io.TextIOWrapper' objects}
   135817    1.322    0.000    1.322    0.000 {method 'search' of 're.Pattern' objects}
	 2200    1.021    0.000    1.021    0.000 {built-in method nt._isdir}

[blueyed]

Please git-bisect it, which would really be useful to know.
So using -s makes it twice as fast.
Also check --durations=50 to see which tests are the slowest there maybe.

[acerv]

No, -s is taking the same amount of time as before. I'm running the tests on a laptop now, because my workstation is in another place.

When you speak about "git-bisect", you mean to try different pytest versions until I find the one causing the problem, right?

[acerv]

I downloaded the 5.2.2 source code and tried to run pytest on your unittests.

    (.venv37) C:\userdata\pytest-5.2.2>python -m cProfile -o profile.bin -m pytest

Well...this is the result:

profile.bin% stats 30
Sat Nov  9 11:17:15 2019    profile.bin

		 332214759 function calls (329005244 primitive calls) in 1502.017 seconds

   Ordered by: internal time
   List reduced from 14532 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
	  221  383.738    1.736  383.738    1.736 {built-in method _winapi.WaitForSingleObject}
   377557  186.926    0.000  187.591    0.000 {built-in method nt.stat}
	81772  129.167    0.002  129.326    0.002 {built-in method nt.listdir}
	  562   70.238    0.125   70.238    0.125 {method 'acquire' of '_thread.lock' objects}
	86416   45.911    0.001   46.085    0.001 {built-in method nt.open}
  1771277   36.165    0.000   36.165    0.000 {method 'search' of 're.Pattern' objects}
   157591   33.430    0.000   76.750    0.000 {built-in method io.open}
  8971618   23.913    0.000   23.913    0.000 {method 'match' of 're.Pattern' objects}
	35550   17.761    0.000   17.761    0.000 {built-in method nt._isdir}
  9026161   15.640    0.000   29.288    0.000 c:\python\win_64\3.7.2\Lib\ast.py:184(iter_child_nodes)
  7490161   14.202    0.000   22.737    0.000 c:\python\win_64\3.7.2\Lib\pathlib.py:657(_from_parsed_parts)
  7390202   13.271    0.000   35.576    0.000 c:\python\win_64\3.7.2\Lib\pathlib.py:1011(_make_child_relpath)
	 6994   13.131    0.002  102.569    0.015 C:\userdata\pytest-5.2.2\.venv37\lib\site-packages\_pytest\pathlib.py:101(find_prefixed)
20201499/20175842   13.099    0.000   29.388    0.000 {built-in method builtins.getattr}
	 7341   11.454    0.002   11.454    0.002 {built-in method builtins.compile}
  7444176   10.333    0.000  147.245    0.000 c:\win_64\3.7.2\Lib\pathlib.py:1068(iterdir)
   201038    9.832    0.000    9.832    0.000 {built-in method builtins.dir}

It looks like it's generally a python problem on windows operating system.

Are you testing pytest on windows? Because it looks like the problem is affecting also your unittesting suite.

[blueyed]

When you speak about "git-bisect", you mean to try different pytest versions until I find the one causing the problem, right?

Yes, you can start with tags/releases, but in general you would install pytest editable, and then (after verifying that the current commit, e.g. the features branch, is bad), run git bisect bad - it will ask you to start git-bisecting, and then you select a good commit, do git bisect good there, and from there on it will bisect the commits (try the middle). This is a bit tedious here since we have many (IMHO) unnecessary commits, so when you land on a "add changelog" or "add author" commit you can do "git bisect --skip" (since it appears to take a while for you to verify it -- for this it might be helpful if you could isolate it, so that it is reproducable in minites at least ;))