Pydantic: [perfomance regression] Generic model creation cause huge slowdown

[bogdandm]

Checks

• [x] I added a descriptive title to this issue
• [x] I have searched (google, github) for similar issues and couldn't find anything
• [x] I have read and followed the docs and still think this is a bug

Bug

After upgrading pydantic to version 1.7 our slowdown detector founds a lot of slow python methods calls. After investigating stacktrace we found source. It is get_caller_module_name() (#1686) function which is extremely slow in _some_ enviroments.

Output of python -c "import pydantic.utils; print(pydantic.utils.version_info())":

             pydantic version: 1.7
            pydantic compiled: True
                 install path: /tv/lib/python3.8/site-packages/pydantic
               python version: 3.8.6 (default, Oct  6 2020, 04:02:53)  [GCC 5.4.0 20160609]
                     platform: Linux-4.9.164-0409164-generic-x86_64-with-glibc2.17
     optional deps. installed: ['typing-extensions']

Note: HDD, docker enviroment with ubuntu14.04 LTS

import typing

import pydantic.generics

CODE_T = typing.TypeVar('CODE_T')


class ResponseDetailCode(pydantic.generics.GenericModel, typing.Generic[CODE_T]):
    ""
    detail: str
    code: CODE_T


with Timer() as t:  # just time.time wrapper
    for i in range(100):
        {'a': ResponseDetailCode[typing.Literal[f'foo{i}', f'bar{i}']]}
print(t.delta)

On 1.5.1 this code takes ~80ms.
On 1.7 - 1700ms (!).
So 1.7+ can not be used on production with HDD disks (on SSD it's like 20% slowdown).

Part of stack trace of class creation (from production env):

  File "/usr/lib/python3.8/posixpath.py", line 379, in abspath
    cwd = os.getcwd()
  File "/usr/lib/python3.8/inspect.py", line 721, in getabsfile
    return os.path.normcase(os.path.abspath(_filename))
  File "/usr/lib/python3.8/inspect.py", line 737, in getmodule
    file = getabsfile(object, _filename)
  File "/usr/lib/python3.8/inspect.py", line 708, in getsourcefile
    if getattr(getmodule(object, filename), '__loader__', None) is not None:
  File "/usr/lib/python3.8/inspect.py", line 1461, in getframeinfo
    filename = getsourcefile(frame) or getfile(frame)
  File "/usr/lib/python3.8/inspect.py", line 1491, in getouterframes
    frameinfo = (frame,) + getframeinfo(frame, context)
  File "/usr/lib/python3.8/inspect.py", line 1514, in stack
    return getouterframes(sys._getframe(1), context)
  File "/tv/lib/python3.8/site-packages/pydantic/generics.py", line 155, in get_caller_module_name
    previous_caller_frame = inspect.stack()[2].frame
  File "/tv/lib/python3.8/site-packages/pydantic/generics.py", line 65, in __class_getitem__
    model_module = get_caller_module_name() or cls.__module__
  File "***/views/models/permissions.py", line 43, in <module>
    ResponseDetailCode[Literal['...']]

It is obvious that inspect.stack() reads many files/file stats from disk directly which is not normal behavior for "create class" operation.

[bogdandm]

[samuelcolvin]

Thanks for reporting. I'm sure this can be improved, I'll look at soon as I have a chance, otherwise pr welcome to improve it

[daviskirk]

I'm a bit confused about the post in the original pull request by @MrMrRobat for this:

We can't set global references to each dynamically created model, as it will either override previous created model, or/and lead to memory leaks.

While that is true, we're creating a global reference for each model in the _generic_types_cache anyway, so wouldn't that also "leak", in which case I would say that we can just go ahead and reference each dynamically created model.

The "overwriting" part shouldn't happen as the _generic_types_cache checks the class and parameters, and even the resolved parameters are also checked in #1989 in case we reference the same parameters (Model[T][T][T][T] is Model[T]).

But I'm probably missing something here.

[MrMrRobat]

Thanks for reporting!

While that is true, we're creating a global reference for each model in the _generic_types_cache anyway, so wouldn't that also "leak", in which case I would say that we can just go ahead and reference each dynamically created model.

That's actually good point, maybe we can drop check if call happened from module.

The "overwriting" part shouldn't happen as the _generic_types_cache checks the class and parameters, and even the resolved parameters are also checked in #1989 in case we reference the same parameters (Model[T][T][T][T] is Model[T]).

The problem is that models in _generic_types_cache are referenced by parameters, while attributes referenced by class names, so to override one you need to make concrete models with identical class names which is not so hard to do:

import urllib.request
from typing import Generic, TypeVar

from pydantic.generics import GenericModel

T = TypeVar("T")

class RequestModel(GenericModel, Generic[T]):
    request: T


class Request:
    ...


RequestModel[urllib.request.Request]
RequestModel[Request]

This code will result in:

NameError: Name conflict: 'GModel[Request]' in '__main__' is already used by <class '__main__.GModel[Request]'>

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "...", line 18, in <module>
    GModel[Request]
  File ".../pydantic/generics.py", line 82, in __class_getitem__
    raise TypeError(f'{model_name!r} already defined above, please consider reusing it') from NameError(
TypeError: 'GModel[Request]' already defined above, please consider reusing it

I think solution would be either to find the way to do away with inspect.stack() in get_caller_module_name() and is_call_from_module(), or drop these functions and set global references by f'{cls.__name__}{some_unique_str}'.

@samuelcolvin, @daviskirk, what do you think?

[daviskirk]

I realized that just dropping the check completely would result in lot's of problems because of naming conflicts ... even just dynamic objects created in functions would cause problems (like in the tests where every model is named Model[T] but of course does something else), so I was completely wrong ;)

set global references by f'{cls.__name__}{some_unique_str}'

Not sure if pickle likes this if the "unique" string is completely dynamic, and if it's not we kind of get the same problem with name overwriting as before don't we?

There's also got to be other python libs that have exactly the same problem of globally referencing dynamically created classes.

[MrMrRobat]

Oh, right, the initial problem was pickling...

The problem is if class created dynamically, we can't guarantee that it will be created by the time of pickle.loads() called, and it may result in even worse consequences: user would be able to use pickle.dumps(), but later on pickle.loads() will fail.

So it seems like dropping this check comepletely is not an option.

[MrMrRobat]

There's also got to be other python libs that have exactly the same problem of globally referencing dynamically created classes.

The other solution was to use __reduce_ex__ method, but I never figured out how it can be implemented with GenericModel.

[MrMrRobat]

@bogdandm, could you run this code in environment where you had 1700ms result previously and share the results?

import sys
from types import ModuleType, FrameType
from typing import TypeVar, Optional, Generic, Literal, Callable, cast

from devtools import Timer

import pydantic.generics

def get_caller_module_name() -> Optional[str]:
    """
    Used inside a function to get its caller module name

    Will only work against non-compiled code, therefore used only in pydantic.generics
    """
    import inspect

    previous_caller_frame = sys._getframe(1).f_back
    if previous_caller_frame is None:
        raise RuntimeError('This function must be used inside another function')

    getmodule = cast(Callable[[FrameType, str], Optional[ModuleType]], inspect.getmodule)
    previous_caller_module = getmodule(previous_caller_frame, previous_caller_frame.f_code.co_filename)
    return previous_caller_module.__name__ if previous_caller_module is not None else None


def is_call_from_module() -> bool:
    """
    Used inside a function to check whether it was called globally

    Will only work against non-compiled code, therefore used only in pydantic.generics
    """
    previous_caller_frame = sys._getframe(1).f_back
    if previous_caller_frame is None:
        raise RuntimeError('This function must be used inside another function')
    return previous_caller_frame.f_locals is previous_caller_frame.f_globals


CODE_T = TypeVar('CODE_T')

class ResponseDetailCode(pydantic.generics.GenericModel, Generic[CODE_T]):
    detail: str
    code: CODE_T


def clear_cache():
    pydantic.generics._generic_types_cache.clear()

    for k, v in globals().copy().items():
        if isinstance(v, type) and issubclass(v, ResponseDetailCode) and v is not ResponseDetailCode:
            globals().pop(k)


with Timer('before patch (using inspect.stack())'):
    for i in range(100):
        {'a': ResponseDetailCode[Literal[f'foo{i}', f'bar{i}']]}

pydantic.generics.is_call_from_module = is_call_from_module
pydantic.generics.get_caller_module_name = get_caller_module_name

clear_cache()
with Timer('after patch (using sys._getframe())'):
    for i in range(100):
        {'a': ResponseDetailCode[Literal[f'foo{i}', f'bar{i}']]}

pydantic.generics.is_call_from_module = lambda: True
pydantic.generics.get_caller_module_name = lambda: '__main__'

clear_cache()
with Timer('before 1.7'):
    for i in range(100):
        {'a': ResponseDetailCode[Literal[f'foo{i}', f'bar{i}']]}

I'm getting this results on SSD:

before patch (using inspect.stack()): 0.120s elapsed
after patch (using sys._getframe()): 0.066s elapsed
before 1.7: 0.065s elapsed

[PrettyWood]

Just tried on https://repl.it and got the following result with 10000 instead of 100

before patch (using inspect.stack()): 46.208s elapsed
after patch (using sys._getframe()): 33.443s elapsed
before 1.7: 34.409s elapsed

It seems like they use HDD

> open('/sys/block/sda/queue/rotational').read()
'1\n'

Let's wait for @bogdandm answer but it feels like a good solution @MrMrRobat 👍

[bogdandm]

It's still not ideal but it is definitely better :tada:

Docker with HDD and legacy ubuntu.

before patch (using inspect.stack()) 0:00:01.647562
after patch (using sys._getframe()) 0:00:00.264206
before 1.7 0:00:00.080809

And on my SSD for comparison (same python enviroment).

before patch (using inspect.stack()) 0:00:00.161573
after patch (using sys._getframe()) 0:00:00.052670
before 1.7 0:00:00.050883

[bogdandm]

Call graph of script part "after patch", maybe it will help.

[MrMrRobat]

Thanks for the graph!

I'm gonna make PR with patch today and it should be even faster, than the one I came up with first.