Add request duration logging in nanoseconds

[sfozz]

Many systems provide the facility (either by default, or by configuration) to log request duration in nanosecond resolution.

In order to provide an optional but consistent approach to logging there should be the ability to log in the same resolution in gunicorn.

Since Python 3.7 all clocks are able to provide times in this resolution. ref

[pajod]

Workaround described in #3375 (comment)

[sfozz]

ah there was a prior Issue... looks like I wasn't thorough in checking!

Although it looks like the reporter decided that micro seconds was the smallest usable resolution.

Do you have a better idea of a path forward given a deeper understanding of the project?

[pajod]

If there is consensus that it should be added, then I'd have an idea how to minimize breaking API change: Pull the signature change up to a new superclass and only change the publicly-overridden class in some later release.

Apart from that, my 2⁄100:

• Most only care for formatting, and that is possible even with Python throwing away available (on Linux, anyway) precision.
• Those who really care about 3 more decimal digits of timer precision, they likely care more about computational effort spent on processing a request, rather than real time passed between operations possibly stalled on I/O on high-latency HTTP-over-TCP/IP connections (the noise of which is not really request-dependent, so why bother tracking it at request level?). And in any case, it is difficult to get right for all workers and use cases in Gunicorn anyway. So it is probably better served by plugging in WSGI middleware (being extensible in that regard is a stated goal of the interface) or locally overriding the class. Maybe all that Gunicorn needs to ship here is a copy-pastable codeblock in docs, or something in examples/

[sfozz]

The other way I was looking at this was using the nanosecond timer instead of the datetime and then deriving the other precision options from that. That also would be a breaking change, but it would be more intentional and clearer as to the purpose.

The motivation for this is simplification and compatibility, if everything is in nanos then is no need to parse all the different precisions from different sources. Additionally when working in heterogeneous environments if all sources are reporting in the same precision then you are able to compare directly without the cognitive overhead of knowing which precision a signal is in and how you go about converting that during the query process.

For the default logs the precision should remain the same as it is currently, but having the option to change this to a consistent format is desirable and forward looking.