pytest (py.test) very slow startup in cygwin

Question

In cygwin, py.test starts up very slow. It does not look like a collection issue because of two reasons: The same test starts up quickly in linux. And sometimes, if rerun the same test fast enough in cygwin, it starts up in less than 1 second. Running through the time command tells it starts up in either 0.4 seconds, or 11.7 seconds, when supplied with the --collection-only option to avoid running the actual tests. I also added a print to the hooks pytest_configure() and pytest_ignore_collect() to be sure indeed it is before the collection starts.

There have been other questions, linke how to speed up py.test, etc. But I have not seen why under cygwin it is slow, and how to resolve the problem.

Update: Ran it through profiling by python -m cProfile -s cumulat ~/.../py.test conftest.py. Below is the top 20 in the result. I tend to think it is the problem with posix.stat in the cygwin or cygwin python package, or the exists and isfile at various places.

   104699 function calls (102659 primitive calls) in 12.223 CPU seconds
   Ordered by: cumulative time
 ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      1    0.016    0.016   12.223   12.223 {execfile}
      1    0.000    0.000   12.223   12.223 <string>:1(<module>)
      1    0.000    0.000   12.207   12.207 py.test:4(<module>)
      1    0.000    0.000   12.051   12.051 config.py:23(main)
  48/22    0.000    0.000   12.051    0.548 core.py:526(_docall)
  48/22    0.000    0.000   12.051    0.548 core.py:520(__call__)
 129/82    0.000    0.000   12.051    0.147 core.py:387(execute)
      1    0.000    0.000   11.926   11.926 config.py:634(pytest_cmdline_parse)
      1    0.000    0.000   11.926   11.926 config.py:70(_prepareconfig)
      1    0.000    0.000   11.926   11.926 config.py:741(parse)
    4/3    0.000    0.000   11.926    3.975 core.py:97(wrapped_call)
    4/3    0.000    0.000   11.926    3.975 core.py:121(__init__)
      1    0.000    0.000   11.911   11.911 config.py:706(_preparse)
     70    0.000    0.000   11.817    0.169 local.py:363(check)
    260   11.817    0.045   11.817    0.045 {posix.stat}  <<<<this one???
      1    0.000    0.000    9.302    9.302 config.py:698(_initini)
      1    0.000    0.000    9.286    9.286 config.py:896(determine_setup)
    188    0.000    0.000    9.286    0.049 genericpath.py:15(exists)  <<<<this one???
     18    0.000    0.000    6.861    0.381 config.py:845(exists)  <<<<this one???
      1    0.000    0.000    6.861    6.861 config.py:851(getcfg)  <<<<this one???
      1    0.000    0.000    2.531    2.531 config.py:694(pytest_load_initial_conftests)
      1    0.000    0.000    2.531    2.531 config.py:477(setinitial)
      1    0.000    0.000    2.531    2.531 config.py:503(_try_load_conftest)
     13    0.000    0.000    2.531    0.195 config.py:511(getconftestmodules)
     32    0.000    0.000    2.531    0.079 genericpath.py:26(isfile)  <<<<this one???
      8    0.000    0.000    2.425    0.303 common.py:261(exists)
      1    0.000    0.000    0.156    0.156 pytest.py:4(<module>)
      1    0.000    0.000    0.125    0.125 main.py:73(wrap_session)
      1    0.000    0.000    0.125    0.125 config.py:615(do_configure)
      1    0.000    0.000    0.125    0.125 main.py:115(pytest_cmdline_main)

A note about sorting in profiling: It is hard to figure out what keyword to use. Adding a line to print out the sort_arg_defs in pstats.py could give an idea:

$ cat -n /usr/lib/python2.x.x/pstats.py
214         sort_arg_defs = self.get_sort_arg_defs()
215         sort_tuple = ()
216         self.sort_type = ""
217         connector = ""
218         for word in field:
219             sort_tuple = sort_tuple + sort_arg_defs[word][0]
220             self.sort_type += connector + sort_arg_defs[word][1]
221             connector = ", "

Conclusion summary: A malformed file path, like //setup.py (which should be /setup.py without the double-slash at the start), reveals a problem in one of four software parts: the pytest config.determine_setup(), the py.path which is used by pytest config, the cygwin python library, or the cygwin posix implementation.

Answer 1

The problem is that pytest searches for //pytest.ini, //tox.ini, //setup.cfg, and //setup.py. Each of them caused either genericpath.exists() or genericpath.isfile() to consume about 2.5 seconds.

On fix is to add the lines below to genericpath.exists() and genericpath.isfile() to skip those four specific paths.

if path.startswith(r'//'):
    return False

An alternative fix would be to modify _pytest/config.py so it does not form those double-slash in the paths to search.

The code used to find out the exact problem is pasted below. Set myshow = True so it will show how time is consumed for every file it is searching for.

$ diff -u /usr/lib/python2.6/genericpath.py genericpath.py
--- /usr/lib/python2.6/genericpath.py   2012-06-09 08:33:12.000000000 -0700
+++ genericpath.py      2015-06-11 11:46:33.674285900 -0700
@@ -9,14 +9,29 @@
 __all__ = ['commonprefix', 'exists', 'getatime', 'getctime', 'getmtime',
            'getsize', 'isdir', 'isfile']

+myshow = False
+import time as mytime
+mybasetime = mytime.time()
+def myshowtime():
+    currenttime = mytime.time()
+    tmdiff = currenttime - mybasetime
+    global mybasetime
+    mybasetime = currenttime
+    return tmdiff

 # Does a path exist?
 # This is false for dangling symbolic links on systems that support them.
 def exists(path):
     """Test whether a path exists.  Returns False for broken symbolic links"""
+    pretime = myshowtime()
+    if path.startswith(r'//'):
+        if myshow: print "\n  genericpath exists  %8.3f %8.3f False " % (pretime, myshowtime()), " ", path, "\n"
+        return False
     try:
         st = os.stat(path)
+        if myshow: print "\n  genericpath exists  %8.3f %8.3f True  " % (pretime, myshowtime()), " ", path, "\n"
     except os.error:
+        if myshow: print "\n  genericpath exists  %8.3f %8.3f False " % (pretime, myshowtime()), " ", path, "\n"
         return False
     return True

@@ -25,9 +40,15 @@
 # for the same path ono systems that support symlinks
 def isfile(path):
     """Test whether a path is a regular file"""
+    pretime = myshowtime()
+    if path.startswith(r'//'):
+        if myshow: print "\n  genericpath isfile  %8.3f %8.3f False " % (pretime, myshowtime()), " ", path, "\n"
+        return False
     try:
         st = os.stat(path)
+        if myshow: print "\n  genericpath isfile  %8.3f %8.3f True  " % (pretime, myshowtime()), " ", path, "\n"
     except os.error:
+        if myshow: print "\n  genericpath isfile  %8.3f %8.3f False " % (pretime, myshowtime()), " ", path, "\n"
         return False
     return stat.S_ISREG(st.st_mode)