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.

Author: sfozz

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:

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

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()
         }
 

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')

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])

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()

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()

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()

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'] == '-'

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"