Powershell v2 Trace Cmdlets Step 2 Im intrigued enough to explore

As I have been getting more familiar with the family of Trace cmdlets I have found a few key steps to getting my head around them.  For the quick, high level overview, check out my first post, Powershell (v2) - Trace Cmdlets (Step 1: What The Heck Are These?).  Now that you are caught up with the general what, lets scratch the surface a little more.  This post will focus on figuring out what tracesources are and how to effectively use them with the Trace-Command cmdlet.

In that first post I mentioned this,

You need to be specific with what you put in the -Name parameter (its required with Trace-Command). If you put -Name * it will run in a seemingly endless fashion because you are tying into virtually every TraceSource on your system. Explore the TraceSources first with Trace-Source.

If youve actually doing this you will notice, depending on what you have set up on your system, there are a lot of potential tracesources.  On my machine (a Windows 7 Enterprise machine with lots of software installed) I come up with almost 190 different listings:

PS > (Get-TraceSource).count
189

Using the same technique on a clean install of version 3 with my home machine (Windows 7 Enterprise SP 1) shows 30 tracesources.  So, environments will vary.  Nonetheless, any default installation of Powershell should have some tracesources.

Figuring out the unique tracesources for a given expression

Testing every one of these manually to get an idea of what Im doing seems like a tedious and rather laborious task Id prefer not do manually if I can help it.  In my mind, tracesources are bit of a black box.  In other words, I only know that they exist and have to figure out what each one does.  The notion of mapping out a black box by inference (something I learned from blind SQL injection) seems appropriate here.  How might I go about connection which tracesources tell me what?  In the spirit of all things Powershell, I will automate the process some to shorten the learning curve.

My first stab at this was to loop through all tracesources for a given expression with the Trace-Command cmdlet.  Now, I know Im putting the cart before the horse: the whole point of the post is how to figure out what each tracesource does.  Well, the only way we can do that is by using each one in Trace-Command and mapping the resulting output to each tracesource.  Since I am not a Microsoft team member nor privy to the source for these objects I have to built my own framework...and this seems like a viable way to do it.  It looks like this:

foreach($tracesource in (Get-Tracesource | Select Name)) {Write-Output "$(_ * 80)`n$($tracesource.name)`n$(_ * 80)`n"; Trace-Command -Name $tracesource.Name -Expression {dir *.txt} -PSHost}

This is a bit of a compact command, so, Ill unpack it some.  I grab the name property of all tracesources,

foreach($tracesource in (Get-Tracesource | Select Name))

then, pass them to Trace-Commands -Name parameter

Trace-Command -Name $tracesource.Name

with the aliased Get-ChildItem cmdlet (dir)

-Expression {dir *.txt}

and return all results to the shell.

-PSHost

Some of the other code is to pretify output.

Write-Output "$(_ * 80)`n$($tracesource.name)`n$(_ * 80)`n"

When I run this, as you should on your machine, I get a lot of non-hits, but, some do turn up positive.  With the way the command is written each tracesources output will be shown below a short "header" as displayed below for demonstration (its pretty ugly below so I shrunk it a little to fit more realistically as you would see it on your console):

________________________________________________________________________________
SingleShell
________________________________________________________________________________

________________________________________________________________________________
MshSnapinLoadUnload
________________________________________________________________________________

________________________________________________________________________________
MshConsoleInfo
________________________________________________________________________________

________________________________________________________________________________
PSSnapInInfo
________________________________________________________________________________

DEBUG: PSSnapInInfo Information: 0 : Property Enter property
PSSnapInInfo.get_LogPipelineExecutionDetails():LogPipelineExecutionDetails
DEBUG: PSSnapInInfo Information: 0 : Property Leave property PSSnapInInfo.get_LogPipelineExecutionDetails()

The list, as I noted earlier, can get pretty long.  And, when the output starts to run (some of which can be quite extensive depending on the expression--or command--you enter) some traces will end up being several hundred lines long.  Run this on your system and see what you get.  In this case, I just did a simple command, but, I was able to identify that the expression, dir *.txt, causes the following tracesources to fire:

• PSSnapInInfo
• SessionState
• SessionStateScope
• ETS
• TypeConversion
• CommandDiscovery
• State
• PSCredential
• PSDriveInfo
• CmdletProviderClass
• CmdletProviderContext
• FileSystemProvider
• DriveCommandAPI
• LocationGlobber
• PathResolution
• ProviderCommandAPI
• WildcardPattern
• PathInfo
• CommandFactory
• History
• CommandMetadata
• CompiledCommandParameter
• MemberResolution
• InternalCommand
• CommandProcessor
• Cmdlet
• PipelineProcessor
• ParameterBinderBase
• ParameterBinding
• ReflectionParameterBinder
• ParameterBinderController
• CommandParameterInternal
• CmdletProviderIntrinsics
• ProviderInstrinsics

Now, thats quite a list.  Thirty four by my count.  All of this activity stirred up by an eight character command.  This shows pretty clearly that tracesources can give you a lot of information.  So, its imperative that you be selective in what you want to pay attention to (and add to your -Name argument collection), otherwise, you will be sorting through tons of output.

Pay attention to the order of tracesources

One thing I want to suggest, to help differentiate between the way I am approach tracesources here and how you would use them in normal practice deals with the order in which they are listed.  When I run the initial command

Get-Tracesource | Select Name

I am unable to sort the resulting collection without specifying the  Name parameter.  This is to be expected as the default sort would fall to the Options property (which is typically None).  Yet, in playing with sort, as you get familiar with them you will more than likely want to leave the order alone as its seems to indicate the order in which tracesources were added to the Powershell framework.  In other words, the default order of tracesources, as they appear when you simply type in Get-TraceSource, tells you what sources were added first (and what came later).  

How can I tell?  Look at the names for the first five tracesources

Get-Tracesource | Select Name -First 5

returns

• SingleShell
• MshSnapinLoadUnload
• MshConsoleInfo
• PSSnapInInfo
• PSSnapInReader

If you are familiar with Powershells history a little you know that Powershell was originally called Monad and the prefix Msh was used before the product got rebranded back in 2006.  Noting the prefixing shift (which never reverts back to Msh after tracesource number three on my v2 box) its pretty clear these were done early on...presumably around early 2006.  Also, when viewing my v3 box the majority of these early tracesources seem to disappear.  Since I have the SDK on my work machine (but not home) its hard to say whether they reappear in v3 or not; more research to follow.  Needless to say, the order in which they show up using the untweaked cmdlet tells you a story about how Powershell matured in terms of features...at least with regards to tracesources that it.  Understanding the importance of not sorting tracesources is only a sidenote, but, an interesting one.

Dont use -Name *

The last key to getting a handle on tracesources, aside from experimenting a bit, is to do a little compare and contrast with 1) the output of Trace-Command as I have broken it down by tracesource, and, 2) the output when you simply specify tracesources and let it run without the differentiation.  For instance, using my command above, you will get each tracesource, one by one, with headers to indicate what output results from the specific tracesource.  When you simply run them as a single command it returns all of the results in their "natural" order, i.e., as the engine processes them in real time.  

My initial approach was very artificial and its intent was to get as granular as the cmdlets would allow.  This approach is the exact opposite, and, the intent here is to demonstrate less about the individual tracesources and more  their composite results.  When you run this, the first place to start is with the parameter -Name *. By hooking into the full set you will how the moving pieces work together as a single unit, each mechanism firing in an orderly fashion as dictated by the flow of the engine.  So, using our command from above, run this,

Trace-Command -Name * -Expression {dir *.txt} -PSHost

Note the -Name parameter now takes a wildcard (* = all) and will basically give you everything it sees.  When I run this I get to about  9500 lines of debug output before I cancel the command (with no idea of how much longer it would run).  Seriously?!  Whos going to read all that.  You can try it if you like, but, Ive done it just to test and can vouch...this is more information than most any normal person wants to deal with.  Not to mention it takes about 10 minutes to run.

Whats weird is that my initial atomized, tracesource by tracesource approach, didnt return nearly this much output.  It yielded maybe 1,000 lines (and thats being liberal).  What we seem to have happen when you use * with -Name is a bit of a recursive loop.  As it runs it starts feeding off its own output and no longer returning accurate insight into the original command, but, now, a mixture of the original command and its own processing.  Not quite what I had hoped for.  My main point here is to underscore the importance of knowing exactly what you want to test for and zeroing in on these specific sources.

Break it down in small bite-sized chunks

Having looked microscopically at individual source output and macroscopically at global output, the next steps (and the last Ill touch on here) are to begin taking results you found useful and running them in small combinations.  For instance, I know from my initial run that PSSnapInInfo and SessionState both gave me hits with my test expression.  So, I try the scientific approach to get a better understanding of what falls where with these three commands (results at the end of the post),

Trace-Command -Name PSSnapInInfo,SessionState -Expression {dir *.txt} -PSHost
Trace-Command -Name PSSnapInInfo -Expression {dir *.txt} -PSHost
Trace-Command -Name SessionState -Expression {dir *.txt} -PSHost

From running this combination of commands I discover that  PSSnapInInfo  runs before SessionState.  As a result I know, when I start really using the tracesources what fires and when.  Now, obviously, some commands will appear in multiple places and may not be as straightforward as this simple example.  The main idea here is to look at your commands, your results, and, your tracesources and be able to connect which one does what.  When they are jumbled together into a single blob of yellow and black, its pretty hard to delineate results.  This way you can explicitly see what happens, when and begin to trace out the mechanics of the internals events.

Results of three commands

Here is the output of the three variations: 1) with both PSSnapInInfo and SessionState 2) with only PSSnapInInfo and 3) with only SessionState.  Just to save you some time, notice in the first five lines for Command 1 below that DEBUG: is followed by the Tracesource for each command as it fires.  This saves you from having to worry about trying to come up with some system of injecting the Tracesource in the composite trace.  The data is already there.  Now, to see if I can figure out some color coding to make it more obvious...as someone said,  la Wireshark or Procmon.  Unfortuately, as far as I can tell, the default manner in which it runs does not allow anything like.  Hopefully I can find some hook to do this, but, fear doing so may interfere with the output as it will start injecting console manipulation.

Command 1

PS C: estingpowershell> Trace-Command -Name PSSnapInInfo,SessionState -Expression {dir *.txt} -PSHost
DEBUG: PSSnapInInfo Information: 0 : Property Enter property
PSSnapInInfo.get_LogPipelineExecutionDetails():LogPipelineExecutionDetails
DEBUG: PSSnapInInfo Information: 0 : Property Leave property PSSnapInInfo.get_LogPipelineExecutionDetails()
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell*.txt
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell*.txt
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell*.txt
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell*.txt
DEBUG: SessionState Information: 0 : WriteLine Drive found in scope 0
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell
DEBUG: SessionState Information: 0 : WriteLine Drive found in scope 0
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine Drive found in scope 0
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell
DEBUG: SessionState Information: 0 : WriteLine Drive found in scope 0
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell
DEBUG: SessionState Information: 0 : WriteLine Drive found in scope 0
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell


Command 2 

PS C: estingpowershell> Trace-Command -Name PSSnapInInfo -Expression {dir *.txt} -PSHost
DEBUG: PSSnapInInfo Information: 0 : Property Enter property
PSSnapInInfo.get_LogPipelineExecutionDetails():LogPipelineExecutionDetails
DEBUG: PSSnapInInfo Information: 0 : Property Leave property PSSnapInInfo.get_LogPipelineExecutionDetails()


Command 3 

PS C: estingpowershell> Trace-Command -Name SessionState -Expression {dir *.txt} -PSHost
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell*.txt
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell*.txt
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell*.txt
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell*.txt
DEBUG: SessionState Information: 0 : WriteLine Drive found in scope 0
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell
DEBUG: SessionState Information: 0 : WriteLine Drive found in scope 0
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine Drive found in scope 0
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell
DEBUG: SessionState Information: 0 : WriteLine Drive found in scope 0
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell
DEBUG: SessionState Information: 0 : WriteLine Drive found in scope 0
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetContainerProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Enter
SessionStateInternal.GetProviderInstance():Microsoft.PowerShell.CoreFileSystem
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetProviderInstance()
DEBUG: SessionState Information: 0 : Method Leave SessionStateInternal.GetContainerProviderInstance()
DEBUG: SessionState Information: 0 : WriteLine result = C: estingpowershell

Uncle...

Well, thats enough for tonight...or, I guess I should say, this morning.  Next, varying up the expressions to learn how to see what triggers which sources and connect the Powershell objects with their traces.