View the http redirect and response message from an external authentication provider using ETW


Recently I had to troubleshoot messages that were being sent from an web application hosted on IIS to an external authentication provider. The logs from the application wasn’t something closer to the metal and wasn’t really providing all the details. I really wanted something like fiddler for the webserver. I could have a ran network traces to troubleshoot the issue but the problem was it wasn’t happening consistently. It was sporadic. I knew there would be ETW traces that would have this information. The IIS web logs don’t capture this information.

Here is a example of the SAML authentication process

500px-SAML

In the application I was working with, IIS was the relying party and the user was to be authenticated with Identity Provider.

I wanted to troubleshoot the “AuthnRequest” and “Auth Resp” from and to the IIS. This can be applied to any external authentication like credit card authentication.

I fired my favorite tool Perfview and captured all the IIS traces along with other defaults. I wasn’t really interested in the .NET Code.

Here is the command line for Perfview to the IIS Providers

If for some reason that does not work.  You could always use the additional providers in Perfview and add these providers which are IIS and HTTP providers.

I let perfview do its job and then stopped the trace when there was an issue.

Here are the ETW events that capture the SAML Request that was sent from IIS to the IDP

Event Name

  1. IIS_Trace/IISGeneral/GENERAL_RESPONSE_HEADERS
  2. Microsoft-Windows-IIS/EventID(47)
  3. IIS_Trace/IISGeneral/GENERAL_RESPONSE_ENTITY_BUFFER
  4. Microsoft-Windows-IIS/EventID(49)
  5. IIS_Trace/IISGeneral/GENERAL_REQUEST_HEADERS

SamlRequest

Here are the ETW events that capture the SAML Response that was being posted from the IDP to the IIS

  1. IIS_Trace/IISGeneral/GENERAL_REQUEST_ENTITY
  2. Microsoft-Windows-IIS/EventID(51)

samlresponse

With this I was able to troubleshoot message that was being sent and received to the IIS.

Use Eventsource to get the duration of a Start Stop of Custom ETW events


The EventSource library provides an option to get duration of Custom ETW start and stop events and when used with Perfview we could leverage this to stop tracing when the duration is more than what we expect.

What it is for example ,there could an external API call the application makes that has to be traced with the start and when it finishes then the stop of the event is called. Ideally we would have a ability to view the duration of these events similar to ASP.NET calls.  The EventSource Library along with Perfview provides this ability to view the duration between the start and stop events.

Here is a code sample with CustomEvent

And here is the output from Perfview with the duration.

StartStopETW

How often we want to capture trace when the performance of our custom event goes down to figure out what went wrong. This is very much possible with this.

Here is the command

PerfView /StopOnEtwEvent:*CustomEvent//Start;TriggerMSec=2000 collect

This would record the ETW events on a flight recorder mode and would stop when the CustomEvent took more than 2 seconds. This is one of the features I really like because it is a great asset to DevOps to see when the issue arises.

Here is an example of Perfview Stop reason that shows why perfview stopped which clearly  indicates when the duration of event took more than 2000 milliseconds.

PerfviewStopReason

There is a bug in perfview that would not record Stop triggered events. I have reported this and I hope this would be fixed in the next public release.

The source code for these samples are here

https://github.com/naveensrinivasan/ETWSamples

Log dynamic Custom objects in ETW using EventSource


With the latest release of EventSource we could create dynamic events without having to create class that inherits from EventSource. This is will be not be good for Performance.

Using these methods we could either log Anonymous objects or Classes that have the EventData Attribute applied to it. The caveat is that these objects public properties alone will be serialized. These properties have to be of native types like string,int,datetime, guid , IEnumerable. If you don’t want a property to be serialized you could apply the attribute EventIgnore.

The source code for this repository is in https://github.com/naveensrinivasan/ETWSamples

Here is the sample code of using  Dynamic eventsource to generate ETW traces

Here is the trace from Perfview generated using

DynamicETW

The case of slow Visual Studio startup


In this post I would use Perfview /ETW to diagnose the delayed start-up of visual studio.

To analyze the problem start-up VS within Perfview as a run command

This would launch visual studio and collect etw traces. I have also enabled CodeMarkers , which is ETW traces for Visual Studio in case if you want to trace any extensions performance.

perfview-mainAfter it completes I choose the CPU Stacks and filtered with devenv.exe process.

On the CPU window I choose call-tree tab which displays the threads.perfviewcpuviewThe most amount of time is spent on the start-up thread and that is what we want to zoom into.

groupedcall-stacksWhen I expanded it does not show the information and everything is grouped into OTHER which does not help me.

The reason for that is perfview groups call-stacks for better viewing. I cleared the “groupparts” textbox and then expanded the start-up thread.

actualcallstacksFrom the call-stacks I could make almost 42% of time is spent on Xamarin and DevExpress extensions within VS. Now I could turn them off and have a better performance.

Perfview is great tool for identifying where the time is being spent!

Measure GC Allocations and Collections using TraceEvent


In this post I will explore  how we could use TraceEvent to measure our code (even at function level) for GC Allocations and Collections.

Save this with “.linq” extension and then open in  linqpad.

Here is the TL;DR

Why would I want to know GC events on a function level? Doesn’t the PerfMon counter  provide that information on an application level? Isn’t Premature optimization root of all evil?

Yes, for most of the part Premature optimization is not necessary. And PerfMon GC counter’s would give answers for the whole application. But it is usually after we build the application and when we start running into performance issues we start looking at them.

The motivation behind this are two things Measure Early and Often for Performance and Essential Truths Everyone Should Know about Performance in a Large Managed Codebase

If you haven’t read or watched the above video please do it. It let’s us know why and how to do it.

In the above video Dustin talks about Roslyn code base and how they used Perfview to measure Roslyn code base and identify potential bottlenecks early to avoid Perf issues.

One of the key differences between managed code and native code with respect to performance is GC. If GC is working hard then your application might not be able to get the performance that you are expecting. GC is good but if we don’t know which calls allocate what amount of data then it is an issue. Especially if you have a section code that is hit very often and which requires a lot of Perf, it is good know where the allocations are coming from. It is not explicit always.

In the above video Dustin shows few examples of Roslyn code where they were able to identify subtle issues that could allocate a lot when you are trying to get the most out of the code.There is also Roslyn Heap Allocation Analyzer which looks at the code help us identify allocations which isn’t necessary. It is a cool project.

I took one of the examples from the video as a motivation to check if  I could measure and make it a utility in my toolbox to help me when I need one.

In the above example I am trying look for a word “pede” in the lorem ipsum text. The code could get it using “foreach” or using the “Any” operator. I would like to run this few times to check what are the allocations and how long does it take. I used LINQPad as a scratch pad.

Here is the result of GC Allocations of using “Any” for 500 iterations and NOT the foreach

GCAllocations

The were 118 allocations of Enumerator and 146 allocations Func. GC usually allocates 100K each time it allocates that’s what is shown in the allocation amount column.

And here is GC Allocations when using “foreach”

GCAllocationWithForEach

There are hardly any new allocations compared to the previous one.

Here is the GC Collections when using  “Any”

GCCollection

There were 18 GC Collections using Any.

Here it is using foreach  and there were 0 collections.

ZeorCollections

Here is measure it time duration results using Any

MeasureWithAny

And here it is using Foreach

MeasureWithForEach

Look ma I figured out why my ETW EventSource isn’t tracing


The EventSource class in the framework 4.5 helps in writing custom ETW tracing.

When using EventSource class built within the framework, if the order of the methods don’t match ordinal number position in the class it would fail generating ETW traces. The EventSource has dependency on the order of the methods in the class.

This code would produce a valid ETW traces

This one would fail producing any ETW Traces.

The difference between them are the order of the methods. If you notice in the failing ETW tracing class the FailedTraceEvent is Second and the FailedDetailedEvent is first which is causing the trace not to be generated. The actual exception text would

Event FailedDetailedEvent is givien event ID 1 but 2 was passed to WriteEvent.

It’s one of those quirks that I ran into when building ETW tracing.

How to troubleshoot these kind of failures?

By default these kind of failed ETW exceptions would not be raised to be handled by the client code. The reason being,in production if you enable ETW tracing and all of a sudden the application crashes would not be something that we would want.

To troubleshoot this, use ETW tracing for exceptions. Use ETW to trace custom ETW failures. How cool is this?  My choice of tool is Perfview.

may-3-2015-etw-exception

Within Perfview in the Events Window I enter Test|Ex in the filter text box which is shown in the above picture. FYI filter text box supports Regular expression. So by entering Test|Ex, I am filtering events with Test or Ex which for exceptions. With that information I could filter all the TestEvent’s and any exceptions that have been raised which shows ArgumentException.

The call-stack of the ArgumentException shows on the static contructor .cctor of  FailedEvent.

may-3-2015-exception-callstack

Get managed call-stacks in .NET for Registry access using ETW


I was recently debugging managed code which was accessing system registry implicitly because of an external dependent library.  So the first thing I asked was a Procmon log for of registry access. And then I also wanted look at the call-stacks for registry access, which Procmon does provide.

Here is a sample call-stack from Procmon for registry access. I am using linqpad as an example in this

ntoskrnl.exe    CmpCallCallBacks + 0x1c0    0xfffff80002c870d0
ntoskrnl.exe     ?? ::NNGAKEGL::`string’ + 0x4c81d    0xfffff80002c31116
ntoskrnl.exe    KiSystemServiceCopyEnd + 0x13    0xfffff800028d4853
ntdll.dll    ZwSetInformationKey + 0xa    0x779214aa
wow64.dll    wow64.dll + 0x2d252    0x7399d252
wow64.dll    wow64.dll + 0x1008f    0x7398008f
wow64.dll    wow64.dll + 0xcf87    0x7397cf87
wow64cpu.dll    TurboDispatchJumpAddressEnd + 0x24    0x7390276d
wow64.dll    wow64.dll + 0xd07e    0x7397d07e
wow64.dll    wow64.dll + 0xc549    0x7397c549
ntdll.dll    LdrpInitializeProcess + 0x17e2    0x779184c8
ntdll.dll     ?? ::FNODOBFM::`string’ + 0x2bea0    0x77917623
ntdll.dll    LdrInitializeThunk + 0xe    0x7790308e
ntdll.dll    NtOpenKey + 0x12    0x77acf9da
KernelBase.dll    OpenRegKey + 0x134    0x772f2ef3
KernelBase.dll    OpenAltSortsKey + 0x29    0x772de216
KernelBase.dll    IsValidLocale + 0x127    0x772e3271
clr.dll    clr.dll + 0xe4d5f    0x6be34d5f
clr.dll    clr.dll + 0xe4ba8    0x6be34ba8
mscorlib.ni.dll    mscorlib.ni.dll + 0x2ba2f1    0x697ba2f1
mscorlib.ni.dll    mscorlib.ni.dll + 0x2ba2c1    0x697ba2c1
mscorlib.ni.dll    mscorlib.ni.dll + 0x2b9faa    0x697b9faa
mscorlib.ni.dll    mscorlib.ni.dll + 0x2b9e0a    0x697b9e0a
mscorlib.ni.dll    mscorlib.ni.dll + 0x2ba15c    0x697ba15c
mscorlib.ni.dll    mscorlib.ni.dll + 0x2ba106    0x697ba106
mscorlib.ni.dll    mscorlib.ni.dll + 0x2b9db8    0x697b9db8
mscorlib.ni.dll    mscorlib.ni.dll + 0x2b9d34    0x697b9d34
clr.dll    clr.dll + 0x24a2a    0x6bd74a2a
clr.dll    clr.dll + 0x23153    0x6bd73153
clr.dll    clr.dll + 0x231cc    0x6bd731cc
clr.dll    clr.dll + 0x2323b    0x6bd7323b
clr.dll    clr.dll + 0x23415    0x6bd73415
clr.dll    clr.dll + 0x2355a    0x6bd7355a
clr.dll    clr.dll + 0x94844    0x6bde4844
<unknown>    0xb2420    0xb2420
mscorlib.ni.dll    mscorlib.ni.dll + 0x255870    0x69755870
mscorlib.ni.dll    mscorlib.ni.dll + 0x2557cd    0x697557cd
mscorlib.ni.dll    mscorlib.ni.dll + 0x255764    0x69755764
<unknown>    0x4e00d9    0x4e00d9
clr.dll    clr.dll + 0x21db    0x6bd521db
clr.dll    clr.dll + 0x24a2a    0x6bd74a2a
clr.dll    clr.dll + 0x24bcc    0x6bd74bcc
clr.dll    clr.dll + 0x24c01    0x6bd74c01
clr.dll    clr.dll + 0x24c21    0x6bd74c21
clr.dll    clr.dll + 0xece82    0x6be3ce82
clr.dll    clr.dll + 0xecf90    0x6be3cf90
clr.dll    clr.dll + 0xecda4    0x6be3cda4
clr.dll    clr.dll + 0xed199    0x6be3d199
clr.dll    clr.dll + 0xed09a    0x6be3d09a
clr.dll    clr.dll + 0x16af00    0x6bebaf00
mscoreei.dll    mscoreei.dll + 0x55ab    0x726355ab
mscoree.dll    mscoree.dll + 0x7f16    0x75077f16
mscoree.dll    mscoree.dll + 0x4de3    0x75074de3
ntdll.dll    __RtlUserThreadStart + 0x70    0x77ae9d72
ntdll.dll    _RtlUserThreadStart + 0x1b    0x77ae9d45

It is all unmanaged call-stacks , what I was looking for was managed call-stacks. The solution to this was ETW tracing. I use Perfmonitor from the BCL teams codeplex site for getting managed call-stacks.

Here are the steps to get managed call-stacks for registry access

PerfMonitor.exe /registry /stacks /lineNumbers start

Run the process and do the steps for registry access

PerfMonitor.exe /registry /stacks /lineNumbers stop
PerfMonitor.exe  /stacks /lineNumbers print

The above should produce a xml file which is by default named as PerfMonitorOutput.print.xml

And here is the managed call-stacks for registry access.

<Event MSec=  “3449.0880” PID=”3356″ PName= “LINQPad” TID=”4536″ EventName=”RegistryOpen” Status=”0x00000000″ KeyHandle=”0x00000000″ ElapsedTime=”0″ KeyName=”\Registry\Machine\System\CurrentControlSet\Control\Nls\Locale\Alternate Sorts” Index=”0″ InitialTime=”1/3/1601 1:11:43 PM”>
<StackTrace>
<CodeAddress Address=”0xfffff80002c22003″ FullMethodName=”_NULL_IMPORT_DESCRIPTOR” ModuleName=”ntoskrnl”/>
<CodeAddress Address=”0xfffff80002bb5d3b” FullMethodName=”$$VProc_ImageExportDirectory” ModuleName=”ntoskrnl”/>
<CodeAddress Address=”0xfffff800028d4853″ FullMethodName=”KiDeliverApc” ModuleName=”ntoskrnl”/>
<CodeAddress Address=”0x77920e0a” FullMethodName=”ZwOpenKeyEx” ModuleName=”ntdll”/>
<CodeAddress Address=”0x7399d1f1″ ModuleName=”wow64″/>
<CodeAddress Address=”0x7398008f” ModuleName=”wow64″/>
<CodeAddress Address=”0x7397cf87″ ModuleName=”wow64″/>
<CodeAddress Address=”0x7390276d” ModuleName=”wow64cpu”/>
<CodeAddress Address=”0x7397d07e” ModuleName=”wow64″/>
<CodeAddress Address=”0x7397c549″ ModuleName=”wow64″/>
<CodeAddress Address=”0x779184c8″ FullMethodName=”LdrpInitializeProcess” ModuleName=”ntdll”/>
<CodeAddress Address=”0x77917623″ FullMethodName=” ?? ::FNODOBFM::`string&apos;” ModuleName=”ntdll”/>
<CodeAddress Address=”0x7790308e” FullMethodName=”LdrInitializeThunk” ModuleName=”ntdll”/>
<CodeAddress Address=”0x77acf9da” FullMethodName=”NtOpenKey” ModuleName=”ntdll”/>
<CodeAddress Address=”0x772f2ef3″ ModuleName=”KernelBase”/>
<CodeAddress Address=”0x772de216″ ModuleName=”KernelBase”/>
<CodeAddress Address=”0x772e3264″ ModuleName=”KernelBase”/>
<CodeAddress Address=”0x6be34d5f” ModuleName=”clr”/>
<CodeAddress Address=”0x6be34ba8″ ModuleName=”clr”/>
<CodeAddress Address=”0x697ba2f1″ FullMethodName=”System.Globalization.CultureData.InitCultureData()” ModuleName=”mscorlib”/>
<CodeAddress Address=”0x697ba2c1″ FullMethodName=”System.Globalization.CultureData.CreateCultureData(class System.String,bool)” ModuleName=”mscorlib”/>
<CodeAddress Address=”0x697b9faa” FullMethodName=”System.Globalization.CultureData.GetCultureData(class System.String,bool)” ModuleName=”mscorlib”/>
<CodeAddress Address=”0x697b9e0a” FullMethodName=”System.Globalization.CultureInfo..ctor(class System.String,bool)” ModuleName=”mscorlib”/>
<CodeAddress Address=”0x697ba15c” FullMethodName=”System.Globalization.CultureInfo.GetCultureByName(class System.String,bool)” ModuleName=”mscorlib”/>
<CodeAddress Address=”0x697ba106″ FullMethodName=”System.Globalization.CultureInfo.InitUserDefaultCulture()” ModuleName=”mscorlib”/>
<CodeAddress Address=”0x697b9db8″ FullMethodName=”System.Globalization.CultureInfo.Init()” ModuleName=”mscorlib”/>
<CodeAddress Address=”0x697b9d34″ FullMethodName=”System.Globalization.CultureInfo..cctor()” ModuleName=”mscorlib”/>
<CodeAddress Address=”0x6bd74a2a” ModuleName=”clr”/>
<CodeAddress Address=”0x6bd73153″ ModuleName=”clr”/>
<CodeAddress Address=”0x6bd731cc” ModuleName=”clr”/>
<CodeAddress Address=”0x6bd7323b” ModuleName=”clr”/>
<CodeAddress Address=”0x6bd73415″ ModuleName=”clr”/>
<CodeAddress Address=”0x6bd7355a” ModuleName=”clr”/>
<CodeAddress Address=”0x6bde4844″ ModuleName=”clr”/>
<CodeAddress Address=”0x122420″/>
<CodeAddress Address=”0x69755870″ FullMethodName=”System.Version.TryParseVersion(class System.String,value class VersionResult&amp;)” ModuleName=”mscorlib”/>
<CodeAddress Address=”0x697557cd” FullMethodName=”System.Version.Parse(class System.String)” ModuleName=”mscorlib”/>
<CodeAddress Address=”0x69755764″ FullMethodName=”System.Version..ctor(class System.String)” ModuleName=”mscorlib”/>
<CodeAddress Address=”0x1e00d9″ FullMethodName=”LINQPad.Loader.Main(class System.String[])” ModuleName=”LINQPad”/>
<CodeAddress Address=”0x6bd521db” ModuleName=”clr”/>
<CodeAddress Address=”0x6bd74a2a” ModuleName=”clr”/>
<CodeAddress Address=”0x6bd74bcc” ModuleName=”clr”/>
<CodeAddress Address=”0x6bd74c01″ ModuleName=”clr”/>
<CodeAddress Address=”0x6bd74c21″ ModuleName=”clr”/>
<CodeAddress Address=”0x6be3ce82″ ModuleName=”clr”/>
<CodeAddress Address=”0x6be3cf90″ ModuleName=”clr”/>
<CodeAddress Address=”0x6be3cda4″ ModuleName=”clr”/>
<CodeAddress Address=”0x6be3d199″ ModuleName=”clr”/>
<CodeAddress Address=”0x6be3d09a” ModuleName=”clr”/>
<CodeAddress Address=”0x6bebaf00″ ModuleName=”clr”/>
<CodeAddress Address=”0x726355ab” ModuleName=”mscoreei”/>
<CodeAddress Address=”0x75077f16″ ModuleName=”mscoree”/>
<CodeAddress Address=”0x75074de3″ ModuleName=”mscoree”/>
<CodeAddress Address=”0x77ae9d72″ FullMethodName=”__RtlUserThreadStart” ModuleName=”ntdll”/>
<CodeAddress Address=”0x77ae9d45″ FullMethodName=”_RtlUserThreadStart” ModuleName=”ntdll”/>
</StackTrace>
</Event>

Here I was  able to get the managed as well as native call-stacks for registry access by keyname.  And here is my list of posts on ETW