gh-102402: Fix floating point math issue by using `time.time_ns()` in `logging.LogRecord`#102412

dougthor42 · 2023-03-04T05:33:16Z

gh-102402: Fix floating point math issue by using time.time_ns() in logging.LogRecord.

Adjust logging.LogRecord to use time.time_ns() instead of time.time().
Change method of calculating LogRecord.msecs to be robust against floating point / binary representation arithmetic errors
Added tests for the changes.

Notes / Open Questions:

LogRecord.msecs is a float so I kept it that way. Why is it a float even though it always has .0?
In order to minimize impact, I kept LogRecord.created as a float in seconds.
I didn't see any type annotations in logging.__init__ so I didn't add any for the new code. Would you like me to add some annotations?
I opted to use string manipulation to grab the msecs. 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.
I wasn't sure of the best place to put the tests, so I just built off the other msecs-related bug.

Fixes#102402.

Fixesgh-102402

ghost · 2023-03-04T05:33:43Z

All commit authors signed the Contributor License Agreement.

Lib/test/test_logging.py

dougthor42 · 2023-03-04T05:41:34Z

Lib/test/test_logging.py

+finally:
+time.time_ns=og_time_ns


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

You can use unittest.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: 123 OG: 1681278183002693921 patched: 456 OG: 1681278183003199141 patched: 789 OG: 1681278183003610801

Ah, my assumption was that we probably didn't want to add imports (I don't know why I assumed that...).
Updated to patch with mock instead of manual patching.

dougthor42 · 2023-03-05T22:44:36Z

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

Lib/logging/__init__.py

arhadthedev · 2023-04-02T08:30:54Z

@vsajip (as a logging module expert)

vsajip

Thanks for the PR - minor changes requested.

Lib/logging/__init__.py

vsajip · 2023-04-12T05:43:59Z

Lib/test/test_logging.py

+finally:
+time.time_ns=og_time_ns


You can use unittest.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: 123 OG: 1681278183002693921 patched: 456 OG: 1681278183003199141 patched: 789 OG: 1681278183003610801

bedevere-bot · 2023-04-12T05:45:00Z

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 phrase I 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.

dougthor42

I have made the requested changes; please review again

Lib/logging/__init__.py

dougthor42 · 2023-04-15T03:08:01Z

Lib/test/test_logging.py

+finally:
+time.time_ns=og_time_ns


Ah, my assumption was that we probably didn't want to add imports (I don't know why I assumed that...).
Updated to patch with mock instead of manual patching.

Lib/logging/__init__.py

Lib/test/test_logging.py

dougthor42

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

Lib/test/test_logging.py

Lib/logging/__init__.py

Lib/test/test_logging.py

serhiy-storchaka

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.

serhiy-storchaka · 2024-03-04T08:21:49Z

Lib/test/test_logging.py

+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


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.

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

Lib/test/test_logging.py

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.

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

dougthor42 · 2024-03-04T17:24:28Z

Lib/test/test_logging.py

+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


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

vsajip · 2024-04-15T17:03:00Z

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

vsajip · 2024-04-16T09:46:37Z

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

…()` in `logging.LogRecord` (pythonGH-102412)

vstinner · 2024-04-17T12:43:58Z

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=7601 test_logging leaked [1600, 1598, 1600] memory blocks, sum=4798

vstinner · 2024-04-17T12:50:02Z

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 · 2024-04-17T12:54:39Z

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

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

serhiy-storchaka · 2024-04-17T13:08:50Z

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 · 2024-04-17T13:12:56Z

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 · 2024-04-17T15:21:47Z

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

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

vstinner · 2024-04-18T17:02:51Z

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

dougthor42 added 4 commits March 3, 2023 21:00

Add test for 102402 100msecs
2f046c2

Update logging.LogRecord to use time_ns.
2460f88
Fixesgh-102402

Simplify msecs calculation
059f856

Add blurb
997bd41

dougthor42 requested a review from vsajip as a code owner March 4, 2023 05:33

bedevere-bot mentioned this pull request Mar 4, 2023
Logging's msecs doesn't handle "100ms" well. #102402
Closed

bedevere-bot added the awaiting review label Mar 4, 2023

dougthor42 commented Mar 4, 2023
View reviewed changes

Fix comments, remove superfluous comment
2e7cde3

arhadthedev added the stdlib Standard Library Python modules in the Lib/ directory label Mar 4, 2023

Merge branch 'main' into fix-gh-102402-logging-msecs
5505cea

Switch to math algorithm rather than string manipulation.
411a421

dougthor42 commented Mar 5, 2023
View reviewed changes

Lib/logging/__init__.pyShow resolvedHide resolved

vsajip requested changes Apr 12, 2023
View reviewed changes

bedevere-bot added awaiting changes and removed awaiting review labels Apr 12, 2023

dougthor42 added 2 commits April 14, 2023 20:02

Correct and update comment
d3a1f78

Use unittest.mock.patch instead of manual monkeypatching
5fa370b

dougthor42 commented Apr 15, 2023
View reviewed changes

serhiy-storchaka reviewed Mar 2, 2024
View reviewed changes

dougthor42 added 5 commits March 2, 2024 14:42

formatting in test_logging.py
39cab9d

Update docs
920bf74

Keep ref togh-89047
8bdc406

Use modulo arithmetic, update comment
bf68b26

Add comment
e404ca0

dougthor42 commented Mar 2, 2024
View reviewed changes

dougthor42 added 4 commits March 3, 2024 14:23

remove issue num from test names; move to comment
ff8140c

Use importhelper instead of importlib.reload
fd45694

Also assert record.created
84b931b

Update test to check multiple offset values
5a604f9

serhiy-storchaka approved these changes Mar 4, 2024
View reviewed changes

bedevere-appbot added awaiting merge and removed awaiting changes labels Mar 4, 2024

dougthor42 added 2 commits March 4, 2024 09:15

Optimize loop vs import CM
dc90919

Move item to variable
502ff65

dougthor42 commented Mar 4, 2024
View reviewed changes

serhiy-storchaka approved these changes Mar 4, 2024
View reviewed changes

vsajip closed this Apr 15, 2024

vsajip reopened this Apr 15, 2024

Merge branch 'main' into fix-gh-102402-logging-msecs
65ea1b5

vsajip merged commit 1316692 into python:mainApr 16, 2024

bedevere-appbot removed the awaiting merge label Apr 16, 2024

diegorusso pushed a commit to diegorusso/cpython that referenced this pull request Apr 17, 2024
pythongh-102402: Fix floating point math issue by using `time.time_ns…
c7c3707
…()` in `logging.LogRecord` (pythonGH-102412)

corona10 mentioned this pull request Apr 18, 2024
gh-112069: Add _PySet_NextEntryRef to be thread-safe. #117990
Merged

dougthor42 deleted the fix-gh-102402-logging-msecs branch April 18, 2024 17:16

bmerry mentioned this pull request Jun 18, 2024
Python 3.13.0b2: rounding can cause incorrect log timestamps #120683
Closed

vsajip mentioned this pull request Jul 5, 2024
Add microseconds to logging.LogRecord #90450
Open

		finally:
		time.time_ns=og_time_ns

		finally:
		time.time_ns=og_time_ns

		finally:
		time.time_ns=og_time_ns

Uh oh!

gh-102402: Fix floating point math issue by using time.time_ns() in logging.LogRecord#102412

gh-102402: Fix floating point math issue by using time.time_ns() in logging.LogRecord#102412

Conversation

dougthor42 commented Mar 4, 2023• edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Notes / Open Questions:

Uh oh!

ghost commented Mar 4, 2023• edited by ghost Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dougthor42 commented Mar 5, 2023

String manipulation:

Math:

Uh oh!

Uh oh!

arhadthedev commented Apr 2, 2023

Uh oh!

vsajip left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

bedevere-bot commented Apr 12, 2023

Uh oh!

dougthor42 left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

dougthor42 left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

serhiy-storchaka left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

dougthor42 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

vsajip commented Apr 15, 2024

Uh oh!

vsajip commented Apr 16, 2024

Uh oh!

vstinner commented Apr 17, 2024

Uh oh!

vstinner commented Apr 17, 2024

Uh oh!

vstinner commented Apr 17, 2024• edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

gh-102402: Fix floating point math issue by using `time.time_ns()` in `logging.LogRecord`#102412

gh-102402: Fix floating point math issue by using `time.time_ns()` in `logging.LogRecord`#102412

dougthor42 commented Mar 4, 2023•
edited
Loading

ghost commented Mar 4, 2023•
edited by ghost
Loading

vstinner commented Apr 17, 2024•
edited
Loading