Bug: Slow import triggered by ApigatewayRestResolver.enable_swagger (Pydantic 2)

[dajmeister]

Expected Behaviour

The enable_swagger method can be used without such a large impact to initialization time.

Current Behaviour

When running the APIGatewayRestResolver.enable_swagger function the following import statement is executed:

from aws_lambda_powertools.event_handler.openapi.models import Server

This import runs for ~300ms (when using Pydantic 2). I suspect this is due to the model_rebuild()s executed at the end of the aws_lambda_powertools.event_handler.openapi.models module.

model_rebuild(Schema)
model_rebuild(Operation)
model_rebuild(Encoding)

profile.log

Code snippet

from aws_lambda_powertools.event_handler import APIGatewayRestResolver

app = APIGatewayRestResolver(enable_validation=True)  
app.enable_swagger(path="dummy")

Possible Solution

No response

Steps to Reproduce

Put this code on a Python file;
Install tuna package using pip install tuna;

Run command

python -X importtime MY_SCRIPT.py 2> profile.log && tuna profile.log

Observe the ~300ms runtime of the import aws_lambda_powertools.event_handler.middlewares.openapi_validation

Powertools for AWS Lambda (Python) version

latest

AWS Lambda function runtime

3.11

Packaging format used

PyPi

Debugging logs

No response

[boring-cyborg]

Thanks for opening your first issue here! We'll come back to you as soon as we can.
In the meantime, check out the #python channel on our Powertools for AWS Lambda Discord: Invite link

[heitorlessa]

Hey @dajmeister, thank you for taking the time to submit a report and I'm stoked you used Tuna to investigate it <3

That's largely pydantic and less on the model rebuild. There are areas we can definitely improve performance here (and I thank you for that!), however that won't be anywhere near close to the 300ms you're experiencing it.

I've created two examples using a simple import pydantic first, and used the same code you shared but importing pydantic before Powertools. There are two things to notice:

• Importing pydantic takes the largest hit (it improved in Pydantic v2)
• After pydantic is imported it is super fast (second profiling file)

Please let me know if I missed anything.

Pydantic and Powertools

profile_pydantic_plus_data_validation.log

Pydantic import alone

profile_pydantic.log

[dajmeister]

Hi @heitorlessa, thanks for responding! The pydantic import is definitely very slow when there is no compiled bytecode. Your profile_pydantic.log file shows an import time of 1.371 seconds. This however gets much better on subsequent imports which reuse the bytecode. In your profile_pydantic_plus_data_validation.log file the pydantic import is only 0.073 seconds.

Your profile_pydantic_plus_data_validation.log example didn't actually trigger the import I was interested in. You hit ModuleNotFoundError: No module named 'jmespath' when running: from aws_lambda_powertools.event_handler import APIGatewayRestResolver (see: #4340).

app.enable_swagger(path="dummy") is the line of code specifically that triggers the "slow" import of interest. Per the profile almost all of the time is spent in the aws_lambda_powertools.event_handler.openapi.models module. I'm not sure what aspect of that module is contributing to the long import time.

[heitorlessa]

I’m in between events and 30+ hours flights so I’ll dig deeper when I’m back home during the week of June 3rd — to set expectations. Thanks for coming back to me quickly

…

On Tue, 21 May 2024 at 23:21, dajmeister ***@***.***> wrote: Hi @heitorlessa <https://github.com/heitorlessa>, thanks for responding! The pydantic import is definitely very slow when there is no compiled bytecode. Your profile_pydantic.log file shows an import time of 1.371 seconds. This however gets much better on subsequent imports which reuse the bytecode. In your profile_pydantic_plus_data_validation.log file the pydantic import is only 0.073 seconds. Your profile_pydantic_plus_data_validation.log example didn't actually trigger the import I was interested in. You hit ModuleNotFoundError: No module named 'jmespath' when running: from aws_lambda_powertools.event_handler import APIGatewayRestResolver (see: #4340 <#4340>). app.enable_swagger(path="dummy") is the line of code specifically that triggers the "slow" import of interest. Per the profile almost all of the time is spent in the aws_lambda_powertools.event_handler.openapi.models module. I'm not sure what aspect of that module is contributing to the long import time. — Reply to this email directly, view it on GitHub <#4372 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAZPQBAPU7T63NUFMFFEIUTZDNC33AVCNFSM6AAAAABH54LAFGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCMRSGYZDINJXGM> . You are receiving this because you were mentioned.Message ID: ***@***.*** com>

[leandrodamascena]

My 2 cents here.
In my opinion, the issue doesn't seem to be with the model_rebuild function at the end of the models.py file. I've been running some tests, and even if I comment out those three lines (which is not a practical solution), the performance difference is only around 30ms. It's worth noting that models.py imports compat.py, and this file imports various components from Pydantic. The performance bottleneck might be stemming from the imports within compat.py, which could be causing delays.

I know that every millisecond matters when running on Lambda, but I believe we may be experiencing a more significant performance regression in some utility/function/class in V2, which could be challenging to detect using tools like Tuna or similar profiling utilities due to Pydanticv2 be a pre-compiled library and we can't inspect methods/functions in detail.

I'll continue digging into the codebase to see if we have a way to improve this.

With model_rebuild

Without model_rebuild

[leandrodamascena]

Hey everyone! I spent some time investigating this a bit further and excluded Powertools from some tests to create a scenario where we are only using Pydantic, without any other dependencies. This helps isolate the issue to understand how Pydantic v1/v2 is behaving in this case.

From my investigation, it seems the way Pydantic handles importing the library and performing validation/serialization has changed between the previous version and the current v2 release. I'm giving my personal opinion here, I can't say that I'm 100% sure, but I think it could be due to the refactoring they did to generate bindings in Rust and/or some underlying architectural changes made by the Pydantic team.

The primary use of Powertools with Pydantic involves model validation and model serialization/deserialization. To reproduce the problem, I performed some tests.

Please consider this event for all the following tests:

event = {
    "name": "company x",
    "address": "street y",
    "employees": [
        {
            "name": "Leandro",
            "roles": [
                {
                "role_name": "DevOps",
                "date_start": "2010-01-01",
                "date_end": "2011-01-01",
                },
                {
                "role_name": "Developer",
                "date_start": "2011-01-01",
                "date_end": "2014-01-01",
                },
            ]
        },
        {
            "name": "X",
            "roles": [
                {
                "role_name": "DevOps",
                "date_start": "2010-01-01",
                "date_end": "2011-01-01",
                },
                {
                "role_name": "Developer",
                "date_start": "2011-01-01",
                "date_end": "2014-01-01",
                },
            ]
        }
    ]
}

First test

This test is using only pydantic + tuna to see how they import Pydantic and I see that in v2 they are loading plugins + core + pydantic + libmetada + fields, while in v1 they just import Pydantic and that's it. In this test, we are just testing ColdStart situations.

Pydantic v1 - code

import datetime
from typing import List
import pydantic

class Role(pydantic.BaseModel):
    role_name: str
    date_start: datetime.date
    date_end: datetime.date

class Employees(pydantic.BaseModel):
    name: str
    roles: List[Role]

class Company(pydantic.BaseModel):
    name: str
    address: str
    employees: List[Employees]

parsed_model = Company.parse_obj(event)
dump_model = parsed_model.dict()

Pydantic v1 - tuna

Import + execution time: 0.032s

Pydantic v2 - code

import datetime
from typing import List
import pydantic

class Role(pydantic.BaseModel):
    role_name: str
    date_start: datetime.date
    date_end: datetime.date

class Employees(pydantic.BaseModel):
    name: str
    roles: List[Role]

class Company(pydantic.BaseModel):
    name: str
    address: str
    employees: List[Employees]

parsed_model = Company.model_validate(event)
dump_model = parsed_model.model_dump()

Pydantic v2 - tuna

Import + execution time: 0.053s

Second test

This test is using only Pydantic + timeit to measure the execution time when ColdStart is not happening.

We know that cold starts is an important thing when working with AWS Lambda and we can see that even after ColdStart (first interaction) the performance of v1 for simple operations remains faster than v2.

Pydantic v1 - code

import timeit
import pydantic

import_module = "import pydantic"

code = ''' 

import datetime
from typing import List


class Role(pydantic.BaseModel):
    role_name: str
    date_start: datetime.date
    date_end: datetime.date

class Employees(pydantic.BaseModel):
    name: str
    roles: List[Role]

class Company(pydantic.BaseModel):
    name: str
    address: str
    employees: List[Employees]

parsed_model = Company.parse_obj(event)
dump_model = parsed_model.dict()
'''

if __name__ == "__main__":
    print("Pydantic version ---->", pydantic.__version__)
    print("Executions ----->", timeit.repeat(stmt=code, setup=import_module, repeat=20, number=1000))

timeit Pydantic v1 - results

(venv) ➜  model-with-union python timeit_pydantic.py
Pydantic version ----> 1.10.16
Executions -----> [0.3602069579064846, 0.3270717919804156, 0.3260737080127001, 0.32723504211753607, 0.32821470801718533, 0.3474197092000395, 0.331315791932866, 0.3305481248535216, 0.34439937490969896, 0.38623699988238513, 0.3627227919641882, 0.41134462505578995, 0.34216895792633295, 0.3431239160709083, 0.331632292130962, 0.32780124992132187, 0.3368915000464767, 0.33176445798017085, 0.32961120805703104, 0.32948400010354817]

Pydantic v2 - code

import timeit
import pydantic

import_module = "import pydantic"

code = ''' 

import datetime
from typing import List


class Role(pydantic.BaseModel):
    role_name: str
    date_start: datetime.date
    date_end: datetime.date

class Employees(pydantic.BaseModel):
    name: str
    roles: List[Role]

class Company(pydantic.BaseModel):
    name: str
    address: str
    employees: List[Employees]

parsed_model = Company.model_validate(event)
dump_model = parsed_model.model_dump()
'''

if __name__ == "__main__":
    print("Pydantic version ---->", pydantic.__version__)
    print("Executions ----->", timeit.repeat(stmt=code, setup=import_module, repeat=20, number=1000))

timeit Pydantic v2 - results

(venv) ➜  model-with-union python timeit_pydantic.py
Pydantic version ----> 2.7.4
Executions -----> [0.7977909999899566, 0.7425271249376237, 0.7596947909332812, 0.7473582909442484, 0.7580573339946568, 0.766909166937694, 0.7376072078477591, 0.7410291249398142, 0.7420287081040442, 0.7721679999958724, 0.7524414169602096, 0.7514087499585003, 0.7521860001143068, 0.7402477920986712, 0.745006832992658, 0.7440242499578744, 0.7420089999213815, 0.7393557080067694, 0.7388893750030547, 0.7491392500232905]

Third test

Using Pyperf to run a benchmark - Check Minimum, Mediam, Mean and Maximum values.

Pydantic v1 - code

import pyperf

runner = pyperf.Runner()

import_module = "import pydantic"

code = ''' 

import datetime
from typing import List


class Role(pydantic.BaseModel):
    role_name: str
    date_start: datetime.date
    date_end: datetime.date

class Employees(pydantic.BaseModel):
    name: str
    roles: List[Role]

class Company(pydantic.BaseModel):
    name: str
    address: str
    employees: List[Employees]

parsed_model = Company.parse_obj(event)
dump_model = parsed_model.dict()
'''

runner.timeit(name="Pydantic test",
              stmt=code,
              setup=import_module)

Pyperf pydantic v1 - result

Total duration: 20.8 sec
Start date: 2024-06-17 15:13:34
End date: 2024-06-17 15:13:52
Raw value minimum: 176 ms
Raw value maximum: 226 ms

Number of calibration run: 1
Number of run with values: 20
Total number of run: 21

Number of warmup per run: 1
Number of value per run: 3
Loop iterations per value: 512
Total number of values: 60

Minimum:         344 us
Median +- MAD:   365 us +- 7 us
Mean +- std dev: 365 us +- 16 us
Maximum:         441 us

  0th percentile: 344 us (-6% of the mean) -- minimum
  5th percentile: 345 us (-5% of the mean)
 25th percentile: 352 us (-3% of the mean) -- Q1
 50th percentile: 365 us (+0% of the mean) -- median
 75th percentile: 370 us (+2% of the mean) -- Q3
 95th percentile: 377 us (+4% of the mean)
100th percentile: 441 us (+21% of the mean) -- maximum

Pydantic v2 - code

import pyperf

runner = pyperf.Runner()

import_module = "import pydantic"

code = ''' 

import datetime
from typing import List


class Role(pydantic.BaseModel):
    role_name: str
    date_start: datetime.date
    date_end: datetime.date

class Employees(pydantic.BaseModel):
    name: str
    roles: List[Role]

class Company(pydantic.BaseModel):
    name: str
    address: str
    employees: List[Employees]

parsed_model = Company.model_validate(event)
dump_model = parsed_model.model_dump()
'''

runner.timeit(name="Pydantic test",
              stmt=code,
              setup=import_module)

Pyperf pydantic v2 - result

Total duration: 20.7 sec
Start date: 2024-06-17 15:10:01
End date: 2024-06-17 15:10:23
Raw value minimum: 208 ms
Raw value maximum: 293 ms

Number of calibration run: 1
Number of run with values: 20
Total number of run: 21

Number of warmup per run: 1
Number of value per run: 3
Loop iterations per value: 256
Total number of values: 60

Minimum:         811 us
Median +- MAD:   861 us +- 31 us
Mean +- std dev: 892 us +- 82 us
Maximum:         1.14 ms

  0th percentile: 811 us (-9% of the mean) -- minimum
  5th percentile: 815 us (-9% of the mean)
 25th percentile: 842 us (-6% of the mean) -- Q1
 50th percentile: 861 us (-3% of the mean) -- median
 75th percentile: 922 us (+3% of the mean) -- Q3
 95th percentile: 1.12 ms (+25% of the mean)
100th percentile: 1.14 ms (+28% of the mean) -- maximum

Number of outlier (out of 723 us..1041 us): 5

Fourth test

Using this project from @samuelcovin, the creator of Pydantic, we have better performance in Pydantic v2 compared to v1. However, this usage scenario is not representative of how we use Pydantic in our application. We do not typically execute validation and go through 100k+ records in our utilities. Our use case is more modest, where we may have around 10k+ records when customers use the BatchProcessor and Parser, but even this is considered an edge case. When running this project with 10 to 20 records, I don't observe any performance difference.

I hope to continue receiving feedback from the community about this issue, but from my perspective, there is not much we can do on the Powertools side.

[CoreOxide]

@dajmeister Not a solution, but at least you'll know that they are working on it:
pydantic/pydantic#6748

[leandrodamascena]

I'm closing this issue because there is already a discussion going on in the Pydantic repository. I'm watching the Pydantic thread and as soon as we see any progress on Pydantic's performance issues, we'll let the customer knows in our release notes.

Pydantic thread: pydantic/pydantic#6748

[github-actions]

⚠️COMMENT VISIBILITY WARNING⚠️

This issue is now closed. Please be mindful that future comments are hard for our team to see.

If you need more assistance, please either tag a team member or open a new issue that references this one.

If you wish to keep having a conversation with other community members under this issue feel free to do so.