Improve performance of the access logger when its disabled #9822

bdraco · 2024-11-11T20:10:05Z

What do these changes do?

Most of the time in the access logger is spent calling clock_gettime, move the check to see if its enabled to an enabled property so we do not have to fetch time and throw it away.

Are there changes in behavior for the user?

no

Is it a substantial burden for the maintainers to support this?

no

Most of the time in the access logger is spent calling clock_gettime, move the check to see if its enabled to an enabled property so we do not have to fetch time and throw it away

codspeed-hq · 2024-11-11T20:17:00Z

CodSpeed Performance Report

Merging #9822 will not alter performance

_{Comparing access_logger_perf (0697774) with master (0f18900)}

Summary

✅ 17 untouched benchmarks

codecov · 2024-11-11T20:18:37Z

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 98.70%. Comparing base (0f18900) to head (0697774).
Report is 2 commits behind head on master.

✅ All tests successful. No failed tests found.

Additional details and impacted files

@@           Coverage Diff           @@
##           master    #9822   +/-   ##
=======================================
  Coverage   98.69%   98.70%           
=======================================
  Files         118      118           
  Lines       36015    36043   +28     
  Branches     4278     4282    +4     
=======================================
+ Hits        35546    35575   +29     
  Misses        315      315           
+ Partials      154      153    -1

Flag	Coverage Δ
CI-GHA	`98.59% <100.00%> (+<0.01%)`	⬆️
OS-Linux	`98.27% <100.00%> (+<0.01%)`	⬆️
OS-Windows	`96.06% <100.00%> (+<0.01%)`	⬆️
OS-macOS	`97.35% <100.00%> (+<0.01%)`	⬆️
Py-3.10.11	`97.19% <100.00%> (+<0.01%)`	⬆️
Py-3.10.15	`97.75% <100.00%> (+<0.01%)`	⬆️
Py-3.11.10	`97.80% <100.00%> (-0.04%)`	⬇️
Py-3.11.9	`97.25% <100.00%> (+0.01%)`	⬆️
Py-3.12.7	`98.34% <100.00%> (+0.01%)`	⬆️
Py-3.13.0	`98.32% <100.00%> (-0.01%)`	⬇️
Py-3.9.13	`97.12% <100.00%> (+<0.01%)`	⬆️
Py-3.9.20	`97.67% <100.00%> (-0.04%)`	⬇️
Py-pypy7.3.16	`97.29% <100.00%> (+<0.01%)`	⬆️
VM-macos	`97.35% <100.00%> (+<0.01%)`	⬆️
VM-ubuntu	`98.27% <100.00%> (+<0.01%)`	⬆️
VM-windows	`96.06% <100.00%> (+<0.01%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

bdraco · 2024-11-11T20:20:37Z

Probably should make it _enabled since we don't want to document this externally

bdraco · 2024-11-11T20:21:45Z

OTOH logger tends to be expensive so an external logger might want to use this as well

docs/logging.rst

…s_logger_perf

asvetlov

Maybe None access logger provides even less overhead?

bdraco · 2024-11-11T21:13:18Z

Maybe None access logger provides even less overhead?

Passing None to access_log in RequestHandler is definitely better but it lacks the ability to easily flip it on/off at run time. Home Assistant turns on aiohttp.access at run time when debugging is on so its still super nice to be able to flip it on and only incur the overhead of the logger.isEnabledFor on every request.

tests/test_web_log.py

bdraco · 2024-11-11T21:36:42Z

Pushed access_logger_perf_sq_311 as a 3.11 test backport for testing on production

bdraco · 2024-11-11T21:43:14Z

Looks to be ~2.4% speed up in the overall request time.

aiohttp_get_profiler.zip

asvetlov

Got you. LGTM.

bdraco · 2024-11-12T14:47:59Z

Thanks for the look!

patchback · 2024-11-12T14:48:08Z

Backport to 3.11: 💔 cherry-picking failed — conflicts found

❌ Failed to cleanly apply 249df6e on top of patchback/backports/3.11/249df6e1599db75a94dc95f63c498545358f6ef8/pr-9822

Backporting merged PR #9822 into master

Ensure you have a local repo clone of your fork. Unless you cloned it
from the upstream, this would be your origin remote.
Make sure you have an upstream repo added as a remote too. In these
instructions you'll refer to it by the name upstream. If you don't
have it, here's how you can add it:
```
$ git remote add upstream https://github.com/aio-libs/aiohttp.git
```

Ensure you have the latest copy of upstream and prepare a branch
that will hold the backported code:

$ git fetch upstream
$ git checkout -b patchback/backports/3.11/249df6e1599db75a94dc95f63c498545358f6ef8/pr-9822 upstream/3.11

Now, cherry-pick PR Improve performance of the access logger when its disabled #9822 contents into that branch:
```
$ git cherry-pick -x 249df6e1599db75a94dc95f63c498545358f6ef8
```
If it'll yell at you with something like fatal: Commit 249df6e1599db75a94dc95f63c498545358f6ef8 is a merge but no -m option was given., add -m 1 as follows instead:
```
$ git cherry-pick -m1 -x 249df6e1599db75a94dc95f63c498545358f6ef8
```
At this point, you'll probably encounter some merge conflicts. You must
resolve them in to preserve the patch from PR Improve performance of the access logger when its disabled #9822 as close to the
original as possible.

Push this branch to your fork on GitHub:

$ git push origin patchback/backports/3.11/249df6e1599db75a94dc95f63c498545358f6ef8/pr-9822

Create a PR, ensure that the CI is green. If it's not — update it so that
the tests and any other checks pass. This is it!
Now relax and wait for the maintainers to process your pull request
when they have some cycles to do reviews. Don't worry — they'll tell you if
any improvements are necessary when the time comes!

🤖 @patchback
I'm built with octomachinery and
my source is open — https://github.com/sanitizers/patchback-github-app.

(cherry picked from commit 249df6e)

…ogger when its disabled (#9828)

bdraco added 3 commits November 11, 2024 14:09

Improve performance of the access logger

ad1d696

Most of the time in the access logger is spent calling clock_gettime, move the check to see if its enabled to an enabled property so we do not have to fetch time and throw it away

Improve performance of the access logger

f898458

Most of the time in the access logger is spent calling clock_gettime, move the check to see if its enabled to an enabled property so we do not have to fetch time and throw it away

Improve performance of the access logger

1ca4bda

Most of the time in the access logger is spent calling clock_gettime, move the check to see if its enabled to an enabled property so we do not have to fetch time and throw it away

bdraco added the backport-3.11 Trigger automatic backporting to the 3.11 release branch by Patchback robot label Nov 11, 2024

document

73bf2a9

bdraco commented Nov 11, 2024

View reviewed changes

docs/logging.rst Outdated Show resolved Hide resolved

bdraco added 3 commits November 11, 2024 14:24

Update docs/logging.rst

a64470a

docs

50ae6b2

Merge remote-tracking branch 'upstream/access_logger_perf' into acces…

9401bd1

…s_logger_perf

psf-chronographer bot added the bot:chronographer:provided There is a change note present in this PR label Nov 11, 2024

bdraco added 4 commits November 11, 2024 14:33

improve example

a31c927

improve example

1422e5f

improve example

20ad229

coverage

95acb75

asvetlov reviewed Nov 11, 2024

View reviewed changes

fix test

7abc142

bdraco added 2 commits November 11, 2024 15:14

fix test

2816858

assert still passes, better to use no cover to verify its not hit

0697774

bdraco commented Nov 11, 2024

View reviewed changes

tests/test_web_log.py Show resolved Hide resolved

bdraco marked this pull request as ready for review November 11, 2024 21:26

bdraco requested a review from webknjaz as a code owner November 11, 2024 21:26

asvetlov approved these changes Nov 12, 2024

View reviewed changes

bdraco merged commit 249df6e into master Nov 12, 2024
40 of 41 checks passed

bdraco deleted the access_logger_perf branch November 12, 2024 14:48

bdraco added a commit that referenced this pull request Nov 12, 2024

Improve performance of the access logger when its disabled (#9822)

0c5c55c

(cherry picked from commit 249df6e)

bdraco added a commit that referenced this pull request Nov 12, 2024

[PR #9822/249df6e backport][3.11] Improve performance of the access l…

7c9b7b9

…ogger when its disabled (#9828)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve performance of the access logger when its disabled #9822

Improve performance of the access logger when its disabled #9822

bdraco commented Nov 11, 2024 •

edited

Loading

codspeed-hq bot commented Nov 11, 2024 •

edited

Loading

codecov bot commented Nov 11, 2024 •

edited

Loading

bdraco commented Nov 11, 2024

bdraco commented Nov 11, 2024

asvetlov left a comment

bdraco commented Nov 11, 2024 •

edited

Loading

bdraco commented Nov 11, 2024

bdraco commented Nov 11, 2024

asvetlov left a comment

bdraco commented Nov 12, 2024

patchback bot commented Nov 12, 2024 •

edited

Loading

Improve performance of the access logger when its disabled #9822

Improve performance of the access logger when its disabled #9822

Conversation

bdraco commented Nov 11, 2024 • edited Loading

What do these changes do?

Are there changes in behavior for the user?

Is it a substantial burden for the maintainers to support this?

codspeed-hq bot commented Nov 11, 2024 • edited Loading

CodSpeed Performance Report

Merging #9822 will not alter performance

Summary

codecov bot commented Nov 11, 2024 • edited Loading

Codecov Report

bdraco commented Nov 11, 2024

bdraco commented Nov 11, 2024

asvetlov left a comment

Choose a reason for hiding this comment

bdraco commented Nov 11, 2024 • edited Loading

bdraco commented Nov 11, 2024

bdraco commented Nov 11, 2024

asvetlov left a comment

Choose a reason for hiding this comment

bdraco commented Nov 12, 2024

patchback bot commented Nov 12, 2024 • edited Loading

Backport to 3.11: 💔 cherry-picking failed — conflicts found

Backporting merged PR #9822 into master

bdraco commented Nov 11, 2024 •

edited

Loading

codspeed-hq bot commented Nov 11, 2024 •

edited

Loading

codecov bot commented Nov 11, 2024 •

edited

Loading

bdraco commented Nov 11, 2024 •

edited

Loading

patchback bot commented Nov 12, 2024 •

edited

Loading