search

aws-powertools / powertools-lambda-python

A developer toolkit to implement Serverless best practices and increase developer velocity.
https://docs.powertools.aws.dev/lambda/python/latest/
MIT No Attribution
2.73k stars 378 forks source link

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

Closed dajmeister closed 6 days ago

dajmeister commented 1 month ago

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)

image

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[bot] commented 1 month ago

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 commented 1 month ago

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:

Please let me know if I missed anything.

Pydantic and Powertools

profile_pydantic_plus_data_validation.log

image

Pydantic import alone

profile_pydantic.log

image
dajmeister commented 1 month ago

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: https://github.com/aws-powertools/powertools-lambda-python/issues/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 commented 1 month ago

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

https://github.com/aws-powertools/powertools-lambda-python/issues/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 https://github.com/aws-powertools/powertools-lambda-python/issues/4372#issuecomment-2122624573, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAZPQBAPU7T63NUFMFFEIUTZDNC33AVCNFSM6AAAAABH54LAFGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCMRSGYZDINJXGM . You are receiving this because you were mentioned.Message ID: @.*** com>

leandrodamascena commented 1 month ago

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

image

Without model_rebuild

image

leandrodamascena commented 4 weeks ago

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 image

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 image

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 commented 3 weeks ago

@dajmeister Not a solution, but at least you'll know that they are working on it: https://github.com/pydantic/pydantic/discussions/6748

leandrodamascena commented 6 days ago

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: https://github.com/pydantic/pydantic/discussions/6748

github-actions[bot] commented 6 days ago

⚠️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.