private static List <ExceptionDetails> FindExceptionForThisRequest(IisRequest request, List <ExceptionDetails> allExceptions) { double startTimeForPipeLineEvent = 0; int processId = 0; int threadId = 0; foreach (IisModuleEvent moduleEvent in request.PipelineEvents.OfType <IisModuleEvent>().Where(x => x.Name == request.FailureDetails.ModuleName)) { if (moduleEvent.Notification == request.FailureDetails.Notification) { startTimeForPipeLineEvent = moduleEvent.StartTimeRelativeMSec; processId = moduleEvent.ProcessId; if (moduleEvent.StartThreadId == moduleEvent.EndThreadId) { threadId = moduleEvent.StartThreadId; } } } List <ExceptionDetails> exceptionsList = new List <ExceptionDetails>(); if (startTimeForPipeLineEvent > 0 && processId != 0 && threadId != 0) { foreach (var ex in allExceptions.Where(x => x.TimeStampRelativeMSec > startTimeForPipeLineEvent && x.TimeStampRelativeMSec <= request.FailureDetails.TimeStampRelativeMSec && processId == x.ProcessId && threadId == x.ThreadId)) { exceptionsList.Add(ex); } } return(exceptionsList); }
static public IisPipelineEvent GetSlowestEvent(IisRequest request) { IisPipelineEvent slowestPipelineEvent = new IisPipelineEvent(); double slowestTime = 0; foreach (var pipeLineEvent in request.PipelineEvents) { if (pipeLineEvent.StartTimeRelativeMSec != 0 && pipeLineEvent.EndTimeRelativeMSec != 0) { var timeinThisEvent = pipeLineEvent.EndTimeRelativeMSec - pipeLineEvent.StartTimeRelativeMSec; if (timeinThisEvent > slowestTime) { slowestTime = timeinThisEvent; slowestPipelineEvent = pipeLineEvent; } } } // Lets check for containment to see if a child event is taking more than 50% // of the time of this pipeline event, then we want to call that out foreach (var pipeLineEvent in request.PipelineEvents.Where(x => (x.StartTimeRelativeMSec > slowestPipelineEvent.StartTimeRelativeMSec) && (x.EndTimeRelativeMSec <= slowestPipelineEvent.EndTimeRelativeMSec))) { var timeinThisEvent = pipeLineEvent.EndTimeRelativeMSec - pipeLineEvent.StartTimeRelativeMSec; if (((timeinThisEvent / slowestTime) * 100) > 50) { slowestTime = timeinThisEvent; slowestPipelineEvent = pipeLineEvent; } } var timeInSlowestEvent = slowestPipelineEvent.EndTimeRelativeMSec - slowestPipelineEvent.StartTimeRelativeMSec; var requestExecutionTime = request.EndTimeRelativeMSec - request.StartTimeRelativeMSec; if (timeInSlowestEvent > 0 && requestExecutionTime > 500) { if (((timeInSlowestEvent / requestExecutionTime) * 100) < 50) { // So this is the scenario where the default set of events that we are tracking // do not have any delay. Lets do our best and see if we can atleast // populate the StartTime, EndTime IisPipelineEvent unKnownPipeLineEvent = CheckForDelayInUnknownEvents(request, timeInSlowestEvent); if (unKnownPipeLineEvent != null) { slowestPipelineEvent = unKnownPipeLineEvent; } } } return(slowestPipelineEvent); }
static private IisRequest GenerateFakeIISRequest(Guid contextId, TraceEvent traceEvent, double timeStamp = 0) { IisRequest request = new IisRequest() { ContextId = contextId }; if (traceEvent != null) { request.StartTimeRelativeMSec = traceEvent.TimeStampRelativeMSec; } else { request.StartTimeRelativeMSec = timeStamp; } request.Method = "UNKNOWN"; request.Path = "Unkwown (GENERAL_REQUEST_START event not captured in trace)"; return(request); }
public static IisPipelineEvent CheckForDelayInUnknownEvents(IisRequest request, double timeInSlowestEvent) { double slowestTimeInThisEvent = 0; int position = 0; var pipelineEventsArray = request.PipelineEvents.ToArray(); for (int i = 0; i < pipelineEventsArray.Length - 1; i++) { if (pipelineEventsArray[i].EndTimeRelativeMSec != 0) { var timeDiff = pipelineEventsArray[i + 1].StartTimeRelativeMSec - pipelineEventsArray[i].EndTimeRelativeMSec; if (slowestTimeInThisEvent < timeDiff) { slowestTimeInThisEvent = timeDiff; position = i; } } } IisPipelineEvent unknownEvent = null; if ((slowestTimeInThisEvent / timeInSlowestEvent) > 1.5) { if (position > 0) { unknownEvent = new IisPipelineEvent(); unknownEvent.Name = "UNKNOWN"; unknownEvent.StartThreadId = pipelineEventsArray[position].EndThreadId; unknownEvent.EndThreadId = pipelineEventsArray[position + 1].StartThreadId; unknownEvent.StartTimeRelativeMSec = pipelineEventsArray[position].EndTimeRelativeMSec; unknownEvent.EndTimeRelativeMSec = pipelineEventsArray[position + 1].StartTimeRelativeMSec; unknownEvent.ProcessId = pipelineEventsArray[position + 1].ProcessId; } } return(unknownEvent); }
public static Dictionary <Guid, IisRequest> ParseIISEvents(TraceLog dataFile, int processId, Dictionary <Guid, IisRequest> iisRequests) { g_processId = processId; var dispatcher = dataFile.Events.GetSource(); dispatcher.Dynamic.AddCallbackForProviderEvent("Microsoft-Windows-ASPNET", "Request/Send", delegate(TraceEvent data) { if (iisRequests.TryGetValue(data.ActivityID, out IisRequest iisRequest)) { if (data.RelatedActivityID != Guid.Empty) { iisRequest.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) { if (traceEvent.ProcessID != g_processId) { return; } 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) { if (traceEvent.ProcessID != g_processId) { return; } int childRequestRecurseLevel = 0; if (childRequests.ContainsKey(traceEvent.ContextId)) { if (childRequests.TryGetValue(traceEvent.ContextId, out childRequestRecurseLevel)) { childRequests[traceEvent.ContextId] = childRequestRecurseLevel - 1; } } }; iis.IISGeneralGeneralRequestStart += delegate(W3GeneralStartNewRequest traceEvent) { if (traceEvent.ProcessID != g_processId) { return; } IisRequest req = new IisRequest() { ContextId = traceEvent.ContextId, StartTimeRelativeMSec = traceEvent.TimeStampRelativeMSec, Method = traceEvent.RequestVerb, Path = traceEvent.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 (!iisRequests.ContainsKey(traceEvent.ContextId)) { iisRequests.Add(traceEvent.ContextId, req); } startcount++; }; iis.IISGeneralGeneralRequestEnd += delegate(W3GeneralEndNewRequest traceEvent) { if (traceEvent.ProcessID != g_processId) { return; } IisRequest request; if (iisRequests.TryGetValue(traceEvent.ContextId, out request)) { request.EndTimeRelativeMSec = traceEvent.TimeStampRelativeMSec; request.BytesReceived = traceEvent.BytesReceived; request.BytesSent = traceEvent.BytesSent; request.StatusCode = traceEvent.HttpStatus; request.SubStatusCode = traceEvent.HttpSubStatus; } endcount++; }; iis.IISRequestNotificationPreBeginRequestStart += delegate(IISRequestNotificationPreBeginStart traceEvent) { if (traceEvent.ProcessID != g_processId) { return; } IisRequest request; if (!iisRequests.TryGetValue(traceEvent.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(traceEvent.ContextId, traceEvent); iisRequests.Add(traceEvent.ContextId, request); } int childRequestRecurseLevel = GetChildEventRecurseLevel(traceEvent.ContextId, childRequests); var iisPrebeginModuleEvent = new IisPrebeginModuleEvent() { Name = traceEvent.ModuleName, StartTimeRelativeMSec = traceEvent.TimeStampRelativeMSec, ProcessId = traceEvent.ProcessID, StartThreadId = traceEvent.ThreadID, ChildRequestRecurseLevel = childRequestRecurseLevel }; request.PipelineEvents.Add(iisPrebeginModuleEvent); }; iis.IISRequestNotificationPreBeginRequestEnd += delegate(IISRequestNotificationPreBeginEnd traceEvent) { if (traceEvent.ProcessID != g_processId) { return; } IisRequest request; int childRequestRecurseLevel = GetChildEventRecurseLevel(traceEvent.ContextId, childRequests); if (iisRequests.TryGetValue(traceEvent.ContextId, out request)) { var module = request.PipelineEvents.FirstOrDefault(m => m.Name == traceEvent.ModuleName && m.ChildRequestRecurseLevel == childRequestRecurseLevel); if (module != null) { module.EndTimeRelativeMSec = traceEvent.TimeStampRelativeMSec; module.EndThreadId = traceEvent.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 traceEvent) { if (traceEvent.ProcessID != g_processId) { return; } IisRequest request; if (!iisRequests.TryGetValue(traceEvent.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(traceEvent.ContextId, traceEvent); iisRequests.Add(traceEvent.ContextId, request); } int childRequestRecurseLevel = GetChildEventRecurseLevel(traceEvent.ContextId, childRequests); var iisModuleEvent = new IisModuleEvent() { Name = traceEvent.ModuleName, StartTimeRelativeMSec = traceEvent.TimeStampRelativeMSec, ProcessId = traceEvent.ProcessID, StartThreadId = traceEvent.ThreadID, fIsPostNotification = traceEvent.fIsPostNotification, Notification = (RequestNotification)traceEvent.Notification, ChildRequestRecurseLevel = childRequestRecurseLevel, foundEndEvent = false }; request.PipelineEvents.Add(iisModuleEvent); }; iis.IISRequestNotificationNotifyModuleEnd += delegate(IISRequestNotificationEventsEnd traceEvent) { if (traceEvent.ProcessID != g_processId) { return; } IisRequest request; int childRequestRecurseLevel = GetChildEventRecurseLevel(traceEvent.ContextId, childRequests); if (iisRequests.TryGetValue(traceEvent.ContextId, out request)) { IEnumerable <IisModuleEvent> iisModuleEvents = request.PipelineEvents.OfType <IisModuleEvent>(); var module = iisModuleEvents.FirstOrDefault(m => m.Name == traceEvent.ModuleName && m.Notification == (RequestNotification)traceEvent.Notification && m.fIsPostNotification == traceEvent.fIsPostNotificationEvent && m.ChildRequestRecurseLevel == childRequestRecurseLevel && m.foundEndEvent == false); if (module != null) { module.EndTimeRelativeMSec = traceEvent.TimeStampRelativeMSec; module.EndThreadId = traceEvent.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 traceEvent) { if (traceEvent.ProcessID != g_processId) { return; } IisRequest request; if (iisRequests.TryGetValue(traceEvent.ContextId, out request)) { request.FailureDetails = new RequestFailureDetails() { HttpReason = traceEvent.HttpReason, HttpStatus = traceEvent.HttpStatus, HttpSubStatus = traceEvent.HttpSubStatus, ModuleName = traceEvent.ModuleName, ConfigExceptionInfo = traceEvent.ConfigExceptionInfo, Notification = (RequestNotification)traceEvent.Notification, TimeStampRelativeMSec = traceEvent.TimeStampRelativeMSec }; } }; iis.IISGeneralGeneralFlushResponseStart += delegate(W3GeneralFlushResponseStart traceEvent) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISGeneralGeneralFlushResponseEnd += delegate(W3GeneralFlushResponseEnd traceEvent) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISGeneralGeneralReadEntityStart += delegate(W3GeneralReadEntityStart traceEvent) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISGeneralGeneralReadEntityEnd += delegate(W3GeneralReadEntityEnd traceEvent) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISCacheFileCacheAccessStart += delegate(W3CacheFileCacheAccessStart traceEvent) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISCacheFileCacheAccessEnd += delegate(W3CacheFileCacheAccessEnd traceEvent) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISCacheUrlCacheAccessStart += delegate(W3CacheURLCacheAccessStart traceEvent) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISCacheUrlCacheAccessEnd += delegate(W3CacheURLCacheAccessEnd traceEvent) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISFilterFilterStart += delegate(W3FilterStart traceEvent) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISFilterFilterEnd += delegate(W3FilterEnd traceEvent) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISAuthenticationAuthStart += delegate(W3AuthStart traceEvent) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISAuthenticationAuthEnd += delegate(W3AuthEnd traceEvent) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISCacheOutputCacheLookupStart += delegate(W3OutputCacheLookupStart traceEvent) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISCacheOutputCacheLookupEnd += delegate(W3OutputCacheLookupEnd traceEvent) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISCompressionDynamicCompressionStart += delegate(W3DynamicCompressionStart traceEvent) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISCompressionDynamicCompressionEnd += delegate(W3DynamicCompressionEnd traceEvent) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISCompressionStaticCompressionStart += delegate(W3StaticCompressionStart traceEvent) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISCompressionStaticCompressionEnd += delegate(W3StaticCompressionEnd traceEvent) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISFilterFilterPreprocHeadersStart += delegate(W3FilterPreprocStart traceEvent) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests); }; iis.IISFilterFilterPreprocHeadersEnd += delegate(W3FilterPreprocEnd traceEvent) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, 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 (iisRequests.TryGetValue(traceEvent.ContextId, out iisRequest)) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests, "CLRThreadPoolQueue"); } }; aspNet.AspNetReqAppDomainEnter += delegate(AspNetAppDomainEnterTraceData traceEvent) { IisRequest iisRequest; if (iisRequests.TryGetValue(traceEvent.ContextId, out iisRequest)) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests, "CLRThreadPoolQueue"); } }; aspNet.AspNetReqSessionDataBegin += delegate(AspNetAcquireSessionBeginTraceData traceEvent) { IisRequest iisRequest; if (iisRequests.TryGetValue(traceEvent.ContextId, out iisRequest)) { AddGenericStartEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests, "AspNetReqSessionData"); } }; aspNet.AspNetReqSessionDataEnd += delegate(AspNetAcquireSessionEndTraceData traceEvent) { IisRequest iisRequest; if (iisRequests.TryGetValue(traceEvent.ContextId, out iisRequest)) { AddGenericStopEventToRequest(traceEvent.ContextId, traceEvent, iisRequests, childRequests, "AspNetReqSessionData"); } }; aspNet.AspNetReqPipelineModuleEnter += delegate(AspNetPipelineModuleEnterTraceData traceEvent) { if (traceEvent.ProcessID != g_processId) { return; } IisRequest request; if (iisRequests.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) { if (traceEvent.ProcessID != g_processId) { return; } IisRequest request; if (iisRequests.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 (iisRequests.TryGetValue(contextGuid, out iisRequest)) { AddGenericStartEventToRequest(contextGuid, traceEvent, iisRequests, 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 (iisRequests.TryGetValue(contextGuid, out iisRequest)) { AddGenericStopEventToRequest(contextGuid, traceEvent, iisRequests, childRequests); } } } }); dispatcher.Process(); // manual fixup for incomplete requests foreach (var request in iisRequests.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 pipleline start events which don't have a pipeline // stop event next to it. If we find, we just set their end to EndTimeRelativeMSec var incompletePipeLineEvents = request.PipelineEvents.Where(m => m.EndTimeRelativeMSec == 0); // not setting incompleteEvent.EndThreadId as this is incorrectly adding a hyperlink for requests // requests that are stuck in the session state module foreach (var incompleteEvent in incompletePipeLineEvents) { incompleteEvent.EndTimeRelativeMSec = dataFile.SessionEndTimeRelativeMSec; } } return(iisRequests); }