poetry startup time is slow

[yoav-orca]

• I am on the latest Poetry version.
• I have searched the issues of this repo and believe that this is not a duplicate.
• If an exception occurs when executing a command, I executed it again in debug mode (-vvv option).

• OS version and name: macOS cataline
• Poetry version: 1.1.4
• The contents of your pyproject.toml file:

[tool.poetry]
name = "poetry_slow_startup"
version = "0.1.0"
description = ""
authors = ["John Doe <[email protected]>"]

[tool.poetry.dependencies]
python = "^3.9"

[tool.poetry.dev-dependencies]

[build-system]
requires = ["poetry-core>=1.0.0"]
build-backend = "poetry.core.masonry.api"

Issue

I'll start by saying that poetry is awesome, it made me and my team more productive since we migrated from Pipenv!

I use the poetry run/shell commands a lot in my daily routine, I also use poetry as a wrapper to other tools that I use from my IDE & git hooks. However, there's an overhead when running commands with poetry:

$ time /usr/bin/true
/usr/bin/true  0.00s user 0.00s system 69% cpu 0.003 total
$ time /usr/bin/true
/usr/bin/true  0.00s user 0.00s system 72% cpu 0.006 total
$ time /usr/bin/true
/usr/bin/true  0.00s user 0.00s system 78% cpu 0.005 total

# now with poetry

$ time poetry run /usr/bin/true
poetry run /usr/bin/true  0.54s user 0.15s system 72% cpu 0.944 total
$ time poetry run /usr/bin/true
poetry run /usr/bin/true  0.48s user 0.09s system 98% cpu 0.581 total
$ time poetry run /usr/bin/true
poetry run /usr/bin/true  0.52s user 0.14s system 78% cpu 0.844 total

It seems that running commands with poetry adds between 570-930ms latency to the command.

I tried to profile the issue, and it seems that most of the time is spent in the import statements before the main is called, the main itself is only 90ms.
I tried to profile the imports with PYTHONPROFILEIMPORTTIME as follows:

PYTHONPROFILEIMPORTTIME=1 poetry run /usr/bin/true 2>imports.txt

I visualized the results using tuna as follows:

tuna imports.txt

The results indicate that most of the time is used in imports that are not used by the run/shell commands.
I propose using LazyLoader to improve the startup time and responsiveness of poetry.

[sinoroc]

Probably could have been filed as "feature request" instead of "bug".

[yoav-orca]

@sinoroc I wasn't sure, because it didn't feel like a feature request per se, because older versions of poetry were faster (poetry 1.0 is consistently under 350ms), but I can change the label

[sinoroc]

@sinoroc I wasn't sure, because it didn't feel like a feature request per se, because older versions of poetry were faster (poetry 1.0 is consistently under 350ms), but I can change the label

No worries. I just mentioned it. Maintainers will decide.

Maybe it is worth editing the first message to clearly show that it could be a regression (i.e. it used to be faster).

[jules-ch]

A bunch of imports for commands need to be moved to handle to delay imports.
It's done like that for some commands & imports but not all.

[yoav-orca]

@jules-ch could you point me to specific candidates, I'll try to send a PR

[jules-ch]

#3618 might help. I think we can wait & see if that improves performance.

[yoav-orca]

@jules-ch I gave poetry 1.1.5 a try, it did slightly improve things, but it's still about ~500ms slower than native code run.
I re-run tuna to see where the time is spent on imports, the situation is not very different, most of the time is spent before the main logic happens.

[abn]

@yoav-orca can you try master? Should get you to around ~300ms. And #3938 will get you to ~250ms. (obviously times here are dependent on externa factors too).

Using pipx

pipx install --suffix=@3938 'poetry @ git+https://github.com/python-poetry/poetry.git@refs/pull/3938/head'
PYTHONPROFILEIMPORTTIME=1 poetry@3938 run /usr/bin/true 2>imports.txt 

pipx install --suffix=@master 'poetry @ git+https://github.com/python-poetry/poetry.git@master'
PYTHONPROFILEIMPORTTIME=1 poetry@master run /usr/bin/true 2>imports.txt 

[yoav-orca]

Hi @abn I tried both versions

My setup:
macOS Catalina
Python 3.9.4

Empty poetry

mkdir test-proj
cd test-proj
poetry init -n

With 3938:

» time poetry@3938 run /usr/bin/true
poetry@3938 run /usr/bin/true  0.31s user 0.07s system 97% cpu 0.391 total
» time poetry@3938 run /usr/bin/true
poetry@3938 run /usr/bin/true  0.32s user 0.08s system 97% cpu 0.403 total
» time poetry@3938 run /usr/bin/true
poetry@3938 run /usr/bin/true  0.31s user 0.07s system 97% cpu 0.399 total

At master:

» time poetry@master run /usr/bin/true
poetry@master run /usr/bin/true  0.31s user 0.07s system 97% cpu 0.394 total
» time poetry@master run /usr/bin/true
poetry@master run /usr/bin/true  0.32s user 0.07s system 97% cpu 0.405 total
» time poetry@master run /usr/bin/true
poetry@master run /usr/bin/true  0.31s user 0.07s system 97% cpu 0.396 total

The diagram looks very similar to both branches, I'm adding the diagram for 3938:

BTW when running on a non-empty project (~50 dependencies) I see a spike of 100-150 ms on startup time.

[lafrenierejm]

@abn, @yoav-orca May I ask what the target performance is for this issue to be considered resolved?

Based on yoav-orca's latest comment, it looked like the timing of master at that point in time was ~350ms and similar to 1.0's timing:

older versions of poetry were faster (poetry 1.0 is consistently under 350ms)

[systematicguy]

We really need this to get going/resolved as it is the sole serious issue in the 1.2 project besides another one.

[neersighted]

I'm going to close this as current speeds are not a regression -- I'd suggest opening issues for specific commands/sections of code with specific targets if anyone finds any unnecessary hot loops or blocking behavior.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.