michael.heier/jellyfin
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge pull request #1003 from Bond-009/stopwatch

Browse Source 
Use stopwatch for more accurate measurements and reduce log spam
This commit is contained in:
Vasily 2019-02-26 01:27:42 +03:00 committed by GitHub
commit 9bab93262e
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 27 additions and 122 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
Emby.Server.Implementations/ApplicationHost.cs
View File

@ -550,16 +550,18 @@ namespace Emby.Server.Implementations
var entryPoints = GetExports<IServerEntryPoint>();
var now = DateTime.UtcNow;
var stopWatch = new Stopwatch();
stopWatch.Start();
await Task.WhenAll(StartEntryPoints(entryPoints, true));
Logger.LogInformation("Executed all pre-startup entry points in {Elapsed:fff} ms", DateTime.Now - now);
Logger.LogInformation("Executed all pre-startup entry points in {Elapsed:fff} ms", stopWatch.Elapsed);
Logger.LogInformation("Core startup complete");
HttpServer.GlobalResponse = null;
now = DateTime.UtcNow;
stopWatch.Restart();
await Task.WhenAll(StartEntryPoints(entryPoints, false));
Logger.LogInformation("Executed all post-startup entry points in {Elapsed:fff} ms", DateTime.Now - now);
Logger.LogInformation("Executed all post-startup entry points in {Elapsed:fff} ms", stopWatch.Elapsed);
stopWatch.Stop();
}
private IEnumerable<Task> StartEntryPoints(IEnumerable<IServerEntryPoint> entryPoints, bool isBeforeStartup)

82
Emby.Server.Implementations/HttpServer/HttpListenerHost.cs
View File

@ -1,5 +1,6 @@
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Globalization;
using System.IO;
using System.Linq;
@ -286,31 +287,6 @@ namespace Emby.Server.Implementations.HttpServer
}
}
private static readonly string[] _skipLogExtensions =
{
".js",
".css",
".woff",
".woff2",
".ttf",
".html"
};
private bool EnableLogging(string url, string localPath)
{
var extension = GetExtension(url);
return ((string.IsNullOrEmpty(extension) || !_skipLogExtensions.Contains(extension))
&& (string.IsNullOrEmpty(localPath) || localPath.IndexOf("system/ping", StringComparison.OrdinalIgnoreCase) == -1));
}
private static string GetExtension(string url)
{
var parts = url.Split(new[] { '?' }, 2);
return Path.GetExtension(parts[0]);
}
public static string RemoveQueryStringByKey(string url, string key)
{
var uri = new Uri(url);
@ -448,10 +424,9 @@ namespace Emby.Server.Implementations.HttpServer
/// </summary>
protected async Task RequestHandler(IHttpRequest httpReq, string urlString, string host, string localPath, CancellationToken cancellationToken)
{
var date = DateTime.Now;
var stopWatch = new Stopwatch();
stopWatch.Start();
var httpRes = httpReq.Response;
bool enableLog = false;
bool logHeaders = false;
string urlToLog = null;
string remoteIp = httpReq.RemoteIp;
@ -498,18 +473,8 @@ namespace Emby.Server.Implementations.HttpServer
return;
}
var operationName = httpReq.OperationName;
enableLog = EnableLogging(urlString, localPath);
urlToLog = urlString;
logHeaders = enableLog && urlToLog.IndexOf("/videos/", StringComparison.OrdinalIgnoreCase) != -1;
if (enableLog)
{
urlToLog = GetUrlToLog(urlString);
LoggerUtils.LogRequest(_logger, urlToLog, httpReq.HttpMethod, httpReq.UserAgent, logHeaders ? httpReq.Headers : null);
}
urlToLog = GetUrlToLog(urlString);
Logger.LogDebug("HTTP {HttpMethod} {Url} UserAgent: {UserAgent} \nHeaders: {@Headers}", urlToLog, httpReq.UserAgent ?? string.Empty, httpReq.HttpMethod, httpReq.Headers);
if (string.Equals(localPath, "/emby/", StringComparison.OrdinalIgnoreCase) ||
string.Equals(localPath, "/mediabrowser/", StringComparison.OrdinalIgnoreCase))
@ -517,6 +482,7 @@ namespace Emby.Server.Implementations.HttpServer
RedirectToUrl(httpRes, DefaultRedirectPath);
return;
}
if (string.Equals(localPath, "/emby", StringComparison.OrdinalIgnoreCase) ||
string.Equals(localPath, "/mediabrowser", StringComparison.OrdinalIgnoreCase))
{
@ -562,16 +528,19 @@ namespace Emby.Server.Implementations.HttpServer
RedirectToUrl(httpRes, DefaultRedirectPath);
return;
}
if (string.Equals(localPath, "/web/", StringComparison.OrdinalIgnoreCase))
{
RedirectToUrl(httpRes, "../" + DefaultRedirectPath);
return;
}
if (string.Equals(localPath, "/", StringComparison.OrdinalIgnoreCase))
{
RedirectToUrl(httpRes, DefaultRedirectPath);
return;
}
if (string.IsNullOrEmpty(localPath))
{
RedirectToUrl(httpRes, "/" + DefaultRedirectPath);
@ -607,33 +576,21 @@ namespace Emby.Server.Implementations.HttpServer
if (handler != null)
{
await handler.ProcessRequestAsync(this, httpReq, httpRes, Logger, operationName, cancellationToken).ConfigureAwait(false);
await handler.ProcessRequestAsync(this, httpReq, httpRes, Logger, httpReq.OperationName, cancellationToken).ConfigureAwait(false);
}
else
{
await ErrorHandler(new FileNotFoundException(), httpReq, false, false).ConfigureAwait(false);
}
}
catch (OperationCanceledException ex)
catch (Exception ex) when (ex is SocketException || ex is IOException || ex is OperationCanceledException)
{
await ErrorHandler(ex, httpReq, false, false).ConfigureAwait(false);
}
catch (IOException ex)
{
await ErrorHandler(ex, httpReq, false, false).ConfigureAwait(false);
}
catch (SocketException ex)
{
await ErrorHandler(ex, httpReq, false, false).ConfigureAwait(false);
}
catch (SecurityException ex)
{
await ErrorHandler(ex, httpReq, false, true).ConfigureAwait(false);
}
catch (Exception ex)
{
var logException = !string.Equals(ex.GetType().Name, "SocketException", StringComparison.OrdinalIgnoreCase);
@ -644,13 +601,15 @@ namespace Emby.Server.Implementations.HttpServer
{
httpRes.Close();
if (enableLog)
stopWatch.Stop();
var elapsed = stopWatch.Elapsed;
if (elapsed.Milliseconds > 500)
{
var statusCode = httpRes.StatusCode;
var duration = DateTime.Now - date;
LoggerUtils.LogResponse(_logger, statusCode, urlToLog, remoteIp, duration, logHeaders ? httpRes.Headers : null);
_logger.LogWarning("HTTP Response {StatusCode} to {RemoteIp}. Time (slow): {Elapsed:ss.fff}. {Url}", httpRes.StatusCode, remoteIp, stopWatch.Elapsed, urlToLog);
}
else
{
_logger.LogDebug("HTTP Response {StatusCode} to {RemoteIp}. Time: {Elapsed:ss.fff}. {Url}", httpRes.StatusCode, remoteIp, stopWatch.Elapsed, urlToLog);
}
}
}
@ -663,12 +622,11 @@ namespace Emby.Server.Implementations.HttpServer
var pathParts = pathInfo.TrimStart('/').Split('/');
if (pathParts.Length == 0)
{
_logger.LogError("Path parts empty for PathInfo: {pathInfo}, Url: {RawUrl}", pathInfo, httpReq.RawUrl);
_logger.LogError("Path parts empty for PathInfo: {PathInfo}, Url: {RawUrl}", pathInfo, httpReq.RawUrl);
return null;
}
var restPath = ServiceHandler.FindMatchingRestPath(httpReq.HttpMethod, pathInfo, out string contentType);
if (restPath != null)
{
return new ServiceHandler

55
Emby.Server.Implementations/HttpServer/LoggerUtils.cs
View File

@ -1,55 +0,0 @@
using System;
using System.Globalization;
using MediaBrowser.Model.Services;
using Microsoft.Extensions.Logging;
namespace Emby.Server.Implementations.HttpServer
{
public static class LoggerUtils
{
public static void LogRequest(ILogger logger, string url, string method, string userAgent, QueryParamCollection headers)
{
if (headers == null)
{
logger.LogInformation("{0} {1}. UserAgent: {2}", "HTTP " + method, url, userAgent ?? string.Empty);
}
else
{
var headerText = string.Empty;
var index = 0;
foreach (var i in headers)
{
if (index > 0)
{
headerText += ", ";
}
headerText += i.Name + "=" + i.Value;
index++;
}
logger.LogInformation("HTTP {0} {1}. {2}", method, url, headerText);
}
}
/// <summary>
/// Logs the response.
/// </summary>
/// <param name="logger">The logger.</param>
/// <param name="statusCode">The status code.</param>
/// <param name="url">The URL.</param>
/// <param name="endPoint">The end point.</param>
/// <param name="duration">The duration.</param>
public static void LogResponse(ILogger logger, int statusCode, string url, string endPoint, TimeSpan duration, QueryParamCollection headers)
{
var durationMs = duration.TotalMilliseconds;
var logSuffix = durationMs >= 1000 && durationMs < 60000 ? "ms (slow)" : "ms";
//var headerText = headers == null ? string.Empty : "Headers: " + string.Join(", ", headers.Where(i => i.Name.IndexOf("Access-", StringComparison.OrdinalIgnoreCase) == -1).Select(i => i.Name + "=" + i.Value).ToArray());
var headerText = string.Empty;
logger.LogInformation("HTTP Response {0} to {1}. Time: {2}{3}. {4} {5}", statusCode, endPoint, Convert.ToInt32(durationMs).ToString(CultureInfo.InvariantCulture), logSuffix, url, headerText);
}
}
}

2
Emby.Server.Implementations/ScheduledTasks/Triggers/DailyTrigger.cs
View File

@ -44,7 +44,7 @@ namespace Emby.Server.Implementations.ScheduledTasks
var dueTime = triggerDate - now;
logger.LogInformation("Daily trigger for {0} set to fire at {1}, which is {2} minutes from now.", taskName, triggerDate.ToString(), dueTime.TotalMinutes.ToString(CultureInfo.InvariantCulture));
logger.LogInformation("Daily trigger for {0} set to fire at {1}, which is {2} minutes from now.", taskName, triggerDate, dueTime);
Timer = new Timer(state => OnTriggered(), null, dueTime, TimeSpan.FromMilliseconds(-1));
}