gh-105623 Fix performance degradation in logging RotatingFileHandler #105887

zhatt · 2023-06-17T16:17:30Z

The check for whether the log file is a real file is expensive on NFS filesystems. This commit reorders the rollover condition checking to not do the file type check if the expected file size is less than the rotation threshold.

Issue: Poor performance on logging.RotatingFileHandler due to fix to #89564 #105623

…ndler The check for whether the log file is a real file is expensive on NFS filesystems. This commit reorders the rollover condition checking to not do the file type check if the expected file size is less than the rotation threshold.

cpython-cla-bot · 2023-06-17T16:17:57Z

All commit authors signed the Contributor License Agreement.

Misc/NEWS.d/next/Library/2023-06-17-09-07-06.gh-issue-105623.5G06od.rst

…G06od.rst Co-authored-by: Oleg Iarygin <oleg@arhadthedev.net>

bedevere-bot · 2023-06-19T08:10:47Z

🤖 New build scheduled with the buildbot fleet by @vsajip for commit 84ad7d8 🤖

If you want to schedule another build, you need to add the 🔨 test-with-buildbots label again.

arhadthedev · 2023-06-19T10:38:03Z

From buildbots:

Objects/object.c:2197: _Py_ForgetReference: Assertion failed: invalid object chain
Enable tracemalloc to get the memory block allocation traceback
object address  : 0x7ff344737770
object refcount : 0
object type     : 0x560543494660
object type name: tuple
object repr     : <refcnt 0 at 0x7ff344737770>

This PR is not the cause (Python-only change cannot break reference counting). However, we need to fix the crash before merging the PR.

bdraco · 2023-07-13T04:23:57Z

Lib/logging/handlers.py

-        # See bpo-45401: Never rollover anything other than regular files
-        if os.path.exists(self.baseFilename) and not os.path.isfile(self.baseFilename):
-            return False


Even with a local file-system this is a substantive chunk of the run time

@bdraco I'm not familiar with the report generated by py-spy. Are you seeing that the os.path.exists() and os.path.isfile() are expensive or the self.format()? The self.format() is probably a different bug that needs fixed since rollover is formatting the message once to get its length and then emit later formats it again.

I'd expect the format and emit to be expensive here (relatively ... the logger is quite busy). What is unexpected is the cost of os.path.exists and os.path.isfile which is solved by this PR.

Sorry for the lack of clarity. This looks like a good fix and I wanted to point out the problem is not limited to NFS.

Under normal usage, self.baseFilename doesn't change. Perhaps we just cache the result of the existence/is-file test when we open the file? Wouldn't that be a better approach?

serhiy-storchaka

LGTM. In the current paradigm it is the right solution.

I wonder whether it would be better to perform this check in doRollover(), before renaming files. But this is a different and not so easy issue.

fantabolous · 2024-06-27T13:55:19Z

Thanks, in my rather logging-heavy Windows NTFS project, shouldRollover went from 25-35% of cpu to <2% after monkey patching this in. (According to yappi.)

miss-islington-app · 2024-06-28T08:52:46Z

Thanks @zhatt for the PR, and @serhiy-storchaka for merging it 🌮🎉.. I'm working now to backport this PR to: 3.12.
🐍🍒⛏🤖

miss-islington-app · 2024-06-28T08:52:46Z

Thanks @zhatt for the PR, and @serhiy-storchaka for merging it 🌮🎉.. I'm working now to backport this PR to: 3.13.
🐍🍒⛏🤖

…ndler (pythonGH-105887) The check for whether the log file is a real file is expensive on NFS filesystems. This commit reorders the rollover condition checking to not do the file type check if the expected file size is less than the rotation threshold. (cherry picked from commit e9b4ec6) Co-authored-by: Craig Robson <craig@zhatt.com> Co-authored-by: Oleg Iarygin <oleg@arhadthedev.net>

bedevere-app · 2024-06-28T08:52:59Z

GH-121116 is a backport of this pull request to the 3.12 branch.

bedevere-app · 2024-06-28T08:53:04Z

GH-121117 is a backport of this pull request to the 3.13 branch.

serhiy-storchaka · 2024-06-28T08:55:52Z

Thank you for your contribution @zhatt, and thank you for reminder @fantabolous. I forgot about this PR.

…andler (GH-105887) (GH-121116) The check for whether the log file is a real file is expensive on NFS filesystems. This commit reorders the rollover condition checking to not do the file type check if the expected file size is less than the rotation threshold. (cherry picked from commit e9b4ec6) Co-authored-by: Craig Robson <craig@zhatt.com> Co-authored-by: Oleg Iarygin <oleg@arhadthedev.net>

…andler (GH-105887) (GH-121117) The check for whether the log file is a real file is expensive on NFS filesystems. This commit reorders the rollover condition checking to not do the file type check if the expected file size is less than the rotation threshold. (cherry picked from commit e9b4ec6) Co-authored-by: Craig Robson <craig@zhatt.com> Co-authored-by: Oleg Iarygin <oleg@arhadthedev.net>

…ndler (pythonGH-105887) The check for whether the log file is a real file is expensive on NFS filesystems. This commit reorders the rollover condition checking to not do the file type check if the expected file size is less than the rotation threshold. Co-authored-by: Oleg Iarygin <oleg@arhadthedev.net>

zhatt requested a review from vsajip as a code owner June 17, 2023 16:17

bedevere-bot added the awaiting review label Jun 17, 2023

bedevere-bot mentioned this pull request Jun 17, 2023

Poor performance on logging.RotatingFileHandler due to fix to #89564 #105623

Closed

Merge branch 'main' into pythongh-105623

b1d5ba1

arhadthedev added the performance Performance or resource usage label Jun 17, 2023

arhadthedev reviewed Jun 17, 2023

View reviewed changes

Misc/NEWS.d/next/Library/2023-06-17-09-07-06.gh-issue-105623.5G06od.rst Outdated Show resolved Hide resolved

Update Misc/NEWS.d/next/Library/2023-06-17-09-07-06.gh-issue-105623.5…

84ad7d8

…G06od.rst Co-authored-by: Oleg Iarygin <oleg@arhadthedev.net>

vsajip added the 🔨 test-with-buildbots Test PR w/ buildbots; report in status section label Jun 19, 2023

bedevere-bot removed the 🔨 test-with-buildbots Test PR w/ buildbots; report in status section label Jun 19, 2023

Merge branch 'main' into pythongh-105623

a677f11

bdraco reviewed Jul 13, 2023

View reviewed changes

Merge branch 'main' into pythongh-105623

e3ee1d7

serhiy-storchaka approved these changes Mar 3, 2024

View reviewed changes

bedevere-app bot added awaiting merge and removed awaiting review labels Mar 3, 2024

Merge branch 'main' into pythongh-105623

3ff1523

Merge branch 'main' into pythongh-105623

7b5189b

serhiy-storchaka enabled auto-merge (squash) June 27, 2024 16:36

serhiy-storchaka merged commit e9b4ec6 into python:main Jun 27, 2024
33 checks passed

bedevere-app bot removed the awaiting merge label Jun 27, 2024

serhiy-storchaka added needs backport to 3.12 bug and security fixes needs backport to 3.13 bugs and security fixes labels Jun 28, 2024

bedevere-app bot removed the needs backport to 3.12 bug and security fixes label Jun 28, 2024

bedevere-app bot removed the needs backport to 3.13 bugs and security fixes label Jun 28, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

gh-105623 Fix performance degradation in logging RotatingFileHandler #105887

gh-105623 Fix performance degradation in logging RotatingFileHandler #105887

zhatt commented Jun 17, 2023 •

edited by bedevere-bot

Loading

cpython-cla-bot bot commented Jun 17, 2023 •

edited

Loading

bedevere-bot commented Jun 19, 2023

arhadthedev commented Jun 19, 2023

bdraco Jul 13, 2023

zhatt Jul 13, 2023

bdraco Jul 13, 2023 •

edited

Loading

vsajip Jul 13, 2023

serhiy-storchaka left a comment

fantabolous commented Jun 27, 2024 •

edited

Loading

miss-islington-app bot commented Jun 28, 2024

miss-islington-app bot commented Jun 28, 2024

bedevere-app bot commented Jun 28, 2024

bedevere-app bot commented Jun 28, 2024

serhiy-storchaka commented Jun 28, 2024

gh-105623 Fix performance degradation in logging RotatingFileHandler #105887

gh-105623 Fix performance degradation in logging RotatingFileHandler #105887

Conversation

zhatt commented Jun 17, 2023 • edited by bedevere-bot Loading

cpython-cla-bot bot commented Jun 17, 2023 • edited Loading

bedevere-bot commented Jun 19, 2023

arhadthedev commented Jun 19, 2023

bdraco Jul 13, 2023

Choose a reason for hiding this comment

zhatt Jul 13, 2023

Choose a reason for hiding this comment

bdraco Jul 13, 2023 • edited Loading

Choose a reason for hiding this comment

vsajip Jul 13, 2023

Choose a reason for hiding this comment

serhiy-storchaka left a comment

Choose a reason for hiding this comment

fantabolous commented Jun 27, 2024 • edited Loading

miss-islington-app bot commented Jun 28, 2024

miss-islington-app bot commented Jun 28, 2024

bedevere-app bot commented Jun 28, 2024

bedevere-app bot commented Jun 28, 2024

serhiy-storchaka commented Jun 28, 2024

zhatt commented Jun 17, 2023 •

edited by bedevere-bot

Loading

cpython-cla-bot bot commented Jun 17, 2023 •

edited

Loading

bdraco Jul 13, 2023 •

edited

Loading

fantabolous commented Jun 27, 2024 •

edited

Loading