8000 gh-102402: Fix floating point math issue by using `time.time_ns()` in… · python/cpython@1316692 · GitHub
[go: up one dir, main page]
Skip to content

Commit 1316692

Browse files
dougthor42dougthor42
authored
gh-102402: Fix floating point math issue by using time.time_ns() in logging.LogRecord (GH-102412)
1 parent 1a1e013 commit 1316692

File tree

4 files changed

+53
-7
lines changed

4 files changed

+53
-7
lines changed

‎Doc/library/logging.rst

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1003,7 +1003,7 @@ the options available to you.
10031003
| | | portion of the time). |
10041004
+----------------+-------------------------+-----------------------------------------------+
10051005
| created | ``%(created)f`` | Time when the :class:`LogRecord` was created |
1006-
| | | (as returned by :func:`time.time`). |
1006+
| | | (as returned by :func:`time.time_ns` / 1e9). |
10071007
+----------------+-------------------------+-----------------------------------------------+
10081008
| exc_info | You shouldn't need to | Exception tuple (à la ``sys.exc_info``) or, |
10091009
| | format this yourself. | if no exception has occurred, ``None``. |

‎Lib/logging/__init__.py

Lines changed: 11 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -56,7 +56,7 @@
5656
#
5757
#_startTime is used as the base when calculating the relative time of events
5858
#
59-
_startTime = time.time()
59+
_startTime = time.time_ns()
6060

6161
#
6262
#raiseExceptions is used to see if exceptions during handling should be
@@ -300,7 +300,7 @@ def __init__(self, name, level, pathname, lineno,
300300
"""
301301
Initialize a logging record with interesting information.
302302
"""
303-
ct = time.time()
303+
ct = time.time_ns()
304304
self.name = name
305305
self.msg = msg
306306
#
@@ -339,9 +339,14 @@ def __init__(self, name, level, pathname, lineno,
339339
self.stack_info = sinfo
340340
self.lineno = lineno
341341
self.funcName = func
342-
self.created = ct
343-
self.msecs = int((ct - int(ct)) * 1000) + 0.0 # see gh-89047
344-
self.relativeCreated = (self.created - _startTime) * 1000
342+
self.created = ct / 1e9 # ns to float seconds
343+
344+
# Get the number of whole milliseconds (0-999) in the fractional part of seconds.
345+
# Eg: 1_677_903_920_999_998_503 ns --> 999_998_503 ns--> 999 ms
346+
# Convert to float by adding 0.0 for historical reasons. See gh-89047
347+
self.msecs = (ct % 1_000_000_000) // 1_000_000 + 0.0
348+
349+
self.relativeCreated = (ct - _startTime) / 1e6
345350
if logThreads:
346351
self.thread = threading.get_ident()
347352
self.threadName = threading.current_thread().name
@@ -572,7 +577,7 @@ class Formatter(object):
572577
%(lineno)d Source line number where the logging call was issued
573578
(if available)
574579
%(funcName)s Function name
575-
%(created)f Time when the LogRecord was created (time.time()
580+
%(created)f Time when the LogRecord was created (time.time_ns() / 1e9
576581
return value)
577582
%(asctime)s Textual time when the LogRecord was created
578583
%(msecs)d Millisecond portion of the creation time

‎Lib/test/test_logging.py

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -60,6 +60,7 @@
6060
import weakref
6161

6262
from http.server import HTTPServer, BaseHTTPRequestHandler
63+
from unittest.mock import patch
6364
from urllib.parse import urlparse, parse_qs
6465
from socketserver import (ThreadingUDPServer, DatagramRequestHandler,
6566
ThreadingTCPServer, StreamRequestHandler)
@@ -4552,6 +4553,44 @@ def test_issue_89047(self):
45524553
s = f.format(r)
45534554
self.assertNotIn('.1000', s)
45544555

4556+
def test_msecs_has_no_floating_point_precision_loss(self):
4557+
# See issue gh-102402
4558+
tests = (
4559+
# time_ns is approx. 2023-03-04 04:25:20 UTC
4560+
# (time_ns, expected_msecs_value)
4561+
(1_677_902_297_100_000_000, 100.0), # exactly 100ms
4562+
(1_677_903_920_999_998_503, 999.0), # check truncating doesn't round
4563+
(1_677_903_920_000_998_503, 0.0), # check truncating doesn't round
4564+
)
4565+
for ns, want in tests:
4566+
with patch('time.time_ns') as patched_ns:
4567+
patched_ns.return_value = ns
4568+
record = logging.makeLogRecord({'msg': 'test'})
4569+
self.assertEqual(record.msecs, want)
4570+
self.assertEqual(record.created, ns / 1e9)
4571+
4572+
def test_relativeCreated_has_higher_precision(self):
4573+
# See issue gh-102402
4574+
ns = 1_677_903_920_000_998_503 # approx. 2023-03-04 04:25:20 UTC
4575+
offsets_ns = (200, 500, 12_354, 99_999, 1_677_903_456_999_123_456)
4576+
orig_modules = import_helper._save_and_remove_modules(['logging'])
4577+
try:
4578+
with patch("time.time_ns") as patched_ns:
4579+
# mock for module import
4580+
patched_ns.return_value = ns
4581+
import logging
4582+
for offset_ns in offsets_ns:
4583+
new_ns = ns + offset_ns
4584+
# mock for log record creation
4585+
patched_ns.return_value = new_ns
4586+
record = logging.makeLogRecord({'msg': 'test'})
4587+
self.assertAlmostEqual(record.created, new_ns / 1e9, places=6)
4588+
# After PR gh-102412, precision (places) increases from 3 to 7
4589+
self.assertAlmostEqual(record.relativeCreated, offset_ns / 1e6, places=7)
4590+
finally:
4591+
import_helper._save_and_remove_modules(['logging'])
4592+
sys.modules.update(orig_modules)
4593+
45554594

45564595
class TestBufferingFormatter(logging.BufferingFormatter):
45574596
def formatHeader(self, records):

‎Misc/NEWS.d/next/Library/2023-03-03-21-13-08.gh-issue-102402.fpkRO1.rst

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,2 @@
1+
Adjust ``logging.LogRecord`` to use ``time.time_ns()`` and fix minor bug
2+
related to floating point math.

0 commit comments

Comments
 (0)
0