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.

Fixes gh-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:

import time from unittest.mock import patch for t in (123, 456, 789): with patch('time.time_ns') as patched_ns: patched_ns.return_value = t value = 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:

import time from unittest.mock import patch for t in (123, 456, 789): with patch('time.time_ns') as patched_ns: patched_ns.return_value = t value = 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

+            with patch("time.time_ns") as patched_ns:
+                orig_modules = import_helper._save_and_remove_modules(['logging'])
+                try:
+                    # mock for module import
+                    patched_ns.return_value = ns
+                    import logging


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

new_ns = ns + offset_ns patched_ns.return_value = new_ns record = 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

+            with patch("time.time_ns") as patched_ns:
+                orig_modules = import_helper._save_and_remove_modules(['logging'])
+                try:
+                    # mock for module import
+                    patched_ns.return_value = ns
+                    import logging


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:

    def test_relativeCreated_has_higher_precision(self):
        # See issue gh-102402
        ns = 1_677_903_920_000_998_503  # approx. 2023-03-04 04:25:20 UTC
        offsets_ns = (200, 500, 12_354, 99_999, 1_677_903_456_999_123_456)

        with (patch("time.time_ns") as time_ns_mock,
              support.swap_attr(logging, '_startTime', ns)):
            for offset_ns in offsets_ns:
                # mock for log record creation
                new_ns = ns + offset_ns
                time_ns_mock.return_value = new_ns

                record = logging.makeLogRecord({'msg': 'test'})
                self.assertAlmostEqual(record.created, new_ns / 1e9, places=6)

                # After PR gh-102412, precision (places) increases from 3 to 7
                self.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

Fixes gh-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 Python modules in the Lib dir 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__.py Show resolved Hide 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 to gh-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-app bot 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:main Apr 16, 2024

bedevere-app bot 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

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

Uh oh!

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!

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