From 691f71deb79d8d327615576e64a464913e70edc3 Mon Sep 17 00:00:00 2001 From: Steve Foster Date: Fri, 16 May 2025 15:14:31 +1200 Subject: [PATCH 1/2] feature: Add request duration in nanoseconds So that if you have other systems that record durations to this resolution then they can be in alignment without needing calculation. --- gunicorn/config.py | 1 + gunicorn/glogging.py | 9 +++++---- gunicorn/instrument/statsd.py | 2 +- gunicorn/workers/base.py | 5 ++--- gunicorn/workers/base_async.py | 6 +++--- gunicorn/workers/gthread.py | 5 ++--- gunicorn/workers/sync.py | 6 +++--- tests/test_logger.py | 12 +++++++----- tests/test_statsd.py | 5 ++--- 9 files changed, 26 insertions(+), 25 deletions(-) diff --git a/gunicorn/config.py b/gunicorn/config.py index c6ab3777f8..f788be27a2 100644 --- a/gunicorn/config.py +++ b/gunicorn/config.py @@ -1434,6 +1434,7 @@ class AccessLogFormat(Setting): T request time in seconds M request time in milliseconds D request time in microseconds + N request time in nanoseconds L request time in decimal seconds p process ID {header}i request header diff --git a/gunicorn/glogging.py b/gunicorn/glogging.py index 075016e2ed..dad17cde8e 100644 --- a/gunicorn/glogging.py +++ b/gunicorn/glogging.py @@ -310,10 +310,11 @@ def atoms(self, resp, req, environ, request_time): 'B': getattr(resp, 'sent', None), 'f': environ.get('HTTP_REFERER', '-'), 'a': environ.get('HTTP_USER_AGENT', '-'), - 'T': request_time.seconds, - 'D': (request_time.seconds * 1000000) + request_time.microseconds, - 'M': (request_time.seconds * 1000) + int(request_time.microseconds / 1000), - 'L': "%d.%06d" % (request_time.seconds, request_time.microseconds), + 'T': request_time // 1_000_000_000, + 'M': request_time // 1_000_000, + 'D': request_time // 1_000, + 'N': request_time, + 'L': "%.6f" % (request_time / 1e+9), 'p': "<%s>" % os.getpid() } diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py index 708a1d6bf9..40fd6d5073 100644 --- a/gunicorn/instrument/statsd.py +++ b/gunicorn/instrument/statsd.py @@ -98,7 +98,7 @@ def access(self, resp, req, environ, request_time): request_time is a datetime.timedelta """ Logger.access(self, resp, req, environ, request_time) - duration_in_ms = request_time.seconds * 1000 + float(request_time.microseconds) / 10 ** 3 + duration_in_ms = request_time // 1_000_000 status = resp.status if isinstance(status, bytes): status = status.decode('utf-8') diff --git a/gunicorn/workers/base.py b/gunicorn/workers/base.py index 5abd4d6bae..972ac72f6d 100644 --- a/gunicorn/workers/base.py +++ b/gunicorn/workers/base.py @@ -8,7 +8,6 @@ import sys import time import traceback -from datetime import datetime from random import randint from ssl import SSLError @@ -198,7 +197,7 @@ def handle_abort(self, sig, frame): sys.exit(1) def handle_error(self, req, client, addr, exc): - request_start = datetime.now() + request_start = time.monotonic_ns() addr = addr or ('', -1) # unix socket case if isinstance(exc, ( InvalidRequestLine, InvalidRequestMethod, @@ -268,7 +267,7 @@ def handle_error(self, req, client, addr, exc): mesg = "" if req is not None: - request_time = datetime.now() - request_start + request_time = time.monotonic_ns() - request_start environ = default_environ(req, client, self.cfg) environ['REMOTE_ADDR'] = addr[0] environ['REMOTE_PORT'] = str(addr[1]) diff --git a/gunicorn/workers/base_async.py b/gunicorn/workers/base_async.py index db35b3a540..be459d3d8a 100644 --- a/gunicorn/workers/base_async.py +++ b/gunicorn/workers/base_async.py @@ -2,11 +2,11 @@ # This file is part of gunicorn released under the MIT license. # See the NOTICE for more information. -from datetime import datetime import errno import socket import ssl import sys +import time from gunicorn import http from gunicorn.http import wsgi @@ -197,7 +197,7 @@ def handle_http2_request(self, listener_name, req, sock, addr, h2_conn): self.log.exception("Exception in post_request hook") def handle_request(self, listener_name, req, sock, addr): - request_start = datetime.now() + request_start = time.monotonic_ns() environ = {} resp = None try: @@ -225,7 +225,7 @@ def handle_request(self, listener_name, req, sock, addr): resp.write(item) resp.close() finally: - request_time = datetime.now() - request_start + request_time = time.monotonic_ns() - request_start self.log.access(resp, req, environ, request_time) if hasattr(respiter, "close"): respiter.close() diff --git a/gunicorn/workers/gthread.py b/gunicorn/workers/gthread.py index bf7711fc45..13a48c7f17 100644 --- a/gunicorn/workers/gthread.py +++ b/gunicorn/workers/gthread.py @@ -19,7 +19,6 @@ import sys import time from collections import deque -from datetime import datetime from functools import partial from . import base @@ -659,7 +658,7 @@ def handle_request(self, req, conn): resp = None try: self.cfg.pre_request(self, req) - request_start = datetime.now() + request_start = time.monotonic_ns() resp, environ = wsgi.create(req, conn.sock, conn.client, conn.server, self.cfg) environ["wsgi.multithread"] = True @@ -685,7 +684,7 @@ def handle_request(self, req, conn): resp.close() finally: - request_time = datetime.now() - request_start + request_time = time.monotonic_ns() - request_start self.log.access(resp, req, environ, request_time) if hasattr(respiter, "close"): respiter.close() diff --git a/gunicorn/workers/sync.py b/gunicorn/workers/sync.py index c11597f22e..2584d440e0 100644 --- a/gunicorn/workers/sync.py +++ b/gunicorn/workers/sync.py @@ -3,12 +3,12 @@ # See the NOTICE for more information. # -from datetime import datetime import errno import os import select import ssl import sys +import time from gunicorn import http from gunicorn.http import wsgi @@ -170,7 +170,7 @@ def handle_request(self, listener, req, client, addr): resp = None try: self.cfg.pre_request(self, req) - request_start = datetime.now() + request_start = time.monotonic_ns() resp, environ = wsgi.create(req, client, addr, listener.getsockname(), self.cfg) # Force the connection closed until someone shows @@ -190,7 +190,7 @@ def handle_request(self, listener, req, client, addr): resp.write(item) resp.close() finally: - request_time = datetime.now() - request_start + request_time = time.monotonic_ns() - request_start self.log.access(resp, req, environ, request_time) if hasattr(respiter, "close"): respiter.close() diff --git a/tests/test_logger.py b/tests/test_logger.py index a4b69d5534..b71bf5e685 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -11,6 +11,8 @@ from gunicorn.glogging import Logger +ONE_SECOND_IN_NS = 1_000_000_000 + def test_atoms_defaults(): response = SimpleNamespace( status='200', response_length=1024, @@ -23,7 +25,7 @@ def test_atoms_defaults(): 'SERVER_PROTOCOL': 'HTTP/1.1', } logger = Logger(Config()) - atoms = logger.atoms(response, request, environ, datetime.timedelta(seconds=1)) + atoms = logger.atoms(response, request, environ, ONE_SECOND_IN_NS) assert isinstance(atoms, dict) assert atoms['r'] == 'GET /my/path?foo=bar HTTP/1.1' assert atoms['m'] == 'GET' @@ -34,7 +36,7 @@ def test_atoms_defaults(): assert atoms['B'] == 1024 assert atoms['{accept}i'] == 'application/json' assert atoms['{content-type}o'] == 'application/json' - + assert atoms['N'] == ONE_SECOND_IN_NS def test_atoms_zero_bytes(): response = SimpleNamespace( @@ -48,7 +50,7 @@ def test_atoms_zero_bytes(): 'SERVER_PROTOCOL': 'HTTP/1.1', } logger = Logger(Config()) - atoms = logger.atoms(response, request, environ, datetime.timedelta(seconds=1)) + atoms = logger.atoms(response, request, environ, ONE_SECOND_IN_NS) assert atoms['b'] == '0' assert atoms['B'] == 0 @@ -72,7 +74,7 @@ def test_get_username_from_basic_auth_header(auth): 'HTTP_AUTHORIZATION': auth, } logger = Logger(Config()) - atoms = logger.atoms(response, request, environ, datetime.timedelta(seconds=1)) + atoms = logger.atoms(response, request, environ, ONE_SECOND_IN_NS) assert atoms['u'] == 'brk0v' @@ -91,5 +93,5 @@ def test_get_username_handles_malformed_basic_auth_header(): } logger = Logger(Config()) - atoms = logger.atoms(response, request, environ, datetime.timedelta(seconds=1)) + atoms = logger.atoms(response, request, environ, ONE_SECOND_IN_NS) assert atoms['u'] == '-' diff --git a/tests/test_statsd.py b/tests/test_statsd.py index b659e78b23..442de53d38 100644 --- a/tests/test_statsd.py +++ b/tests/test_statsd.py @@ -8,7 +8,6 @@ import shutil import socket import tempfile -from datetime import timedelta from types import SimpleNamespace from gunicorn.config import Config @@ -115,8 +114,8 @@ def test_instrument(): assert logger.sock.msgs[0] == b"gunicorn.log.critical:1|c|@1.0" logger.sock.reset() - logger.access(SimpleNamespace(status="200 OK"), None, {}, timedelta(seconds=7)) - assert logger.sock.msgs[0] == b"gunicorn.request.duration:7000.0|ms" + logger.access(SimpleNamespace(status="200 OK"), None, {}, 7000000000) + assert logger.sock.msgs[0] == b"gunicorn.request.duration:7000|ms" assert logger.sock.msgs[1] == b"gunicorn.requests:1|c|@1.0" assert logger.sock.msgs[2] == b"gunicorn.request.status.200:1|c|@1.0" From 1ea2f3bd95b3ee78f46ec9c954b31577497bf73d Mon Sep 17 00:00:00 2001 From: Steve Foster Date: Wed, 24 Jun 2026 08:46:18 +1200 Subject: [PATCH 2/2] chore: lint and replace other uses of datetime.now() --- docs/content/reference/settings.md | 1 + gunicorn/workers/base_async.py | 4 ++-- gunicorn/workers/gthread.py | 4 ++-- tests/test_logger.py | 3 ++- 4 files changed, 7 insertions(+), 5 deletions(-) diff --git a/docs/content/reference/settings.md b/docs/content/reference/settings.md index c7d5426577..6d625e8906 100644 --- a/docs/content/reference/settings.md +++ b/docs/content/reference/settings.md @@ -516,6 +516,7 @@ a user agent T request time in seconds M request time in milliseconds D request time in microseconds +N request time in nanoseconds L request time in decimal seconds p process ID {header}i request header diff --git a/gunicorn/workers/base_async.py b/gunicorn/workers/base_async.py index be459d3d8a..6d5a92d1e2 100644 --- a/gunicorn/workers/base_async.py +++ b/gunicorn/workers/base_async.py @@ -144,7 +144,7 @@ def handle_http2(self, listener, client, addr): def handle_http2_request(self, listener_name, req, sock, addr, h2_conn): """Handle a single HTTP/2 request.""" stream_id = req.stream.stream_id - request_start = datetime.now() + request_start = time.monotonic_ns() environ = {} resp = None @@ -184,7 +184,7 @@ def handle_http2_request(self, listener_name, req, sock, addr, h2_conn): response_body ) - request_time = datetime.now() - request_start + request_time = time.monotonic_ns() - request_start self.log.access(resp, req, environ, request_time) except Exception: diff --git a/gunicorn/workers/gthread.py b/gunicorn/workers/gthread.py index 13a48c7f17..7fce516d6f 100644 --- a/gunicorn/workers/gthread.py +++ b/gunicorn/workers/gthread.py @@ -569,7 +569,7 @@ def handle_http2_request(self, req, conn, h2_conn): try: self.cfg.pre_request(self, req) - request_start = datetime.now() + request_start = time.monotonic_ns() # Create WSGI environ resp, environ = wsgi.create(req, conn.sock, conn.client, @@ -644,7 +644,7 @@ def send_trailers_h2(trailers): response_body ) - request_time = datetime.now() - request_start + request_time = time.monotonic_ns() - request_start self.log.access(resp, req, environ, request_time) finally: diff --git a/tests/test_logger.py b/tests/test_logger.py index b71bf5e685..ddbd3d5077 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -2,7 +2,6 @@ # This file is part of gunicorn released under the MIT license. # See the NOTICE for more information. -import datetime from types import SimpleNamespace import pytest @@ -13,6 +12,7 @@ ONE_SECOND_IN_NS = 1_000_000_000 + def test_atoms_defaults(): response = SimpleNamespace( status='200', response_length=1024, @@ -38,6 +38,7 @@ def test_atoms_defaults(): assert atoms['{content-type}o'] == 'application/json' assert atoms['N'] == ONE_SECOND_IN_NS + def test_atoms_zero_bytes(): response = SimpleNamespace( status='200', response_length=0,