Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

gh-102402: Fix floating point math issue by usingtime.time_ns() inlogging.LogRecord#102412

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to ourterms of service andprivacy statement. We’ll occasionally send you account related emails.

Already on GitHub?Sign in to your account

Merged
vsajip merged 24 commits intopython:mainfromdougthor42:fix-gh-102402-logging-msecs
Apr 16, 2024
Merged

gh-102402: Fix floating point math issue by usingtime.time_ns() inlogging.LogRecord#102412

vsajip merged 24 commits intopython:mainfromdougthor42:fix-gh-102402-logging-msecs
Apr 16, 2024

Conversation

@dougthor42
Copy link
Contributor

@dougthor42dougthor42 commentedMar 4, 2023•
edited
Loading

gh-102402: Fix floating point math issue by usingtime.time_ns() inlogging.LogRecord.

  • Adjustlogging.LogRecord to usetime.time_ns() instead oftime.time().
  • Change method of calculatingLogRecord.msecs to be robust against floating point / binary representation arithmetic errors
  • Added tests for the changes.

Notes / Open Questions:

  1. LogRecord.msecs is a float so I kept it that way. Why is it a float even though it always has.0?
  2. In order to minimize impact, I keptLogRecord.created as a float in seconds.
  3. I didn't see any type annotations inlogging.__init__ so I didn't add any for the new code. Would you like me to add some annotations?
  4. I opted to use string manipulation to grab themsecs. I have an integer math-based approach, but it's, IMO, more verbose and harder to read/understand. LMK if you want me to switch back to that (there are still some minor fixes to apply to it).
    • I was able to come up with a math approach that is easy enough to understand.
  5. I wasn't sure of the best place to put the tests, so I just built off the othermsecs-related bug.

Fixes#102402.

@ghost
Copy link

ghost commentedMar 4, 2023•
edited by ghost
Loading

All commit authors signed the Contributor License Agreement.
CLA signed

Comment on lines 4328 to 4329
finally:
time.time_ns=og_time_ns
Copy link
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

Question: Is there a more preferred way to accomplish this other than monkeypatchingtime.time_ns?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

You can useunittest.mock.patch as in this example:

importtimefromunittest.mockimportpatchfortin (123,456,789):withpatch('time.time_ns')aspatched_ns:patched_ns.return_value=tvalue=time.time_ns()print(f'patched:{value}')print(f'OG:{time.time_ns()}')

which should, when run, print something like this:

patched: 123OG: 1681278183002693921patched: 456OG: 1681278183003199141patched: 789OG: 1681278183003610801

Copy link
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

Ah, my assumption was that we probably didn't want to add imports (I don't know why I assumed that...).

Updated to patch withmock instead of manual patching.

@arhadthedevarhadthedev added the stdlibStandard Library Python modules in the Lib/ directory labelMar 4, 2023
@dougthor42
Copy link
ContributorAuthor

I was able to come up with a math approach that is pretty easy to understand. It's also faster.

String manipulation:

$ python -m timeit -s "import time; ct=time.time_ns()" "float(str(ct)[-9:][:3])"2000000 loops, best of 5: 162 nsec per loop

Math:

$ python -m timeit -s "import time; ct=time.time_ns()" "ct_in_msecs = ct // 1_000_000; ct_in_secs = (ct_in_msecs // 1_000) * 1_000; msecs = (ct_in_msecs - ct_in_secs) + 0.0"5000000 loops, best of 5: 74.3 nsec per loop

This version is a little faster:

$ python -m timeit -s "import time; ct=time.time_ns()" "msecs = (ct - ((ct // 1_000_000_000) * 1_000_000_000)) // 1_000_000 + 0.0"5000000 loops, best of 5: 59.1 nsec per loop

@arhadthedev
Copy link
Member

@vsajip (as a logging moduleexpert)

Copy link
Member

@vsajipvsajip left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

Thanks for the PR - minor changes requested.

Comment on lines 4328 to 4329
finally:
time.time_ns=og_time_ns
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

You can useunittest.mock.patch as in this example:

importtimefromunittest.mockimportpatchfortin (123,456,789):withpatch('time.time_ns')aspatched_ns:patched_ns.return_value=tvalue=time.time_ns()print(f'patched:{value}')print(f'OG:{time.time_ns()}')

which should, when run, print something like this:

patched: 123OG: 1681278183002693921patched: 456OG: 1681278183003199141patched: 789OG: 1681278183003610801

@bedevere-bot
Copy link

A Python core developer has requested some changes be made to your pull request before we can consider merging it. If you could please address their requests along with any other requests in other reviews from core developers that would be appreciated.

Once you have made the requested changes, please leave a comment on this pull request containing the phraseI have made the requested changes; please review again. I will then notify any core developers who have left a review that you're ready for them to take another look at this pull request.

Copy link
ContributorAuthor

@dougthor42dougthor42 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

I have made the requested changes; please review again

Comment on lines 4328 to 4329
finally:
time.time_ns=og_time_ns
Copy link
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

Ah, my assumption was that we probably didn't want to add imports (I don't know why I assumed that...).

Updated to patch withmock instead of manual patching.

Copy link
ContributorAuthor

@dougthor42dougthor42 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

Thanks@serhiy-storchaka! I've addressed most items but would like more information on the request for additional testing.

Copy link
Member

@serhiy-storchakaserhiy-storchaka left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

LGTM. I left only one minor suggestion, which can be ignored if you have other reasons.

Thank you for your contribution,@dougthor42. For a first time contributor, this PR has surprisingly high quality, you did not even make common errors. And I did not expect such good responsibility after months of inactivity. I will be glad to see your other PRs.

Comment on lines 4336 to 4341
withpatch("time.time_ns")aspatched_ns:
orig_modules=import_helper._save_and_remove_modules(['logging'])
try:
# mock for module import
patched_ns.return_value=ns
importlogging

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

I think that it can be out of the loop. You only need the following code in the loop:

new_ns=ns+offset_nspatched_ns.return_value=new_nsrecord=logging.makeLogRecord({'msg':'test'})self.assertAlmostEqual(record.created,new_ns/1e9,places=6)self.assertAlmostEqual(record.relativeCreated,offset_ns/1e6,places=7)

It is just an optimization.

Copy link
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

Agreed. It may be "just an optimization" but I wouldn't consider it apremature optimization. Updated.

Copy link
ContributorAuthor

@dougthor42dougthor42 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

For a first time contributor, this PR has surprisingly high quality, you did not even make common errors. And I did not expect such good responsibility after months of inactivity. I will be glad to see your other PRs.

Thanks! I do hope to find more PRs that I can help with (and have thetime to help with...)

Comment on lines 4336 to 4341
withpatch("time.time_ns")aspatched_ns:
orig_modules=import_helper._save_and_remove_modules(['logging'])
try:
# mock for module import
patched_ns.return_value=ns
importlogging
Copy link
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

Agreed. It may be "just an optimization" but I wouldn't consider it apremature optimization. Updated.

@vsajip
Copy link
Member

Closing and reopening, as there seems to have been a spurious error.

@vsajipvsajip closed thisApr 15, 2024
@vsajipvsajip reopened thisApr 15, 2024
@vsajipvsajip merged commit1316692 intopython:mainApr 16, 2024
@vsajip
Copy link
Member

Thank you@dougthor42 for your patience - sorry it dropped off my radar for so long.

dougthor42 reacted with heart emoji

diegorusso pushed a commit to diegorusso/cpython that referenced this pull requestApr 17, 2024
@vstinner
Copy link
Member

This change introduced reference leaks:

$ ./python -m test -R 3:3 test_logging -m test_relativeCreated_has_higher_precision(...)test_logging leaked [2535, 2531, 2535] references, sum=7601test_logging leaked [1600, 1598, 1600] memory blocks, sum=4798
dougthor42 reacted with eyes emoji

@vstinner
Copy link
Member

I suggest to not reimport the logging module in the test:

deftest_relativeCreated_has_higher_precision(self):# See issue gh-102402ns=1_677_903_920_000_998_503# approx. 2023-03-04 04:25:20 UTCoffsets_ns= (200,500,12_354,99_999,1_677_903_456_999_123_456)with (patch("time.time_ns")astime_ns_mock,support.swap_attr(logging,'_startTime',ns)):foroffset_nsinoffsets_ns:# mock for log record creationnew_ns=ns+offset_nstime_ns_mock.return_value=new_nsrecord=logging.makeLogRecord({'msg':'test'})self.assertAlmostEqual(record.created,new_ns/1e9,places=6)# After PR gh-102412, precision (places) increases from 3 to 7self.assertAlmostEqual(record.relativeCreated,offset_ns/1e6,places=7)

@vstinner
Copy link
Member

vstinner commentedApr 17, 2024•
edited
Loading

Change method of calculating LogRecord.msecs to be robust against floating point / b

I'm happy that myPEP 564 – Add new time functions with nanosecond resolution is used to fix very concrete time rounding issues ;-)

dougthor42 reacted with heart emoji

@serhiy-storchaka
Copy link
Member

Could you please open a new issue for the leak? I tried to find the cause, and still have not found it. It is a puzzle.

@vstinner
Copy link
Member

Could you please open a new issue for the leak? I tried to find the cause, and still have not found it. It is a puzzle.

I proposed a fix:#117985

dougthor42 reacted with heart emoji

@dougthor42
Copy link
ContributorAuthor

Oh no! Sorry that my change caused more work for people 😞.

TIL about-R / --huntrleaks - I'll keep it mind for next time!

@vstinner
Copy link
Member

Buildbots were broken for 1 day. I merged my fix since no better fix was proposed:8f25cc9

Sign up for freeto join this conversation on GitHub. Already have an account?Sign in to comment

Reviewers

@vsajipvsajipvsajip requested changes

@serhiy-storchakaserhiy-storchakaserhiy-storchaka approved these changes

Assignees

No one assigned

Labels

stdlibStandard Library Python modules in the Lib/ directory

Projects

Status: Done

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

Logging's msecs doesn't handle "100ms" well.

6 participants

@dougthor42@arhadthedev@bedevere-bot@vsajip@vstinner@serhiy-storchaka
[8]ページ先頭
©2009-2025 Movatter.jp