in src/PerfView/PerfViewData.cs [1546:2218]
protected override void WriteHtmlBody(TraceLog dataFile, TextWriter writer, string fileName, TextWriter log)
{
writer.WriteLine("<H2>IIS Request Statistics</H2>");
var dispatcher = dataFile.Events.GetSource();
dispatcher.Dynamic.AddCallbackForProviderEvent("Microsoft-Windows-ASPNET", "Request/Send", delegate (TraceEvent data)
{
IisRequest request;
if (m_Requests.TryGetValue(data.ActivityID, out request))
{
if (data.RelatedActivityID != Guid.Empty)
{
request.RelatedActivityId = data.RelatedActivityID;
}
}
});
Dictionary<Guid, int> childRequests = new Dictionary<Guid, int>();
var iis = new IisTraceEventParser(dispatcher);
int startcount = 0;
int endcount = 0;
iis.IISGeneralGeneralChildRequestStart += delegate (W3GeneralChildRequestStart traceEvent)
{
int childRequestRecurseLevel = 0;
if (childRequests.ContainsKey(traceEvent.ContextId))
{
if (childRequests.TryGetValue(traceEvent.ContextId, out childRequestRecurseLevel))
{
childRequests[traceEvent.ContextId] = childRequestRecurseLevel + 1;
}
}
else
{
childRequests.Add(traceEvent.ContextId, 1);
}
};
iis.IISGeneralGeneralChildRequestEnd += delegate (W3GeneralChildRequestEnd traceEvent)
{
int childRequestRecurseLevel = 0;
if (childRequests.ContainsKey(traceEvent.ContextId))
{
if (childRequests.TryGetValue(traceEvent.ContextId, out childRequestRecurseLevel))
{
childRequests[traceEvent.ContextId] = childRequestRecurseLevel - 1;
}
}
};
iis.IISGeneralGeneralRequestStart += delegate (W3GeneralStartNewRequest request)
{
IisRequest req = new IisRequest();
req.ContextId = request.ContextId;
req.StartTimeRelativeMSec = request.TimeStampRelativeMSec;
req.Method = request.RequestVerb;
req.Path = request.RequestURL;
// This check is required for requests which have child
// request events in them. For those, the StartNewRequest
// would be called twice for the same request. At this
// point, I don't think that is causing any problems to us
if (!m_Requests.ContainsKey(request.ContextId))
{
m_Requests.Add(request.ContextId, req);
}
startcount++;
};
iis.IISGeneralGeneralRequestEnd += delegate (W3GeneralEndNewRequest req)
{
IisRequest request;
if (m_Requests.TryGetValue(req.ContextId, out request))
{
request.EndTimeRelativeMSec = req.TimeStampRelativeMSec;
request.BytesReceived = req.BytesReceived;
request.BytesSent = req.BytesSent;
request.StatusCode = req.HttpStatus;
request.SubStatusCode = req.HttpSubStatus;
}
endcount++;
};
iis.IISRequestNotificationPreBeginRequestStart += delegate (IISRequestNotificationPreBeginStart preBeginEvent)
{
IisRequest request;
if (!m_Requests.TryGetValue(preBeginEvent.ContextId, out request))
{
// so this is the case where we dont have a GENERAL_REQUEST_START
// event but we got a MODULE\START Event fired for this request
// so we do our best to create a FAKE start request event
// populating as much information as we can as this is one of
// those requests which could have started before the trace was started
request = GenerateFakeIISRequest(preBeginEvent.ContextId, preBeginEvent);
m_Requests.Add(preBeginEvent.ContextId, request);
}
int childRequestRecurseLevel = GetChildEventRecurseLevel(preBeginEvent.ContextId, childRequests);
var iisPrebeginModuleEvent = new IisPrebeginModuleEvent();
iisPrebeginModuleEvent.Name = preBeginEvent.ModuleName;
iisPrebeginModuleEvent.StartTimeRelativeMSec = preBeginEvent.TimeStampRelativeMSec;
iisPrebeginModuleEvent.ProcessId = preBeginEvent.ProcessID;
iisPrebeginModuleEvent.StartThreadId = preBeginEvent.ThreadID;
iisPrebeginModuleEvent.ChildRequestRecurseLevel = childRequestRecurseLevel;
request.PipelineEvents.Add(iisPrebeginModuleEvent);
};
iis.IISRequestNotificationPreBeginRequestEnd += delegate (IISRequestNotificationPreBeginEnd preBeginEvent)
{
IisRequest request;
int childRequestRecurseLevel = GetChildEventRecurseLevel(preBeginEvent.ContextId, childRequests);
if (m_Requests.TryGetValue(preBeginEvent.ContextId, out request))
{
var module = request.PipelineEvents.FirstOrDefault(m => m.Name == preBeginEvent.ModuleName && m.ChildRequestRecurseLevel == childRequestRecurseLevel);
if (module != null)
{
module.EndTimeRelativeMSec = preBeginEvent.TimeStampRelativeMSec;
module.EndThreadId = preBeginEvent.ThreadID;
}
}
// so this is the case where we dont have a GENERAL_REQUEST_START
// event as well as Module Start event for the request but we got
// a Module End Event fired for this request. Assuming this happens,
// the worst we will miss is delay between this module end event
// to the next module start event and that should ideally be very
// less. Hence we don't need the else part for this condition
//else { }
};
iis.IISRequestNotificationNotifyModuleStart += delegate (IISRequestNotificationEventsStart moduleEvent)
{
IisRequest request;
if (!m_Requests.TryGetValue(moduleEvent.ContextId, out request))
{
// so this is the case where we dont have a GENERAL_REQUEST_START
// event but we got a MODULE\START Event fired for this request
// so we do our best to create a FAKE start request event
// populating as much information as we can as this is one of
// those requests which could have started before the trace was started
request = GenerateFakeIISRequest(moduleEvent.ContextId, moduleEvent);
m_Requests.Add(moduleEvent.ContextId, request);
}
int childRequestRecurseLevel = GetChildEventRecurseLevel(moduleEvent.ContextId, childRequests);
var iisModuleEvent = new IisModuleEvent();
iisModuleEvent.Name = moduleEvent.ModuleName;
iisModuleEvent.StartTimeRelativeMSec = moduleEvent.TimeStampRelativeMSec;
iisModuleEvent.ProcessId = moduleEvent.ProcessID;
iisModuleEvent.StartThreadId = moduleEvent.ThreadID;
iisModuleEvent.fIsPostNotification = moduleEvent.fIsPostNotification;
iisModuleEvent.Notification = (RequestNotification)moduleEvent.Notification;
iisModuleEvent.ChildRequestRecurseLevel = childRequestRecurseLevel;
iisModuleEvent.foundEndEvent = false;
request.PipelineEvents.Add(iisModuleEvent);
};
iis.IISRequestNotificationNotifyModuleEnd += delegate (IISRequestNotificationEventsEnd moduleEvent)
{
IisRequest request;
int childRequestRecurseLevel = GetChildEventRecurseLevel(moduleEvent.ContextId, childRequests);
if (m_Requests.TryGetValue(moduleEvent.ContextId, out request))
{
IEnumerable<IisModuleEvent> iisModuleEvents = request.PipelineEvents.OfType<IisModuleEvent>();
var module = iisModuleEvents.FirstOrDefault(m => m.Name == moduleEvent.ModuleName && m.Notification == (RequestNotification)moduleEvent.Notification && m.fIsPostNotification == moduleEvent.fIsPostNotificationEvent && m.ChildRequestRecurseLevel == childRequestRecurseLevel && m.foundEndEvent == false);
if (module != null)
{
module.EndTimeRelativeMSec = moduleEvent.TimeStampRelativeMSec;
module.EndThreadId = moduleEvent.ThreadID;
module.foundEndEvent = true;
}
}
// so this is the case where we dont have a GENERAL_REQUEST_START event as well
// as Module Start event for the request but we got a Module End Event fired for
// this request. Assuming this happens, the worst we will miss is delay between
// this module end event to the next module start event and that should ideally be
// less. Hence we don't need the else part for this condition
};
iis.IISRequestNotificationModuleSetResponseErrorStatus += delegate (IISRequestNotificationEventsResponseErrorStatus responseErrorStatusNotification)
{
IisRequest request;
if (m_Requests.TryGetValue(responseErrorStatusNotification.ContextId, out request))
{
request.FailureDetails = new RequestFailureDetails();
request.FailureDetails.HttpReason = responseErrorStatusNotification.HttpReason;
request.FailureDetails.HttpStatus = responseErrorStatusNotification.HttpStatus;
request.FailureDetails.HttpSubStatus = responseErrorStatusNotification.HttpSubStatus;
request.FailureDetails.ModuleName = responseErrorStatusNotification.ModuleName;
request.FailureDetails.ErrorCode = responseErrorStatusNotification.ErrorCode;
request.FailureDetails.ConfigExceptionInfo = responseErrorStatusNotification.ConfigExceptionInfo;
request.FailureDetails.Notification = (RequestNotification)responseErrorStatusNotification.Notification;
request.FailureDetails.TimeStampRelativeMSec = responseErrorStatusNotification.TimeStampRelativeMSec;
}
};
iis.IISGeneralGeneralFlushResponseStart += delegate (W3GeneralFlushResponseStart traceEvent)
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISGeneralGeneralFlushResponseEnd += delegate (W3GeneralFlushResponseEnd traceEvent)
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISGeneralGeneralReadEntityStart += delegate (W3GeneralReadEntityStart traceEvent)
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISGeneralGeneralReadEntityEnd += delegate (W3GeneralReadEntityEnd traceEvent)
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISCacheFileCacheAccessStart += delegate (W3CacheFileCacheAccessStart traceEvent)
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISCacheFileCacheAccessEnd += delegate (W3CacheFileCacheAccessEnd traceEvent)
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISCacheUrlCacheAccessStart += delegate (W3CacheURLCacheAccessStart traceEvent)
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISCacheUrlCacheAccessEnd += delegate (W3CacheURLCacheAccessEnd traceEvent)
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISFilterFilterStart += delegate (W3FilterStart traceEvent)
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISFilterFilterEnd += delegate (W3FilterEnd traceEvent)
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISAuthenticationAuthStart += delegate (W3AuthStart traceEvent)
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISAuthenticationAuthEnd += delegate (W3AuthEnd traceEvent)
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISCacheOutputCacheLookupStart += delegate (W3OutputCacheLookupStart traceEvent)
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISCacheOutputCacheLookupEnd += delegate (W3OutputCacheLookupEnd traceEvent)
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISCompressionDynamicCompressionStart += delegate (W3DynamicCompressionStart traceEvent)
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISCompressionDynamicCompressionEnd += delegate (W3DynamicCompressionEnd traceEvent)
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISCompressionStaticCompressionStart += delegate (W3StaticCompressionStart traceEvent)
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISCompressionStaticCompressionEnd += delegate (W3StaticCompressionEnd traceEvent)
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISFilterFilterPreprocHeadersStart += delegate (W3FilterPreprocStart traceEvent)
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
iis.IISFilterFilterPreprocHeadersEnd += delegate (W3FilterPreprocEnd traceEvent)
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests);
};
var aspNet = new AspNetTraceEventParser(dispatcher);
// The logic used here is that delays between "AspNetTrace/AspNetReq/Start" and "AspNetTrace/AspNetReq/AppDomainEnter"
// will be due to the delay introduced due to the CLR threadpool code based on how
// ASP.NET code emits these events.
aspNet.AspNetReqStart += delegate (AspNetStartTraceData traceEvent)
{
IisRequest iisRequest;
if (m_Requests.TryGetValue(traceEvent.ContextId, out iisRequest))
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests, "CLRThreadPoolQueue");
}
};
aspNet.AspNetReqAppDomainEnter += delegate (AspNetAppDomainEnterTraceData traceEvent)
{
IisRequest iisRequest;
if (m_Requests.TryGetValue(traceEvent.ContextId, out iisRequest))
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests, "CLRThreadPoolQueue");
}
};
aspNet.AspNetReqSessionDataBegin += delegate (AspNetAcquireSessionBeginTraceData traceEvent)
{
IisRequest iisRequest;
if (m_Requests.TryGetValue(traceEvent.ContextId, out iisRequest))
{
AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, childRequests, "AspNetReqSessionData");
}
};
aspNet.AspNetReqSessionDataEnd += delegate (AspNetAcquireSessionEndTraceData traceEvent)
{
IisRequest iisRequest;
if (m_Requests.TryGetValue(traceEvent.ContextId, out iisRequest))
{
AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, childRequests, "AspNetReqSessionData");
}
};
aspNet.AspNetReqPipelineModuleEnter += delegate (AspNetPipelineModuleEnterTraceData traceEvent)
{
IisRequest request;
if (m_Requests.TryGetValue(traceEvent.ContextId, out request))
{
var aspnetPipelineModuleEvent = new AspNetPipelineModuleEvent()
{
Name = traceEvent.ModuleName,
ModuleName = traceEvent.ModuleName,
StartTimeRelativeMSec = traceEvent.TimeStampRelativeMSec,
ProcessId = traceEvent.ProcessID,
StartThreadId = traceEvent.ThreadID,
};
request.PipelineEvents.Add(aspnetPipelineModuleEvent);
}
};
aspNet.AspNetReqPipelineModuleLeave += delegate (AspNetPipelineModuleLeaveTraceData traceEvent)
{
IisRequest request;
if (m_Requests.TryGetValue(traceEvent.ContextId, out request))
{
IEnumerable<AspNetPipelineModuleEvent> aspnetPipelineModuleEvents = request.PipelineEvents.OfType<AspNetPipelineModuleEvent>();
var module = aspnetPipelineModuleEvents.FirstOrDefault(m => m.ModuleName == traceEvent.ModuleName && m.foundEndEvent == false);
if (module != null)
{
module.EndTimeRelativeMSec = traceEvent.TimeStampRelativeMSec;
module.EndThreadId = traceEvent.ThreadID;
module.foundEndEvent = true;
}
}
};
// Lets look at the rest of Enter/Leave events in AspNetReq now.
aspNet.AddCallbackForEvents(name => name.EndsWith("Enter"), null, (TraceEvent traceEvent) =>
{
// We are using AspNetReqAppDomainEnter to compute for ClrThreadPool so exclude that for now
if (!traceEvent.OpcodeName.EndsWith("AppDomainEnter") && !traceEvent.OpcodeName.EndsWith("PipelineModuleEnter"))
{
object contextObj = traceEvent.PayloadByName("ContextId");
if (contextObj != null && contextObj.GetType() == typeof(Guid))
{
Guid contextGuid = (Guid)contextObj;
IisRequest iisRequest;
if (m_Requests.TryGetValue(contextGuid, out iisRequest))
{
AddGenericStartEventToRequest(contextGuid, traceEvent, childRequests);
}
}
}
});
aspNet.AddCallbackForEvents(name => name.EndsWith("Leave"), null, (TraceEvent traceEvent) =>
{
if (!traceEvent.OpcodeName.EndsWith("PipelineModuleLeave"))
{
object contextObj = traceEvent.PayloadByName("ContextId");
if (contextObj != null && contextObj.GetType() == typeof(Guid))
{
Guid contextGuid = (Guid)contextObj;
IisRequest iisRequest;
if (m_Requests.TryGetValue(contextGuid, out iisRequest))
{
AddGenericStopEventToRequest(contextGuid, traceEvent, childRequests);
}
}
}
});
var clr = new ClrTraceEventParser(dispatcher);
clr.ExceptionStart += delegate (ExceptionTraceData data)
{
ExceptionDetails ex = new ExceptionDetails();
ex.ExceptionMessage = data.ExceptionMessage;
ex.ExceptionType = data.ExceptionType;
ex.ThreadId = data.ThreadID;
ex.ProcessId = data.ProcessID;
ex.TimeStampRelativeMSec = data.TimeStampRelativeMSec;
allExceptions.Add(ex);
};
dispatcher.Process();
// manual fixup for incomplete requests
foreach (var request in m_Requests.Values.Where(x => x.EndTimeRelativeMSec == 0))
{
// so these are all the requests for which we see a GENERAL_REQUEST_START and no GENERAL_REQUEST_END
// for these it is safe to set the request.EndTimeRelativeMSec to the last timestamp in the trace
// because that is pretty much the duration that the request is active for.
request.EndTimeRelativeMSec = dataFile.SessionEndTimeRelativeMSec;
// Also, for this request, lets first try to find a pipeline start event which does not have a pipeline
// stop event next to it. If we find, we just set the EndTimeRelativeMSec to the end of the trace
var incompletePipeLineEvents = request.PipelineEvents.Where(m => m.EndTimeRelativeMSec == 0);
if (incompletePipeLineEvents.Count() >= 1)
{
foreach (var incompleteEvent in incompletePipeLineEvents)
{
incompleteEvent.EndTimeRelativeMSec = dataFile.SessionEndTimeRelativeMSec;
}
// not setting incompleteEvent.EndThreadId as this is incorrectly adding a hyperlink for requests
// requests that are stuck in the session state module
}
}
writer.WriteLine("<UL>");
var fileInfo = new System.IO.FileInfo(dataFile.FilePath);
writer.WriteLine("<LI> Total Requests: {0:n} </LI>", m_Requests.Count);
writer.WriteLine("<LI> Trace Duration (Sec): {0:n1} </LI>", dataFile.SessionDuration.TotalSeconds);
writer.WriteLine("<LI> RPS (Requests/Sec): {0:n2} </LI>", m_Requests.Count / dataFile.SessionDuration.TotalSeconds);
writer.WriteLine("<LI> Number of CPUs: {0}</LI>", dataFile.NumberOfProcessors);
writer.WriteLine("<LI> Successful Requests: {0}</LI>", m_Requests.Values.Count(x => x.StatusCode < 400));
writer.WriteLine("<LI> Failed Requests: {0}</LI>", m_Requests.Values.Count(x => x.StatusCode >= 400));
writer.WriteLine("</UL>");
try
{
writer.WriteLine("<H3>HTTP Statistics Per Request URL</H3>");
writer.WriteLine("<Table Border=\"1\">");
writer.Write("<TR>");
writer.Write("<TH Align='Center' Title='This is the Request URL. '>Path</TH>");
writer.Write("<TH Align='Center' Title='All requests for this URL'>Total</TH>");
writer.Write("<TH Align='Center' Title='The number of requests that finished with a Success HTTP Status Code'>HTTP Status (200-206)</TH>");
writer.Write("<TH Align='Center' Title='The number of requests that finished with a Redirect HTTP Status Code'>HTTP Status (301-307)</TH>");
writer.Write("<TH Align='Center' Title='The number of requests that failed with a HTTP Client error'>HTTP Status (400-412)</TH>");
writer.Write("<TH Align='Center' Title='The number of requests that failed with a HTTP server error'>HTTP Status (>=500)</TH>");
writer.WriteLine("</TR>");
var httpStatisticsPerUrl = m_Requests.Values.GroupBy(n => n.Path.Split('?')[0]).Select(c => new { Path = c.Key, Total = c.Count(), Successful = c.Count(s => s.StatusCode <= 206), Redirect = c.Count(s => s.StatusCode >= 301 && s.StatusCode <= 307), ClientError = c.Count(s => s.StatusCode >= 400 && s.StatusCode <= 412), ServerError = c.Count(s => s.StatusCode >= 500) });
// sort this list by the the maximum number of requests
foreach (var item in httpStatisticsPerUrl.OrderByDescending(x => x.Total))
{
writer.WriteLine("<TR>");
writer.Write($"<TD>{item.Path}</TD><TD Align='Center'>{item.Total}</TD><TD Align='Center'>{item.Successful}</TD><TD Align='Center'>{item.Redirect}</TD><TD Align='Center'>{item.ClientError}</TD><TD Align='Center'>{item.ServerError}</TD>");
writer.Write("</TR>");
}
writer.WriteLine("</Table>");
}
catch (Exception e)
{
log.WriteLine(@"Error while displaying 'HTTP Statistics Per Request URL' " + "\r\n" + e.ToString());
}
try
{
writer.WriteLine("<H3>HTTP Request Execution Statistics Per Request URL</H3>");
writer.WriteLine("<Table Border=\"1\">");
writer.Write("<TR>");
writer.Write("<TH Align='Center' Title='This is the Request URL.'>Path</TH>");
writer.Write("<TH Align='Center' Title='All requests for this URL'>Total</TH>");
writer.Write("<TH Align='Center' Title='The number of requests that finished in less than 1 second'> < 1s </TH>");
writer.Write("<TH Align='Center' Title='The number of requests that finished in less than 5 seconds'>< 5s</TH>");
writer.Write("<TH Align='Center' Title='The number of requests that finished in less than 15 seconds'>< 15s</TH>");
writer.Write("<TH Align='Center' Title='The number of requests that finished in less than 30 seconds'>< 30s</TH>");
writer.Write("<TH Align='Center' Title='The number of requests that finished in less than 60 seconds'>< 60s</TH>");
writer.Write("<TH Align='Center' Title='The number of requests that finished in more than 60 seconds'>> 60s</TH>");
writer.WriteLine("</TR>");
var httpRequestExecutionPerUrl = m_Requests.Values.GroupBy(n => n.Path.Split('?')[0]).Select(c => new
{
Path = c.Key,
Total = c.Count(),
OneSec = c.Count(s => (s.EndTimeRelativeMSec - s.StartTimeRelativeMSec) < 1000),
FiveSec = c.Count(s => (s.EndTimeRelativeMSec - s.StartTimeRelativeMSec) >= 1000 && (s.EndTimeRelativeMSec - s.StartTimeRelativeMSec) < 5000),
FifteenSec = c.Count(s => (s.EndTimeRelativeMSec - s.StartTimeRelativeMSec) >= 5000 && (s.EndTimeRelativeMSec - s.StartTimeRelativeMSec) < 15000),
ThirtySec = c.Count(s => (s.EndTimeRelativeMSec - s.StartTimeRelativeMSec) >= 15000 && (s.EndTimeRelativeMSec - s.StartTimeRelativeMSec) < 30000),
SixtySec = c.Count(s => (s.EndTimeRelativeMSec - s.StartTimeRelativeMSec) >= 30000 && (s.EndTimeRelativeMSec - s.StartTimeRelativeMSec) < 60000),
MoreThanSixtySec = c.Count(s => (s.EndTimeRelativeMSec - s.StartTimeRelativeMSec) > 60000)
});
// sort this list by the the maximum number of requests
foreach (var item in httpRequestExecutionPerUrl.OrderByDescending(x => x.Total))
{
writer.WriteLine("<TR>");
writer.Write($"<TD>{item.Path}</TD><TD Align='Center'>{item.Total}</TD><TD Align='Center'>{item.OneSec}</TD><TD Align='Center'>{item.FiveSec}</TD><TD Align='Center'>{item.FifteenSec}</TD><TD Align='Center'>{item.ThirtySec}</TD><TD Align='Center'>{item.SixtySec}</TD><TD Align='Center'>{item.MoreThanSixtySec}</TD>");
writer.Write("</TR>");
}
writer.WriteLine("</Table>");
}
catch (Exception e)
{
log.WriteLine(@"Error while displaying 'HTTP Request Execution Statistics Per Request URL' " + "\r\n" + e.ToString());
}
writer.WriteLine("<H3>Top 100 Slowest Request Statistics</H3>");
writer.WriteLine("The below table shows the top 100 slowest requests in this trace. Requests completing within 100 milliseconds are ignored. Hover over column headings for explanation of columns. <BR/><BR/>");
writer.WriteLine("<Table Border=\"1\">");
writer.Write("<TR>");
writer.Write("<TH Align='Center' Title='This column represents the HTTP METHOD used to make the request'>Method</TH>");
writer.Write("<TH Align='Center' Title='This is the Request URL. Click on the individual requests to see all ETW events for that request.' >Path</TH>");
writer.Write("<TH Align='Center' Title='cs-bytes represents the total bytes sent by the client for this HTTP Request'>cs-bytes</TH>");
writer.Write("<TH Align='Center' Title='sc-bytes represents the total bytes that the server sent for the HTTP Response'>sc-bytes</TH>");
writer.Write("<TH Align='Center' Title='The HTTP Status Code and Substatus code that server sent for this HTTP request'>HttpStatus</TH>");
writer.Write("<TH Align='Center' Title='The total time it took to execute the request on the server'>Duration(ms)</TH>");
writer.Write("<TH Align='Center' Title='This is the slowest module in the IIS request processing pipeline. Click on the the slowest module to see user mode stack trace for the thread. Hyperlinks to open thread stack traces are added only if the starting thread and ending thread for the module are the same.'>Slowest Module</TH>");
writer.Write("<TH Align='Center' Title='This represents the time spent in the slowest module (in milliseconds)'>Time Spent In Slowest Module(ms)</TH>");
writer.Write("<TH Align='Center' Title='This column gives you a percentage of time spent in the slowest module to the total time spent in request execution'>%Time Spent In Slowest Module</TH>");
writer.Write("<TH Align='Center' Title='Click on the relevant Views to see the stack traces captured for the request'>Stack Traces</TH>");
writer.WriteLine("</TR>");
foreach (var request in m_Requests.Values.Where(x => x.EndTimeRelativeMSec != 0).OrderByDescending(m => m.EndTimeRelativeMSec - m.StartTimeRelativeMSec).Take(100).Where((m => (m.EndTimeRelativeMSec - m.StartTimeRelativeMSec) > 100)))
{
writer.WriteLine("<TR>");
double slowestTime = 0;
IisPipelineEvent slowestPipelineEvent = GetSlowestEvent(request);
slowestTime = slowestPipelineEvent.EndTimeRelativeMSec - slowestPipelineEvent.StartTimeRelativeMSec;
int processId = slowestPipelineEvent.ProcessId;
int ThreadId = slowestPipelineEvent.StartThreadId;
double startTimePipelineEvent = slowestPipelineEvent.StartTimeRelativeMSec;
double endTimePipelineEvent = slowestPipelineEvent.EndTimeRelativeMSec;
string threadTimeStacksString = $"{processId};{ThreadId};{startTimePipelineEvent};{endTimePipelineEvent}";
string activityStacksString = $"{processId};{request.RelatedActivityId.ToString()};{startTimePipelineEvent};{endTimePipelineEvent}";
double totalTimeSpent = request.EndTimeRelativeMSec - request.StartTimeRelativeMSec;
string requestPath = request.Path;
// limit display of URL to specific character length only otherwise the table is expanding crazily
if (requestPath.Length > 85)
{
requestPath = requestPath.Substring(0, 80) + "...";
}
string threadTimeStacks = "";
string activityStacks = "";
// limit display of even the module names to specific character length only otherwise the table is expanding crazily
string slowestPipelineEventDisplay = slowestPipelineEvent.ToString();
if (slowestPipelineEventDisplay != null && slowestPipelineEventDisplay.Length > 55)
{
slowestPipelineEventDisplay = slowestPipelineEventDisplay.Substring(0, 50) + "...";
}
if (slowestPipelineEvent.StartThreadId == slowestPipelineEvent.EndThreadId)
{
threadTimeStacks = $"<A HREF =\"command:threadtimestacks:{threadTimeStacksString}\">Thread Time stacks</A>";
}
else
{
threadTimeStacks = "";
}
activityStacks = $"<A HREF =\"command:activitystacks:{activityStacksString}\">Activity Stacks</A>";
string detailedRequestCommandString = $"detailedrequestevents:{request.ContextId};{request.StartTimeRelativeMSec};{request.EndTimeRelativeMSec}";
string csBytes = (request.BytesReceived == 0) ? "-" : request.BytesReceived.ToString();
string scBytes = (request.BytesSent == 0) ? "-" : request.BytesSent.ToString();
string statusCode = (request.StatusCode == 0) ? "-" : $"{ request.StatusCode}.{ request.SubStatusCode}";
writer.WriteLine($"<TD>{request.Method}</TD><TD><A HREF=\"command:{detailedRequestCommandString}\">{requestPath}</A></TD><TD>{csBytes}</TD><TD>{scBytes}</TD><TD>{statusCode}</TD><TD>{totalTimeSpent:0.00}</TD><TD>{slowestPipelineEventDisplay}</TD><TD>{slowestTime:0.00}</TD><TD>{((slowestTime / totalTimeSpent * 100)):0.00}%</TD><TD>{activityStacks} {threadTimeStacks}</TD>");
writer.Write("</TR>");
}
writer.WriteLine("</TABLE>");
if (m_Requests.Values.Count(x => x.FailureDetails != null) > 0)
{
writer.WriteLine("<H2>Failed Requests</H2>");
writer.WriteLine("<BR/>The below table provides details of all the failed requests (requests with StatusCode >399) in the trace. <BR/>");
writer.WriteLine("<Table Border=\"1\">");
writer.Write("<TR>");
writer.Write("<TH Align='Center' Title='This column represents the HTTP METHOD used to make the request'>Method</TH>");
writer.Write("<TH Align='Center' Title='This is the Request URL' >Path</TH>");
writer.Write("<TH Align='Center' Title='cs-bytes represents the total bytes sent by the client for this HTTP Request'>cs-bytes</TH>");
writer.Write("<TH Align='Center' Title='sc-bytes represents the total bytes that the server sent for the HTTP Response'>sc-bytes</TH>");
writer.Write("<TH Align='Center' Title='The HTTP Status Code and Substatus code that server sent for this HTTP request'>HttpStatus</TH>");
writer.Write("<TH Align='Center' Title='A user-friendly description of the error code sent by the server'>Reason</TH>");
writer.Write("<TH Align='Center' Title='This is the actual HTTP Status which the server sent for this request irrespective of the failure'>Final Status</TH>");
writer.Write("<TH Align='Center' Title='Additional error code that IIS generated for the failed request'>ErrorCode</TH>");
writer.Write("<TH Align='Center' Title='The module responsible for setting the failed HTTP Status' >FailingModuleName</TH>");
writer.Write("<TH Align='Center' Title='The total time it took to execute the request on the server'>Duration(ms)</TH>");
writer.Write("<TH Align='Center' Title='Any CLR Exceptions that happened on this thread'>Exceptions</TH>");
writer.WriteLine("</TR>");
foreach (var request in m_Requests.Values.Where(x => x.FailureDetails != null))
{
writer.WriteLine("<TR>");
double totalTimeSpent = request.EndTimeRelativeMSec - request.StartTimeRelativeMSec;
string requestPath = request.Path;
// limit display of URL to 100 characters only
// otherwise the table is expanding crazily
if (requestPath.Length > 100)
{
requestPath = requestPath.Substring(0, 100) + "...";
}
string detailedRequestCommandString = $"detailedrequestevents:{request.ContextId};{request.StartTimeRelativeMSec};{request.EndTimeRelativeMSec}";
string csBytes = (request.BytesReceived == 0) ? "-" : request.BytesReceived.ToString();
string scBytes = (request.BytesSent == 0) ? "-" : request.BytesSent.ToString();
string exceptionDetails = FindExceptionForThisRequest(request);
writer.WriteLine($"<TD>{request.Method}</TD><TD><A HREF=\"command:{detailedRequestCommandString}\">{requestPath}</A></TD><TD>{csBytes}</TD><TD>{scBytes}</TD><TD>{request.FailureDetails.HttpStatus}.{request.FailureDetails.HttpSubStatus}</TD><TD>{request.FailureDetails.HttpReason}</TD><TD>{request.StatusCode}.{request.SubStatusCode}</TD><TD>{request.FailureDetails.ErrorCode}</TD><TD>{request.FailureDetails.ModuleName} ({request.FailureDetails.Notification}) </TD><TD>{totalTimeSpent:0.00}</TD><TD>{exceptionDetails}</TD>");
writer.Write("</TR>");
}
writer.WriteLine("</TABLE>");
}
else
{
writer.WriteLine("<BR/><BR/>There are no failed requests (HTTP Requests with StatusCode >=400) in this trace file");
}
writer.Flush();
}