Mypy: MyPy 0.750 slow startup (or hang) on macOS

[nickwilliams-eventbrite]

• Are you reporting a bug, or opening a feature request?
  _Bug report_
• Please insert below the code you are checking with mypy,
  or a mock-up repro if the source is private. We would appreciate
  if you try to simplify your case to a minimal repro.
  _This is not applicable to this bug report._

• What is the actual behavior/output?
  _Running the mypy . command hangs forever after upgrading to MyPy 0.750 on macOS. Even trying mypy --version to verify the installed version hangs forever. Both commands have to be killed with Ctrl+C (pressing that multiple times is required, actually) after several minutes of waiting for output. Also tried uninstalling and re-installing MyPy from scratch with no luck. Only downgrading to 0.740 solves it from hanging forever, but now mypy --version takes about 45 seconds instead of < 1 second like it was before upgrading and downgrading, even though it outputs 0.740. Here is example output of killing mypy --version under 0.750 after several minutes:_

  $ mypy --version
  ^C^C^C^C^C^C^C^C^CTraceback (most recent call last):
  File "/Users/nwilliams/.virtualenvs/pysoa3/bin/mypy", line 6, in <module>
    from mypy.__main__ import console_entry
  File "/Users/nwilliams/.virtualenvs/pysoa3/lib/python3.7/site-packages/mypy/__main__.py", line 4, in <module>
    from mypy.main import main
  File "mypy/main.py", line 13, in <module>
  File "mypy/build.py", line 33, in <module>
  File "mypy/semanal.py", line 95, in <module>
  File "mypy/typeanal.py", line 30, in <module>
  File "<frozen importlib._bootstrap>", line 978, in _find_and_load
  KeyboardInterrupt
  

• What is the behavior/output you expect?
  For mypy . to run in generally the same amount of time it took previously (~10-15 seconds) and for mypy --version to output and exit instantly, instead of hanging forever like they now do.
• What are the versions of mypy and Python you are using?
  $ python --version Python 3.7.4 $ cat ~/.virtualenvs/pysoa3/lib/python3.7/site-packages/mypy/version.py __version__ = "0.750"
  _The Python version was installed from Homebrew._
  Do you see the same issue after installing mypy from Git master?
  _If I pip install git+https://github.com/python/[email protected], mypy . works. That's the same version (0.750), just installed from Git instead of PyPi. So this appears to be an issue with the PyPi wheel._
• What are the mypy flags you are using? (For example --strict-optional)
  [mypy] python_version = 3.7 check_untyped_defs = True [mypy-tasks] ignore_errors = True [mypy-(several projects listed here).*] ignore_missing_imports = True ...

[ethanhs]

Can you try installing mypy with the pip flag --no-binary=mypy, so that it uses a source release? My guess is mypyc may be causing issues.

[nickwilliams-eventbrite]

pip install mypy==0.750 --no-binary=mypy installed from the source tarball and it appears to work. Both mypy . and mypy --version complete without hanging forever, but mypy --version still takes about 30-45 seconds instead of the usual < 1 second.

In a different virtualenv where I still have MyPy 0.740 installed and never tried to upgrade it, mypy --version takes < 1 second still. So I tried pip install mypy==0.750 --no-binary=mypy in that virtualenv as well, and now mypy --version completes but takes 30-45 seconds.

[nickwilliams-eventbrite]

I should be really clear about something, too: This problem appears to be limited to macOS. On both an Ubuntu machine and an Ubuntu Docker container running on my Mac, 0.750 does not exhibit these symptoms.

[ethanhs]

Hm, okay that is rather odd. Can you please try python -m mypy --version? I'm trying to eliminate that it is the startup script going wrong.

[nickwilliams-eventbrite]

Whoa. python -m mypy --version is _waaayyyy_ faster. < 1 second.

[ethanhs]

Fascinating! My guess is that there is something going on with the startup script that setuptools installs. Can you run python -c 'import pkg_resources' and see how long that takes? Also if you want to debug this in real time, I'll be watching https://gitter.im/python/typing and we can debug via live chat.

[JukkaL]

I can reproduce this on macOS. However, it seems that this only affects the first run:

$ pip install mypy
Collecting mypy
  Using cached https://files.pythonhosted.org/packages/e6/98/4f2acce4aea2ecb01bf5ac80f64a9c56b00373e0887447422343d93bc034/mypy-0.750-cp35-cp35m-macosx_10_6_x86_64.whl
Processing /Users/jukka/Library/Caches/pip/wheels/ee/62/05/814eedac709dcbcfb1ff3aae918ed67f7140314b77e420bb5e/typed_ast-1.4.0-cp35-cp35m-macosx_10_6_intel.whl
Collecting typing-extensions>=3.7.4
  Using cached https://files.pythonhosted.org/packages/03/92/705fe8aca27678e01bbdd7738173b8e7df0088a2202c80352f664630d638/typing_extensions-3.7.4.1-py3-none-any.whl
Collecting mypy-extensions<0.5.0,>=0.4.0
  Using cached https://files.pythonhosted.org/packages/5c/eb/975c7c080f3223a5cdaff09612f3a5221e4ba534f7039db34c35d95fa6a5/mypy_extensions-0.4.3-py2.py3-none-any.whl
Installing collected packages: typed-ast, typing-extensions, mypy-extensions, mypy
Successfully installed mypy-0.750 mypy-extensions-0.4.3 typed-ast-1.4.0 typing-extensions-3.7.4.1
$ time mypy --version
mypy 0.750

real    0m21.926s
user    0m0.176s
sys 0m0.085s
$ time mypy --version
mypy 0.750

real    0m0.321s
user    0m0.157s
sys 0m0.058s
$ time mypy --version
mypy 0.750

real    0m0.197s
user    0m0.129s
sys 0m0.040s

I can also reproduce the issue on older mypy versions, all the way back to 0.700, so it seems that this may be caused by the environment. Using python -m mypy doesn't make any difference in my case (the first run is slow, the second fast).

I'll continue investigating this.

@nickwilliams-eventbrite Can you verify if this only affects the first run after installation (as seems to be the case for me), and if this also happens with mypy 0.700?

[TH3CHARLie]

I verifed on my MacOS machine that the first run is slow and later ones are OK.(From 0.750 back to 0.700, 0.670 is OK) @JukkaL

[JukkaL]

@TH3CHARLie Thanksk for the information!

I think I figured out what triggers the behavior on my Mac: the first run is consistently slow if I have Cisco AnyConnect (VPN) running. Here's the behavior I'm observing (I've repeated this a few times, so it probably isn't random):

1. If AnyConnect is not running, the runtime after installation is consistently below 10s, typically around 4s.
2. Once AnyConnect is running, the runtime is usually at least 14s.
3. After I close AnyConnect, the runtime is still slow after the first subsequent installation, but goes below 10s after subsequent installations (typically around 4s).

I still don't undertand why AnyConnect might be causing this. Perhaps something does a network request when starting mypy? I'm going to debug further, now that I have a repro.

Can somebody who has experienced the issue try closing all applications (other than your terminal) and see if it helps? Try installing mypy several times, since the first run after closing applications may still be slow.

[TH3CHARLie]

@JukkaL quick repro: closed all applications except terminal, install mypy using pip and after installing, turn on/off Wi-Fi:

mypy 0.740 Wi-Fi On: 34.075 total Off: 1.986 total
mypy 0.750 Wi-Fi On: 30.693 total Off: 1.971 total

I have no Cisco AnyConnect but the results indicate that the phenomenon is not closely related to any particular software but some general network requests maybe

Some addups: I tried some other packages:pytest and flake8, both of them run slower on the first run when Wi-Fi is on, and run using normal time on the first run when Wi-Fi is off. The statistical comparison is less obvious compares to mypy, though: 0.8s(On) and 0.2s(Off)

[JukkaL]

Based on fs_usage output, this may be related to XProtect, the built-in anti-malware tool in macOS.

Here's an extract from fs_usage output during a slow mypy run:

13:45:59.062790  stat64                                 /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000009   python3.7.178431
13:45:59.062821  stat64                                 /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000008   python3.7.178431
13:45:59.062829  stat64                                 /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000005   python3.7.178431
13:45:59.062855  open              F=3        (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000025   python3.7.178431
13:45:59.062939  stat64                                 /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000012   syspolicyd.175955
13:45:59.062963  access                       (R___)    /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000019   syspolicyd.175955
13:45:59.063099  stat64                                 /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000007   syspolicyd.175955
13:45:59.063192  getattrlist                            /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000009   syspolicyd.175955
13:45:59.063200  stat64                                 /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000005   syspolicyd.175955
13:45:59.063208  statfs64                               /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000005   syspolicyd.175955
13:45:59.063247  getattrlist                            /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000007   syspolicyd.175955
13:45:59.063262  getattrlist                            /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000013   syspolicyd.175955
13:45:59.069590  stat64                                 /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000012   syspolicyd.177749
13:45:59.070112  open              F=16       (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000017   syspolicyd.177749
13:45:59.070133  open              F=20       (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000015   syspolicyd.177749
13:45:59.070422  getattrlist                            /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000061   syspolicyd.177749
13:45:59.070714  open              F=16       (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000023   syspolicyd.177749
13:45:59.070778  open              F=22       (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000043   syspolicyd.177749
13:45:59.070921  getattrlist                            /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000094   XprotectService.177751
13:45:59.070952  open              F=16       (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000017   syspolicyd.177749
13:45:59.071011  open              F=16       (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000015   syspolicyd.177749
13:45:59.080986  lstat64                                /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000012   XprotectService.177748
13:45:59.081019  stat64                                 /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000005   XprotectService.177748
13:45:59.081049  lstat64                                /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000006   XprotectService.177748
13:45:59.081054  stat64                                 /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000004   XprotectService.177748
13:45:59.081063  open              F=3        (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000045   XprotectService.178036
13:45:59.081086  open              F=4        (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000024   XprotectService.177748
13:45:59.081138  open              F=5        (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000040   XprotectService.177748
13:45:59.081221  open              F=5        (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000033   XprotectService.177748
13:45:59.294047  stat64                                 /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000012   syspolicyd.177752
13:45:59.294665  open              F=20       (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000021   syspolicyd.177752
13:45:59.294687  open              F=22       (R___________)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000016   syspolicyd.177752
13:45:59.295896  open                   [ 20] (R_____N____X)  /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                      0.000014   syspolicyd.177749
13:45:59.295905  stat64                                 /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                            0.000008   syspolicyd.177749
13:45:59.296337  fcntl             F=3   <CMD=98>    /Users/jukka/venv/test/lib/python3.7/site-packages/mypy/semanal_enum.cpython-37m-darwin.so                                                                               0.233475   python3.7.178431

If I'm reading this correctly, most of the time is spent in XProtect. Looking at the output more generally, it seems that importing modules is slow. There is no particular single thing which takes a lot of time, but many somewhat slow operations (since there are many C extensions).

My current hypothesis is that XProtect sometimes slows things down, but once it's scanned a file once, it no longer has a performance impact. If I'm correct, I'm not sure if there's anything we can do about this. Maybe Apple will fix the issue in a future macOS update.

A simple, partial workaround would be to compile fewer modules, assuming Python modules won't be impacted by this. Some modules aren't performance-sensitive so compiling them isn't very important.

[JukkaL]

My investigation still doesn't shed light on why mypy 0.750 would hang forever. It's possible that there are two separate issues.

@nickwilliams-eventbrite Can you verify that 0.750 actually hangs forever and is not just extremely slow (e.g. run it with python -v -v -m mypy --version and see if there's a trickle of output)?

[JukkaL]

@nickwilliams-eventbrite Actually you'd need to run PYTHONVERBOSE=x mypy --version, I think, if python -m mypy is not hanging. Also I'd like to know if mypy --version is still failing after you've successfully run python -m mypy --version.

[JukkaL]

I have another hypothesis: this problem/these problems on happen on Catalina. If you can reproduce the problem, it would be interesting to hear which version of macOS you are running.

[TH3CHARLie]

@JukkaL macOS 10.15.1 Catalina

[nielsbom]

Maybe I can help as well:

I'm on MacOS Catalina 10.15.2
I've installed mypy 0.761 with pip.
I'm using Python 3.7.5.

Running mypy --version the first time gives this traceback:

^CTraceback (most recent call last):
  File "/usr/local/bin/mypy", line 5, in <module>
    from mypy.__main__ import console_entry
  File "/usr/local/lib/python3.7/site-packages/mypy/__main__.py", line 4, in <module>
    from mypy.main import main
  File "mypy/main.py", line 13, in <module>
  File "mypy/build.py", line 34, in <module>
  File "mypy/semanal_main.py", line 39, in <module>
KeyboardInterrupt

Subsequent runs run fast (normal speed I'm assuming).

@JukkaL let me know if you want more debugging runs

[JukkaL]

Here's another idea: We currently generate a C extension shim for each compiled module. Maybe the shims could be Python modules instead? This might speed up the initial run on macOS. I created https://github.com/mypyc/mypyc/issues/742 to track this idea.