网上有很多开源的性能分析组件，比如MiniProfiler，都很优秀，在这里我们手工实现基本的性能跟踪。
asp.net mvc或者.net core mvc都有自己的生命周期，这里以asp.net mvc为例！
一、创建日志类
这个类需要穿插到各个模块中，所以尽量放在一个独立的组件。附代码：
namespace Singoo.Common
{
public static class PerfAnalyze
{
static PerfAnalyze()
{
HandleCollection = new List<PerfInfoModel>();
}
public static List<PerfInfoModel> HandleCollection { get; set; }
public static void Input(string item)
{
Input(new PerfInfoModel() { EventItem = item, CurrDatetime = DateTime.Now });
}
const string firstEventItem = "Application_BeginRequest";
const string lastEventItem = "Application_EndRequest";
private static void Input(PerfInfoModel model)
{
if (!System.Configuration.ConfigurationManager.AppSettings.AllKeys.Contains("PerfAnalyzeLog") || System.Configuration.ConfigurationManager.AppSettings["PerfAnalyzeLog"].ToString() != "true")
return;
HandleCollection.Add(model);
}
public static void OutputLog()
{
Func<string, string> funcLenPadd = (x) =>
{
return x.Length < 50
? x.PadRight(50 - x.Length, ' ')
: x;
};
if (HandleCollection == null || HandleCollection.Count == 0) return;
var builder = new StringBuilder();
builder.Append("------------------start-----------------------\r\n");
DateTime firstDatetime = HandleCollection.Min(p => p.CurrDatetime);
DateTime lastDatetime = new DateTime(1900, 1, 1);
double costTime = 0; //花费时间（毫秒）
foreach (var item in HandleCollection.OrderBy(p => p.CurrDatetime))
{
lastDatetime = item.CurrDatetime;
costTime = (lastDatetime - firstDatetime).TotalMilliseconds;
builder.AppendFormat("事件： {0} 日志时间： {1} 消耗时间(毫秒)： {2} \r\n", funcLenPadd(item.EventItem), item.CurrDatetime.ToString("yyyy-MM-dd HH:mm:ss ffff"), costTime);
}
builder.Append("-------------------end------------------------\r\n");
FileLog.Log(builder.ToString(), ""); //生成的日志文件在 \LogFile\年月日
}
public static string OutputConsole()
{
if (HandleCollection == null || HandleCollection.Count == 0) return "";
var arrId = "arrPerfAnalyze_" DateTime.Now.ToString("ffff");
var builder = new StringBuilder("<script>");
builder.Append($"let {arrId}=[];");
DateTime firstDatetime = HandleCollection.Min(p => p.CurrDatetime);
DateTime lastDatetime = new DateTime(1900, 1, 1);
double costTime = 0; //花费时间（毫秒）
foreach (var item in HandleCollection.OrderBy(p => p.CurrDatetime))
{
lastDatetime = item.CurrDatetime;
costTime = (lastDatetime - firstDatetime).TotalMilliseconds;
builder.AppendFormat("{3}.push({{\"事件\":\"{0}\",\"日志时间\":\"{1}\",\"消耗时间(毫秒)\":{2}}});", item.EventItem, item.CurrDatetime.ToString("yyyy-MM-dd HH:mm:ss ffff"), costTime, arrId);
}
//剩下的EndRequest其实差别不大，加上
builder.AppendFormat("{3}.push({{\"事件\":\"{0}\",\"日志时间\":\"{1}\",\"消耗时间(毫秒)\":{2}}});", "Application_EndRequest(请求结束)", lastDatetime.ToString("yyyy-MM-dd HH:mm:ss ffff"), costTime, arrId);
builder.Append("console.warn(`在web.config-appsetting配置<add key=\"PerfAnalyzeLog\" value=\"true/false\" />进行开启和关闭`);");
builder.Append($"console.table({arrId});");
builder.Append("</script>");
return builder.ToString();
}
}
public class PerfInfoModel
{
/// <summary>
/// 事件
/// </summary>
public string EventItem { get; set; }
/// <summary>
/// 当前时间
/// </summary>
public DateTime CurrDatetime { get; set; }
/// <summary>
/// 花费时间(毫秒)
/// </summary>
public double CostTime { get; set; } = 0;
}
}记录日志时，只记录事件和时间，在输出的时候计算耗时。
二、在各事件中记录日志
1）在生命周期事件中记录日志
#region 一堆的事件
protected void Application_Start()
{
PerfAnalyze.Input("Application_Start(系统初始化)");
}
protected void Application_BeginRequest()
{
PerfAnalyze.Input("Application_BeginRequest(请求开始)");
}
protected void Application_PreRequestHandlerExecute()
{
PerfAnalyze.Input("Application_PreRequestHandlerExecute");
}
protected void Application_PostRequestHandlerExecute()
{
PerfAnalyze.Input("Application_PostRequestHandlerExecute");
}
protected void Application_PostAuthorizeRequest()
{
PerfAnalyze.Input("Application_PostAuthorizeRequest");
}
protected void Application_ResolveRequestCache()
{
PerfAnalyze.Input("Application_ResolveRequestCache");
}
protected void Application_PostAcquireRequestState()
{
PerfAnalyze.Input("Application_PostAcquireRequestState");
}
protected void Application_PostResolveRequestCache()
{
PerfAnalyze.Input("Application_PostResolveRequestCache");
}
protected void Application_PostMapRequestHandler()
{
PerfAnalyze.Input("Application_PostMapRequestHandler");
}
protected void Application_AcquireRequestState()
{
PerfAnalyze.Input("Application_AcquireRequestState");
}
protected void Application_UpdateRequestCache()
{
PerfAnalyze.Input("Application_UpdateRequestCache");
}
protected void Application_ReleaseRequestState()
{
PerfAnalyze.Input("Application_ReleaseRequestState");
}
protected void Application_AuthorizeRequest()
{
PerfAnalyze.Input("Application_AuthorizeRequest");
}
protected void Application_EndRequest()
{
PerfAnalyze.Input("Application_EndRequest(请求结束)");
PerfAnalyze.OutputLog(); //输出到txt日志
PerfAnalyze.HandleCollection.Clear();
}
protected void Application_End()
{
PerfAnalyze.Input("Application_End(停止系统)");
}
#endregion2）在横切点，全局筛选器中写入日志
创建一个筛选器，记录Action的执行和合并View的结果输出所消耗的时间。
public class GlobalFilterAttribute : ActionFilterAttribute
{
private HtmlTextWriter tw;
private StringWriter sw;
private StringBuilder sb;
private HttpWriter output;
public override void OnActionExecuting(ActionExecutingContext context)
{
sb = new StringBuilder();
sw = new StringWriter(sb);
tw = new HtmlTextWriter(sw);
output = (HttpWriter)context.RequestContext.HttpContext.Response.Output;
context.RequestContext.HttpContext.Response.Output = tw;//注意，加上这个语句，后面才能取到Result数据
string ControllerName = context.RouteData != null && context.RouteData.Values.Keys.Contains("controller")
? context.RouteData.Values["controller"].ToString()
: "Home";
string ActionName = context.RouteData != null && context.RouteData.Values.Keys.Contains("action")
? context.RouteData.Values["action"].ToString()
: "Index";
PerfAnalyze.Input($"{ControllerName}-{ActionName}-GlobalFilter-OnActionExecuting(开始执行方法)");
base.OnActionExecuting(context);
}
public override void OnActionExecuted(ActionExecutedContext context)
{
base.OnActionExecuted(context);
string ControllerName = context.RouteData != null && context.RouteData.Values.Keys.Contains("controller")
? context.RouteData.Values["controller"].ToString()
: "Home";
string ActionName = context.RouteData != null && context.RouteData.Values.Keys.Contains("action")
? context.RouteData.Values["action"].ToString()
: "Index";
PerfAnalyze.Input($"{ControllerName}-{ActionName}-GlobalFilter-OnActionExecuted(方法执行完毕)");
}
public override void OnResultExecuting(ResultExecutingContext context)
{
string ControllerName = context.RouteData != null && context.RouteData.Values.Keys.Contains("controller")
? context.RouteData.Values["controller"].ToString()
: "Home";
string ActionName = context.RouteData != null && context.RouteData.Values.Keys.Contains("action")
? context.RouteData.Values["action"].ToString()
: "Index";
PerfAnalyze.Input($"{ControllerName}-{ActionName}-GlobalFilter-OnResultExecuting(开始整合View)");
base.OnResultExecuting(context);
}
public override void OnResultExecuted(ResultExecutedContext context)
{
string response = sb.ToString();
string ControllerName = context.RouteData != null && context.RouteData.Values.Keys.Contains("controller")
? context.RouteData.Values["controller"].ToString()
: "Home";
string ActionName = context.RouteData != null && context.RouteData.Values.Keys.Contains("action")
? context.RouteData.Values["action"].ToString()
: "Index";
var actionResult = context.Result;
if (actionResult is ViewResult)
{
PerfAnalyze.Input($"{ControllerName}-{ActionName}-GlobalFilter-OnResultExecuted(整合View完毕并输出)");
string js = PerfAnalyze.OutputConsole();
if (js != null && js.Trim().Length > 0)
response = js;
}
output.Write(response);
base.OnResultExecuted(context);
}
}可以看到，我们使用了一个js，拼成json数组，最后用console.table输出日志，这部分最后只到action完成并输出结果，后续的操作基本无消耗，可以等同完成了。若要查看全部完整的日志，可以查看txt文本日志
三、查看日志
1）通过谷歌浏览器DevTool查看Console日志
可以看到，日志从开始请求到结束请求一系列的操作，并消耗的时间（毫秒）。
怎么在我们的程序中写入日志？很简单，在我们的程序中写入：
public virtual ActionResult Index(string dsfm_code)
{
PerfAnalyze.Input("SmartCodeSingleController-Index-Start(开始执行低代码首页方法)");
//...
}
2）查看文本日志
