diff --git a/docs/source/settings.rst b/docs/source/settings.rst index e1e91fa76..6350c0e44 100644 --- a/docs/source/settings.rst +++ b/docs/source/settings.rst @@ -215,6 +215,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 @@ -1148,7 +1149,7 @@ change the worker process user. Switch worker process to run as this group. A valid group id (as an integer) or the name of a user that can be -retrieved with a call to ``pwd.getgrnam(value)`` or ``None`` to not +retrieved with a call to ``grp.getgrnam(value)`` or ``None`` to not change the worker processes group. .. _umask: diff --git a/gunicorn/config.py b/gunicorn/config.py index 07c5aab34..1c62e792d 100644 --- a/gunicorn/config.py +++ b/gunicorn/config.py @@ -1417,6 +1417,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 e34fcd5f7..ec11bebb2 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 7bc4e6ffd..dfccb200a 100644 --- a/gunicorn/instrument/statsd.py +++ b/gunicorn/instrument/statsd.py @@ -95,7 +95,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 93c465c98..d39c69c8b 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 @@ -204,7 +203,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 9466d6aaa..eab500cda 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 @@ -87,7 +87,7 @@ def handle(self, listener, client, addr): util.close(client) def handle_request(self, listener_name, req, sock, addr): - request_start = datetime.now() + request_start = time.monotonic_ns() environ = {} resp = None try: @@ -115,7 +115,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 7a23228cd..4f40f8966 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 threading import RLock @@ -314,7 +313,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 @@ -340,7 +339,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 4c029f912..945758219 100644 --- a/gunicorn/workers/sync.py +++ b/gunicorn/workers/sync.py @@ -3,13 +3,13 @@ # See the NOTICE for more information. # -from datetime import datetime import errno import os import select import socket import ssl import sys +import time from gunicorn import http from gunicorn.http import wsgi @@ -163,7 +163,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 @@ -183,7 +183,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 54801266c..817720bd1 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -7,6 +7,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, @@ -19,7 +21,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' @@ -30,7 +32,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( @@ -44,7 +46,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 @@ -68,7 +70,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' @@ -87,5 +89,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 88adb0040..de40a8a73 100644 --- a/tests/test_statsd.py +++ b/tests/test_statsd.py @@ -4,7 +4,6 @@ import shutil import socket import tempfile -from datetime import timedelta from types import SimpleNamespace from gunicorn.config import Config @@ -111,8 +110,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"