Significant speed degradation from 0.931 to 0.941

[brianmedigate]

Bug Report

I upgraded from 0.931 to 0.941, and the time it takes to run a full run without a cache on my codebase increased from less than 2 minutes to almost 12 minutes.

I was surprised not to find any issues about this yet, maybe I'm just a relatively early adopter, or maybe something about my configuration or codebase is idiosyncratic, although nothing obvious that I can see.

To Reproduce

Not sure exactly how to give enough information to reproduce it, but let's just start with asking if you are aware of an expected performance regression in this version, and if so, if there are any known factors that exacerbate it.

Your Environment

Mypy 0.941 (appears to be the same on 0.940)
Python 3.8.10
Ubuntu 20.04.

An extract of the most salient parts of my configuration:

[mypy]
follow_imports = silent
ignore_missing_imports = True
check_untyped_defs = True
disallow_untyped_defs = True
no_implicit_optional = True
strict_equality = True
warn_redundant_casts = True
python_version = 3.8
platform = linux
plugins = pydantic.mypy
namespace_packages = True

My first suspect was the pydantic plugin but I removed it, to no effect.

[KotlinIsland]

Can you verify that you are using a compiled wheel? run mypy -v . and look for:LOG: Compiled: True

[brianmedigate]

yes

LOG:  Cache Dir:              .mypy_cache
LOG:  Compiled:               True

[KotlinIsland]

The only other think I could recommend is to try some of the other 0.940+dev wheels here: https://github.com/mypyc/mypy_mypyc-wheels and see if you have any luck or can track down where about the slowdown started.

[JukkaL]

This is the first report about a performance regression in 0.941 I remember hearing about, so it seems likely that something in your codebase specifically triggers the regression.

@KotlinIsland's suggestion is a good one. You can also run mypy -v to get more verbose logging and see if most of the time is spent processing a specific module, or whether things are slower overall.

[twoertwein]

Pandas did not see a slowdown: Pandas updated from 0.931 to 0.941 (and at the same time also updated pyright). I'm not certain how much variance there is between github action runs but before mypy+pyright took 4m 27s and afterwards 2m 35s.

[brianmedigate]

Looks like it started being slow in this wheel: https://github.com/mypyc/mypy_mypyc-wheels/releases/tag/v0.940%2Bdev.6c1eb5b36b83ecf959a50100d282ca86186f470f.
Here is the relevant commit (to mypyc): 6c1eb5b
And the commit message mentions:

this slows down the richards benchmark by about 15%

Sounds like it might be relevant?
kudos to @JukkaL for the excellent commit message btw!

I ran with --verbose, and there was a visibly slow SSC of size 111 which took a couple minutes to process, and a couple of visibly slow singletons, but nothing obviously non-proportional to their speeds in the faster version.

Any advice on how to proceed?

[JukkaL]

Any advice on how to proceed?

I can see how that PR could affect performance a little, but over 5x performance loss is much worse than I'd expect. Can you double check a few additional wheels before/after the commit to get more confidence that this is the root cause?

Another idea would be to try running mypy on Python 3.10, and maybe on some different hardware, to investigate if the regression is repeatable or specific to certain configuration.

If the slowdown is consistent, I'd suggest profiling the mypy run to see whether there is some particular function causing the regressions, or whether things are slow overall. I can give instructions if you want to try this (it's not difficult).

As mentioned in the commit message, the "always-defined attributes" optimization could help with performance. I have this close to ready for merging. I could focus on getting it finished, and perhaps you could check performance with this optimization. This will probably take at least one or two weeks, however.

[brianmedigate]

I did a sort of binary search, and everything before it was similar to 0.931, and everything after it was similar to 0.940.
I don't have access to much different hardware, but it replicates on a couple of laptops and in our CI.
I just tried it with python 3.10 and it's about the same.

Yeah I'd be happy to try profiling it, and to try it with the optimization. Thanks!

[brianmedigate]

I tried to find a subset of my code which takes a disproportionate amount of time, but unfortunately it is very interconnected, so it's difficult to tease the parts apart. So far I didn't find anything obviously disproportionate.

[KotlinIsland]

Is the code public? I'm pretty comfortable minifying issues and would be happy to lend a hand.

[brianmedigate]

Unfortunately no, sorry

[bersbersbers]

I'd like to mention a potentially related issue here (#12225). I first noticed it in 0.931, and it certainly hasn't gotten any better with 0.940. I regularly have to clean my mypy cache due to this, maybe that is related and explains why people are having trouble reproducing it.

[JukkaL]

@brianmedigate @bersbersbers I wrote a wiki page about how to profile compiled mypy. Currently I've only verified that the instructions work in Linux, though: https://github.com/python/mypy/wiki/Profiling-Mypy

If you can submit profiles collected from both an older (good) mypy version and the latest mypy version, I can have a look at the them.

[brianmedigate]

Will do, thanks!

[brianmedigate]

Here are profiles from 0.931 and 0.942 on the same codebase, with no cache:
profile.tar.gz

[bersbersbers]

@JukkaL thanks! I finished profiling the comparisons between 0.942 and 0.931 with no difference in runtime, so this does not appear to be regression (and you will not gain any insight by that comparison). I will use your suggestions to post similar results at #12225 to help investigate that root cause.

[JukkaL]

@brianmedigate Thanks for the profiles! The regression is clearly visible, but I have no idea how #11940 might have caused this. However, a few other commits look suspicious.

To move forward, there are few things that could help:

• Collect profiles for 6c1eb5b and the previous commit using wheels from https://github.com/mypyc/mypy_mypyc-wheels. This could confirm the source of the regression.
• Collect profiles also using the non-compiled wheel (...-py3-none-any.whl) using the before/after commits, to see whether the regression is specific to compiled mypy. If it reproduces using interpreted mypy, the regression should be easier to debug.

[JukkaL]

Based on the profile, I suspect that the regression is related to enum types. It may be due to an enum type with a large number values causing large unions with literal types that result in extreme slowdown due to O(n**2) or worse algorithms in mypy. Alternatively, it might be caused by a large union of literal types.

[JukkaL]

If we can narrow down the root cause, hopefully we can optimize the parts of mypy that trigger slow performance. Also, if you can identify a likely culprit in your codebase, it may be possible to find a small code fragment that reproduces this.

[brianmedigate]

Here are the profiles: profile.tar.gz
It does appear to reproduce itself with the non-compiled version.

Yep, it's the enums, good catch!

We have a couple pretty large enums (with a couple of hundred elements each) and one huge one (with 2500 elements). I tried commenting out most of the elements, and the total runtime comes back down to what it was on 0.930.

[JukkaL]

@brianmedigate Thanks for the additional profiles!

I can see the regression also in the non-compiled profile, so the mypyc change is almost certainly not causing this. Could you also try profiling commit 48d810d? It seems like it could be the root cause. Feel free to only collect the profile using either compiled or interpreted mypy. If we can narrow this down to that particular commit, there might some performance improvements I can implement (or we might want to revert the commit).

[brianmedigate]

Looks promising profile.tar.gz

[JukkaL]

Nice! I also made some progress.

After some experimentation, I was able to come up with a smallish example that 48d810d made a lot slower.

First, we have an enum with 500 items generated by this script:

# gen.py
print('from enum import Enum')
print()
print('class E(Enum):')

for i in range(500):
    print('    V%d = "%d"' % (i, i))

Generate e.py like this:

$ python gen.py > e.py

Now this program takes a long time to type check:

from typing import overload
from e import E

@overload
def f(x: int) -> int: ...
@overload
def f(x: object) -> object: ...
def f(x): pass

def g(e: E) -> None:
    f(e.value if e else None)

This took about 15s to type check using 48d810d, but only 2.5s using the previous commit.

It's possible that we can simplify the code further. It looks like increasing the number of enum items by 2x makes type checking about 4x slower, so this could well be some O(n**2) behavior.

[brianmedigate]

Awesome, nice work!

[JukkaL]

@brianmedigate Can you double check if the regression has been fixed in the latest GitHub master? Hopefully #12526 helped.

[brianmedigate]

It's better, but still significantly slower than it was before. Around 7 and a half minutes. Here's the profile:
profile.tar.gz

[JukkaL]

@brianmedigate I landed several additional optimizations. It would be great if you can check 222029b, or a more recent commit. (It will be a few hours at least from now before the wheels are ready.)

[JukkaL]

@brianmedigate Just to let you know that the wheels were built and are now up-to-date.

[brianmedigate]

Down a bit more, to just under 7 minutes

[JukkaL]

The only remaining relatively low-hanging fruit that I see as somewhat likely to help would be the caching of make_simplified_union results (more detail in #12225 (comment)).

There's also a workaround that you might be able to implement fairly easily in your codebase. Replacing e.value calls with str(e.value) calls, when e has an enum type which has many items, might speed up mypy runs. Even if this isn't an acceptable long-term solution, if you manage to use this to speed up mypy runs, this may help you find a short fragment of code that reproduces the slowdown, making it easier to investigate.

[brianmedigate]

Unfortunately it's an enum which is used widely throughout the codebase, and the code which does .value is also scattered around, and is often deep within a database or serialization layer, so there isn't a convenient way to do that, even as a short-term fix.

I thought about somehow making the enum not an enum, i.e. implementing my own enum metaclass (or even vendoring EnumMeta and changing its name or something) in order to get the runtime behavior of an enum without mypy knowing that it's an enum.

Or maybe it would it be possible to implement a way to somehow mark that enum in order to "opt out" of 48d810d for the offending enum? Or in general a way of explicitly giving up accuracy of checks in order to optimize? It might be a bit of a rabbit hole philosophically for mypy to start making things like that configurable, but it would basically be a cleaner way to achieve "making it an enum without being an enum".

[brianmedigate]

Hmm, making it not an enum didn't work, which makes sense now that I think about it, because I lost all of the semantics of enums in mypy, and it just thought the elements were literal values rather than instances of the class.

[brianmedigate]

I was able to just rip out the huge enum and replace it with a class containing constants, without too much damage. Together with your optimizations, the runtime is back down to approximately where it was on 0.930. As far as I'm concerned, this is a stable steady-state; once the next version of mypy is published to pypi I can upgrade.