Request timings not very accurate (nearest 15ms)

[benaadams]

And the server is too fast for it to be that imprecise.

info: Microsoft.AspNet.Hosting.Internal.WebApplication[1]
Request starting HTTP/1.1 GET http://localhost:5001/plaintext
info: Microsoft.AspNet.Hosting.Internal.WebApplication[2]
Request finished in 15ms 200
info: Microsoft.AspNet.Hosting.Internal.WebApplication[1]
Request starting HTTP/1.1 GET http://localhost:5001/favicon.ico
info: Microsoft.AspNet.Hosting.Internal.WebApplication[2]
Request finished in 0ms 200
info: Microsoft.AspNet.Hosting.Internal.WebApplication[1]
Request starting HTTP/1.1 GET http://localhost:5001/plaintext
info: Microsoft.AspNet.Hosting.Internal.WebApplication[2]
Request finished in 0ms 200
info: Microsoft.AspNet.Hosting.Internal.WebApplication[1]
Request starting HTTP/1.1 GET http://localhost:5001/favicon.ico
info: Microsoft.AspNet.Hosting.Internal.WebApplication[2]
Request finished in 0ms 200
info: Microsoft.AspNet.Hosting.Internal.WebApplication[1]
Request starting HTTP/1.1 GET http://localhost:5001/plaintext
info: Microsoft.AspNet.Hosting.Internal.WebApplication[2]
Request finished in 0ms 200
info: Microsoft.AspNet.Hosting.Internal.WebApplication[1]
Request starting HTTP/1.1 GET http://localhost:5001/favicon.ico
info: Microsoft.AspNet.Hosting.Internal.WebApplication[2]
Request finished in 0ms 200
info: Microsoft.AspNet.Hosting.Internal.WebApplication[1]
Request starting HTTP/1.1 GET http://localhost:5001/plaintext
info: Microsoft.AspNet.Hosting.Internal.WebApplication[2]
Request finished in 15ms 200
info: Microsoft.AspNet.Hosting.Internal.WebApplication[1]
Request starting HTTP/1.1 GET http://localhost:5001/favicon.ico
info: Microsoft.AspNet.Hosting.Internal.WebApplication[2]
Request finished in 0ms 200
info: Microsoft.AspNet.Hosting.Internal.WebApplication[1]
Request starting HTTP/1.1 GET http://localhost:5001/plaintext
info: Microsoft.AspNet.Hosting.Internal.WebApplication[2]
Request finished in 0ms 200
info: Microsoft.AspNet.Hosting.Internal.WebApplication[1]
Request starting HTTP/1.1 GET http://localhost:5001/favicon.ico
info: Microsoft.AspNet.Hosting.Internal.WebApplication[2]
Request finished in 0ms 200

[mattnischan]

in src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs:

public static void RequestFinished(this ILogger logger, HttpContext httpContext, int startTimeInTicks, int currentTick)

in src/Microsoft.AspNet.Hosting/Internal/HostingApplication.cs:

var currentTick = Environment.TickCount;
_logger.RequestFinished(httpContext, context.StartTick, currentTick);

Environment.TickCount is non-high-precision in most platforms, about 15ms resolution, as you're seeing. In some cases DateTime.Ticks can be higher precision, but that is implementation dependent.

Could also burn a Stopwatch here every time, but I don't know if the overhead is worth it. DateTime.Ticks does seem like the better compromise.

[benaadams]

@mattnischan added a PR for the improvement #543

[JunTaoLuo]

The PR has been merged. Thanks @benaadams!