mirror of https://github.com/python/cpython
gh-102402: Fix floating point math issue by using `time.time_ns()` in `logging.LogRecord` (GH-102412)
This commit is contained in:
parent
1a1e013a4a
commit
1316692e8c
|
@ -1003,7 +1003,7 @@ the options available to you.
|
|||
| | | portion of the time). |
|
||||
+----------------+-------------------------+-----------------------------------------------+
|
||||
| created | ``%(created)f`` | Time when the :class:`LogRecord` was created |
|
||||
| | | (as returned by :func:`time.time`). |
|
||||
| | | (as returned by :func:`time.time_ns` / 1e9). |
|
||||
+----------------+-------------------------+-----------------------------------------------+
|
||||
| exc_info | You shouldn't need to | Exception tuple (à la ``sys.exc_info``) or, |
|
||||
| | format this yourself. | if no exception has occurred, ``None``. |
|
||||
|
|
|
@ -56,7 +56,7 @@ __date__ = "07 February 2010"
|
|||
#
|
||||
#_startTime is used as the base when calculating the relative time of events
|
||||
#
|
||||
_startTime = time.time()
|
||||
_startTime = time.time_ns()
|
||||
|
||||
#
|
||||
#raiseExceptions is used to see if exceptions during handling should be
|
||||
|
@ -300,7 +300,7 @@ class LogRecord(object):
|
|||
"""
|
||||
Initialize a logging record with interesting information.
|
||||
"""
|
||||
ct = time.time()
|
||||
ct = time.time_ns()
|
||||
self.name = name
|
||||
self.msg = msg
|
||||
#
|
||||
|
@ -339,9 +339,14 @@ class LogRecord(object):
|
|||
self.stack_info = sinfo
|
||||
self.lineno = lineno
|
||||
self.funcName = func
|
||||
self.created = ct
|
||||
self.msecs = int((ct - int(ct)) * 1000) + 0.0 # see gh-89047
|
||||
self.relativeCreated = (self.created - _startTime) * 1000
|
||||
self.created = ct / 1e9 # ns to float seconds
|
||||
|
||||
# Get the number of whole milliseconds (0-999) in the fractional part of seconds.
|
||||
# Eg: 1_677_903_920_999_998_503 ns --> 999_998_503 ns--> 999 ms
|
||||
# Convert to float by adding 0.0 for historical reasons. See gh-89047
|
||||
self.msecs = (ct % 1_000_000_000) // 1_000_000 + 0.0
|
||||
|
||||
self.relativeCreated = (ct - _startTime) / 1e6
|
||||
if logThreads:
|
||||
self.thread = threading.get_ident()
|
||||
self.threadName = threading.current_thread().name
|
||||
|
@ -572,7 +577,7 @@ class Formatter(object):
|
|||
%(lineno)d Source line number where the logging call was issued
|
||||
(if available)
|
||||
%(funcName)s Function name
|
||||
%(created)f Time when the LogRecord was created (time.time()
|
||||
%(created)f Time when the LogRecord was created (time.time_ns() / 1e9
|
||||
return value)
|
||||
%(asctime)s Textual time when the LogRecord was created
|
||||
%(msecs)d Millisecond portion of the creation time
|
||||
|
|
|
@ -60,6 +60,7 @@ import warnings
|
|||
import weakref
|
||||
|
||||
from http.server import HTTPServer, BaseHTTPRequestHandler
|
||||
from unittest.mock import patch
|
||||
from urllib.parse import urlparse, parse_qs
|
||||
from socketserver import (ThreadingUDPServer, DatagramRequestHandler,
|
||||
ThreadingTCPServer, StreamRequestHandler)
|
||||
|
@ -4552,6 +4553,44 @@ class FormatterTest(unittest.TestCase, AssertErrorMessage):
|
|||
s = f.format(r)
|
||||
self.assertNotIn('.1000', s)
|
||||
|
||||
def test_msecs_has_no_floating_point_precision_loss(self):
|
||||
# See issue gh-102402
|
||||
tests = (
|
||||
# time_ns is approx. 2023-03-04 04:25:20 UTC
|
||||
# (time_ns, expected_msecs_value)
|
||||
(1_677_902_297_100_000_000, 100.0), # exactly 100ms
|
||||
(1_677_903_920_999_998_503, 999.0), # check truncating doesn't round
|
||||
(1_677_903_920_000_998_503, 0.0), # check truncating doesn't round
|
||||
)
|
||||
for ns, want in tests:
|
||||
with patch('time.time_ns') as patched_ns:
|
||||
patched_ns.return_value = ns
|
||||
record = logging.makeLogRecord({'msg': 'test'})
|
||||
self.assertEqual(record.msecs, want)
|
||||
self.assertEqual(record.created, ns / 1e9)
|
||||
|
||||
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)
|
||||
orig_modules = import_helper._save_and_remove_modules(['logging'])
|
||||
try:
|
||||
with patch("time.time_ns") as patched_ns:
|
||||
# mock for module import
|
||||
patched_ns.return_value = ns
|
||||
import logging
|
||||
for offset_ns in offsets_ns:
|
||||
new_ns = ns + offset_ns
|
||||
# mock for log record creation
|
||||
patched_ns.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)
|
||||
finally:
|
||||
import_helper._save_and_remove_modules(['logging'])
|
||||
sys.modules.update(orig_modules)
|
||||
|
||||
|
||||
class TestBufferingFormatter(logging.BufferingFormatter):
|
||||
def formatHeader(self, records):
|
||||
|
|
|
@ -0,0 +1,2 @@
|
|||
Adjust ``logging.LogRecord`` to use ``time.time_ns()`` and fix minor bug
|
||||
related to floating point math.
|
Loading…
Reference in New Issue