Test failures due to #3045.

The Appveyor tests may also fail because they ran for over an hour, which seemed to be a hard limit for my account. When I forcibly reran the Python2.7 Library tests, it succeeded but took ~55 minutes.

That's unreasonable. The current test takes 16 minutes; that would mean that the scipy test alone takes ~40 minutes. If that's happening, something is wrong.

I'm referring to the configuration with TEST_LIBRARIES=YES. In the other configuration, they do take about 15 minutes.

There aren't many timestamps in the Appveyor build-log, but here's the link:
https://ci.appveyor.com/project/mobiusklein/pyinstaller/build/job/epeufno6qja3k190

According to the "slowest tests" table at the end the scipy tests took around two minutes a piece, and there are only four scipy tests. It's running all the library tests, though, which is around 150 tests. If we assume that every test takes on average 15 seconds, we're at 37 minutes already. There were other worse offenders, like openpyxl and pandas which took almost 3 minutes.

This takes 30 minutes: https://ci.appveyor.com/project/matysek/pyinstaller/build/2747/job/a0pba0khlqi8n5kw

I'm not sure I have a solid grasp of the state for each test, but given that the Travis builds ran in 30 minutes I'm tempted to go down a path that checks if the scipy hook is getting picked up on every test, but I'm not sure how to do that. There is a lot of runtime magic to trace through, and it's unclear how tests are isolated from each other (or the test harness program for that matter).

Does this sound like a reasonable line of inquiry given that I made so few changes, and if so, which module makes sense to start in?

Don't spend extra time on this now. I'm going to submit a PR to reduce the test time and then we'll see where we are.

I wrote two test scripts, one that imported scipy and one that did not and ran PyInstaller on them. Both executables bundled the scipy DLLs.

I see now that I didn't realize that by adding that hook, it would be executed every time PyInstaller ran, not just every time a script with scipy was analyzed. So those DLLs were added to every test app on Windows, not just the scipy tests' apps.

Wait, what was the test app that did not import SciPy? What is the exact script?

Here is the test script with scipy

import numpy as np
from scipy import linalg
from scipy.optimize import leastsq

print(linalg.pinv(np.eye(100)))


def gaussian(x, m, s2):
    return 1. / np.sqrt(np.pi * s2 * 2) * np.exp((-(x - m) ** 2) / (2 * s2))


def generate_gaussian(x, m, s2):
    return gaussian(x, m, s2)


x = np.linspace(-10, 10)
y = generate_gaussian(x, 0.5, 5)


def fit_gaussian(params, x, y):
    m, s2 = params
    yhat = gaussian(x, m, s2)
    return y - yhat


params, _ = leastsq(fit_gaussian, (0, 1), (x, y))

print(params)

Here is the test script without scipy

import numpy as np


def gaussian(x, m, s2):
    return 1. / np.sqrt(np.pi * s2 * 2) * np.exp((-(x - m) ** 2) / (2 * s2))


def generate_gaussian(x, m, s2):
    return gaussian(x, m, s2)


x = np.linspace(-10, 10)
y = generate_gaussian(x, 0.5, 5)

print(y.mean(), y.sd())

It seems not all scripts fire the scipy hook. A script with just the standard library didn't trigger that hook. I would have expected scipy to trigger including numpy, but not the other way around.

Can you post the trace log as a gist? It's pyinstaller --log-level=TRACE IIRC.

Attempting to make a gist with both logs was throwing a 405 error

no scipy: https://gist.github.com/mobiusklein/d35e803065ec72b6b929c293aa86cd8e
scipy: https://gist.github.com/mobiusklein/43e9642bed9d06ffbb01ecfea4306527

This is where scipy is coming from:

7848 TRACE: _safe_import_hook 'scipy' SourceModule('numpy.testing.nosetester', 'C:\\Users\\Owner\\Anaconda2\\envs\\cython-debug\\lib\\site-packages\\numpy\\testing\\nosetester.py') None 0

I don't see an explicit import in that file on https://github.com/numpy/numpy/blob/master/numpy/testing/nose_tools/nosetester.py

There is indeed an import in a class method https://github.com/numpy/numpy/blob/master/numpy/testing/nose_tools/nosetester.py#L246

That makes sense. The file has been moved in HEAD, but is still there in the released version.

What we need to do is add a hook-numpy with excludedimports = collect_submodules('numpy.testing').

It appears that after excluding numpy.testing, using either mode of expression, numpy becomes unimportable:

Traceback (most recent call last):
  File "C:\Users\Owner\Dev\testing\pyinstaller-scipy\other-script.py", line 1, in <module>
    import numpy as np
  File "C:\Users\Owner\Anaconda2\envs\cython-debug\Lib\site-packages\PyInstaller\loader\pyimod03_importers.py", line 396, in load_module
    exec(bytecode, module.__dict__)
  File "C:\Users\Owner\Anaconda2\envs\cython-debug\lib\site-packages\numpy\__init__.py", line 142, in <module>
    from . import add_newdocs
  File "C:\Users\Owner\Anaconda2\envs\cython-debug\Lib\site-packages\PyInstaller\loader\pyimod03_importers.py", line 396, in load_module
    exec(bytecode, module.__dict__)
  File "C:\Users\Owner\Anaconda2\envs\cython-debug\lib\site-packages\numpy\add_newdocs.py", line 13, in <module>
    from numpy.lib import add_newdoc
  File "C:\Users\Owner\Anaconda2\envs\cython-debug\Lib\site-packages\PyInstaller\loader\pyimod03_importers.py", line 396, in load_module
    exec(bytecode, module.__dict__)
  File "C:\Users\Owner\Anaconda2\envs\cython-debug\lib\site-packages\numpy\lib\__init__.py", line 8, in <module>
    from .type_check import *
  File "C:\Users\Owner\Anaconda2\envs\cython-debug\Lib\site-packages\PyInstaller\loader\pyimod03_importers.py", line 396, in load_module
    exec(bytecode, module.__dict__)
  File "C:\Users\Owner\Anaconda2\envs\cython-debug\lib\site-packages\numpy\lib\type_check.py", line 11, in <module>
    import numpy.core.numeric as _nx
  File "C:\Users\Owner\Anaconda2\envs\cython-debug\Lib\site-packages\PyInstaller\loader\pyimod03_importers.py", line 396, in load_module
    exec(bytecode, module.__dict__)
  File "C:\Users\Owner\Anaconda2\envs\cython-debug\lib\site-packages\numpy\core\__init__.py", line 74, in <module>
    from numpy.testing.nosetester import _numpy_tester
ImportError: No module named testing.nosetester
[9384] Failed to execute script other-script

I'll have to re-enable it for now.

The offending line: https://github.com/numpy/numpy/blob/master/numpy/__init__.py#L151

Oh well. But would you mind modifying the numpy hook to match the scipy hook? These DLLs will be in the next numpy release as well.

Sure.

Since numpy drags scipy in, and numpy is used by many, many big C extension libraries, it follows that the scipy hook is firing more often than I expected. I'm still not sure how that translates to nearly doubling the runtime of the test suite beyond adding a few dozen DLLs to probe on a file system walk. Does PyInstaller do more with DLLs than copy them around?

Actually, since they're added to binaries, they're run through pefile to inspect DLL dependencies. That would explain most of the extra time.

@htgoebel What's the best way to solve this?

Thank you for helping me debug this in real-time. I've only written hooks for my own libraries by trial-and-error. I'll have to pick this up again tomorrow.

What we need to do is add a hook-numpy with
excludedimports = collect_submodules('numpy.testing').

excludedimports = ['numpy.testing']

should be okay, given that this is the only module of the testing package imported superfluously.

I can make these changes, but the tail end of the exploration @xoviat and I did found that we must include numpy.testing because numpy.__init__ imports it for historical reasons. This means that any time we include numpy we also include scipy automatically.

This may explain why the tests are taking so long on Windows, since numpy will be pulled into at least 8 other tests directly, and a difficult to count number indirectly.

Since this adds ~30 DLLs to the bundle that all have to be inspected as @xoviat mentioned, it's unclear if there is an alternative solution that avoids this expensive step. Furthermore, it sounds like these same DLLs will be put in the numpy wheels in the future, meaning that even if we somehow break this linkage between numpy and scipy, in practice people building executables with scipy on Windows will have to analyze 60 DLLs, which could make build times even longer. They may even conflict and send us spiraling into DLL-Hell.

One solution may be to patch numpy with a runtime hook.

Yes, I just screwed up trying to get rid of all those commits. I'm about to start adding the properly committed files if I haven't destroyed things.

Wow, those commits are gone for good! Hopefully you can recover the changes.

I have the files backed up. I've never tried to rewrite published history before.

It looks like you're even with develop, so you can just copy and paste each file from your backup into the repository and commit. Simple but effective.

Did you see some of the feedbacck in the review above? Particularly the copyright header?

I appear to have added it to the scipy hook, but not the NumPy one. Fortunately, this I could just --amend.

Nevermind, the backed up files were the wrong version. I'll get it right tomorrow.

If you want to go for another round, please make sure that the files comply with flake8. Particularly the lines are < 80 characters.

Also, I don't think we can add scipy to requirements.txt due to the significant increase in test time.

Hopefully I've addressed the issues in the format of the hooks and the commits. I've held off on updating the test requirements until discussion confirms whether they should be added.

I don't think it's a big time cost for non-Windows builds, but it might be worth noting that the hooks for pandas, h5py, and matplotlib definitely pull in numpy, and openpyxl and PyQT may pull in numpy. That in turn pulls in scipy.

@xoviat , @htgoebel tests appear to be passing, and I've addressed the stylistic issues. Are there more changes I should make to get the minimum functionality accepted? I've omitted the test requirements update as per @xoviat 's comment.

@htgoebel Did I make the changes you requested?

@htgoebel I'm not sure what else is needed in order for this to be merged. Did I miss something?