X Tutup
The Wayback Machine - https://web.archive.org/web/20201101143956/https://github.com/PowerShell/PowerShell/pull/13673
Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PowerShell profiler #13673

Draft
wants to merge 16 commits into
base: master
from
Draft

PowerShell profiler #13673

wants to merge 16 commits into from

Conversation

@iSazonov
Copy link
Collaborator

@iSazonov iSazonov commented Sep 22, 2020

PR Summary

Simple demo:

$sb = { $a = 3; if ($a -eq 3) { Write-Host ">$a" } else { Sleep 5 } Sleep 2 }
Measure-Script -ScriptBlock $sb
Measure-Script { function f { param($p = @{ a=$(Sleep 2;1)}) $p }; f }

PR Context

Based on Jason's approach lzybkr@d620bb4

  • Perf event (with minimal data) issues for every sequence point while measure runs

    • the event is marked as start and recursive event
  • Perf events are implemented in ProfilerEventSource class

  • Perf event contains

    • Timestamp
    • script block Id
    • parent script block Id (allow to keep track of the call stack)
    • runspace Id (allow to support jobs, ForEach -Parallel and many runspaces)
  • Now perf events are issued for default parameter evaluations (and more).

  • Limitations:

    • no Stop events
    • we do not explicitly see parameter binding operations, pipeline/cmdlet phases (Begin, Process, End)
  • Rundown event (with full meta data) issues for every sequence point after measure stops

  • Rundown event issues for every script block (not used in Measure-Script now)

  • Rundown event issues are implemented in ProfilerRundownEventSource class

  • Scriptblock cache was simplifed and now it caches CompiledScriptBlock-s

    • previously ScriptBlock object was cached but never used directly - before use we always cloned them and a comment says it is because we should avoid a reference to SessionStateInternal and memory leak.
    • the ScriptBlock cloning was really new ScriptBlock(CompiledScriptBlock)
    • so it makes sense to cache ScriptBlock objects, now we cache CompiledScriptBlock-s and create script blocks with new ScriptBlock(CompiledScriptBlock) without extra cloning.
    • removed a lock if script block is already compiled
  • To collect meta data we use ConcurrentDictionary CompiledScriptBlock.s_cachedScripts cache

  • To initialize the cache at measure start we use CompiledScriptBlock cache and then register every script block at creation time.

  • This allow us to have meta data for every script block.

  • Exception (an edge case) - long running script blocks already removed from CompiledScriptBlock cache.

  • Measure-Script cmdlet is implemented for demo use

  • ProfileEventRecord is used for typed output

  • Duration is broken in common

    • now duration is calculated as substruction two Start event timestamps
    • we haven't Stop events
    • so it is not work for last event

For discussion

Since we have only start timestamps we haven't stop timestamp for last sequence point. Perhaps we need a script block stop event and maybe start event.

Here a question is should we think about measuring pipelines, parameter bindings.

Also can we be compatible with PerfView tool?

PR Checklist

@iSazonov iSazonov mentioned this pull request Sep 22, 2020
2 of 14 tasks complete
@nohwnd
Copy link

@nohwnd nohwnd commented Sep 23, 2020

Looks good. I am not able to build it on Windows. Cleaned up and ran bootstrap script, but I still see
"C:\Projects\powershell\src\System.Management.Automation\engine\Subsystem\SubsystemInfo.cs(304,29): error CS0103: The name 'SubsystemStrings' does not exist in the current context [C:\Projects\powershell\src\System.Management.Automation\System.Management.Automation.csproj]" any advice?

@iSazonov
Copy link
Collaborator Author

@iSazonov iSazonov commented Sep 23, 2020

@lzybkr I added a scriptblock rundown event per #13589 (comment)
For the example $sb = { Get-Process pwsh* | % -Begin { Sleep 2} -Process { $_.Name } } we get 3 such events:

  • for the full scriptblock
  • for { Sleep 2}
  • for { $_.Name }
    We get events for nested scriptblocks. Do we need its?

Also I found how use ConditionalWeakTable. With it I get strange scriptblocks without sequence points.

@nohwnd It is very strange. It seems your local fork is broken. At least you could do ipmo ./Build.psm1 -Force and Start-PSBuild -Clean. Then I could remove local directory tree and load from GitHub again.

Copy link
Member

@lzybkr lzybkr left a comment

This looks pretty good, I especially like relying on the rundown event internally which means it should work well out of process as well.

[NonEvent]
internal void WriteRundownEvents()
{
foreach (var pair in CompiledScriptBlockData.GetCompiledScriptBlockTable())

This comment has been minimized.

@lzybkr

lzybkr Sep 23, 2020
Member

This isn't ideal as it may write out much more than necessary, but it may also miss some script blocks that are hit while profiling.

The ConditionalWeakTable does not prevent garbage collection, so if, e.g. we cleared the script block cache while profiling, scripts that had exited while profiling would be missing the rundown data.

This comment has been minimized.

@iSazonov

iSazonov Sep 24, 2020
Author Collaborator

  • Yes, it is not ideal. For the simple test I shared I see a size of the table is 86. In big application (Pester) it could be 500 or 1000 - it does not look so critical bad.
  • I tried ConcurrentDictionary instead of ConditionalWeakTable. You can revert last commit and see the case. My idea was to register scriptblock in Compile() method so that we was independent from scriptblock cache. It is more predictable but we need to clean the buffer somehow.
    • for ConcurrentDictionary case I cleaned up the buffer at EventSource disable time. It is not ideal too. It duplicates the scriptblock cache.
    • for ConditionalWeakTable we could temporary stop to clean up the scriptblock cache until we disable EventSource.

This comment has been minimized.

@lzybkr

lzybkr Sep 24, 2020
Member

The profiler could take a snapshot of the script block cache when starting. This snapshot would hold references so it wouldn't matter if the script block cache was cleared.

Then, script block creation would also add to that snapshot.

This way, the memory is owned by the profiler and can be cleared when profiling is disabled allowing garbage collection to do it's thing.

This comment has been minimized.

@iSazonov

iSazonov Sep 25, 2020
Author Collaborator

The snapshot does not help in a scenario with long live scriptblocks. Such scriptblocks could be tracked with ConditionalWeakTable. We could avoid ConditionalWeakTable if there is a way to identify running scripts.

This comment has been minimized.

@lzybkr

lzybkr Sep 25, 2020
Member

I think you could gather by breaking every runspace (I think the debugger can do this) and walking the stack of each runspace.

But I think it would be simpler to just take a snapshot of the scriptblock cache. IIRC, the only scriptblock that doesn't end up in the cache comes from the command line.

Regardless, ConditionalWeakTable is likely not what you want because you don't control keeping the data you need alive.

This comment has been minimized.

@iSazonov

iSazonov Sep 28, 2020
Author Collaborator

Now I replace ConditionalWeakTable with ConcurrentDictionary, add an initialization from scriptblock cache, simplify the scriptblock cache ( we cached ScriptBlock but never use it directly - clone before use but Clone() method actually
copies a reference to CompiledScriptBlock so we can cache directly CompiledScriptBlock)ю

This comment has been minimized.

@IISResetMe

IISResetMe Sep 28, 2020
Contributor

@lzybkr Do you have any ideas for how to track the "origin" or "root dispatcher" for the individual script blocks as described above? It would make it so much easier to consume the events in any tool/context.

This comment has been minimized.

@iSazonov

iSazonov Sep 28, 2020
Author Collaborator

Jason said Debugger has a callstack. I am looking...

This comment has been minimized.

@iSazonov

iSazonov Sep 29, 2020
Author Collaborator

I added Runspace and parent scriptblock Ids in perf event. I am still not sure it works as expected - need a review.
Also I added a typed output and set Start Opcode on perf event - need to find how to issue Stop event.
Duration is now broken in common - we need to take into account Runspaces.

This comment has been minimized.

@iSazonov

iSazonov Sep 30, 2020
Author Collaborator

I pulled some commits and it's ready for further discussion. The PR description has also been updated.

var compiledScriptBlock = pair.Key;
ScriptBlockRundown(compiledScriptBlock.Id, compiledScriptBlock.Ast.Body.Extent.Text);

if (compiledScriptBlock.SequencePoints is null)

This comment has been minimized.

@lzybkr

lzybkr Sep 23, 2020
Member

Based on my comment and the code it guards, I think the point was to avoid needing tests like this elsewhere.

This comment has been minimized.

@iSazonov

iSazonov Sep 24, 2020
Author Collaborator

But I catch NRE here :-( Should we consider this as separate bug and open a tracking issue?

This comment has been minimized.

@lzybkr

lzybkr Sep 24, 2020
Member

I suppose it's not exactly a bug if it's not causing other issues now - so your call.

{
var extent = compiledScriptBlockData.SequencePoints[profileDate.SequencePointPosition];

PSObject result = new PSObject();

This comment has been minimized.

@lzybkr

lzybkr Sep 23, 2020
Member

This should be a real object as I'd expect we'll construct a ton of them.

This comment has been minimized.

@iSazonov

iSazonov Sep 25, 2020
Author Collaborator

My thoughts about Measure-Script cmdlet is we could have some cases:

  • with -OutFile parameter write real objects to standard file like ewtx
  • with -Raw switch write real objects to the pipeline
  • by default write specific psobjects so that users can investigate simple scripts and to get nice formatted output on console (like @IISResetMe demo below #13673 (comment))

This comment has been minimized.

@lzybkr

lzybkr Sep 25, 2020
Member

You should always prefer a real object if you know the properties you'll need, especially if you might be writing out thousands of said objects.

This comment has been minimized.

@iSazonov

iSazonov Sep 29, 2020
Author Collaborator

Typed output implemented.

@lzybkr
Copy link
Member

@lzybkr lzybkr commented Sep 23, 2020

@iSazonov - I'm not sure what it would take to get support in perfview. I believe it support languages like JavaScript so I'd imagine PowerShell could do something similar. Maybe @brianrob (current maintainer of perfview) can offer some suggestions.

@lzybkr
Copy link
Member

@lzybkr lzybkr commented Sep 23, 2020

@IISResetMe (who adapted my SDK sample into the module PSProfiler) might also want to take a look.

@brianrob
Copy link

@brianrob brianrob commented Sep 23, 2020

What kind of support in PerfView are you looking for?

@IISResetMe
Copy link
Contributor

@IISResetMe IISResetMe commented Sep 24, 2020

The output format is slightly awkward, but beyond that I could definitely work with this:

$sb = { Get-Process pwsh* | % -Begin { Sleep 2} -Process { $_.Name } }
Measure-Script -ScriptBlock $sb |
  Where ExtentText -NotLike '[{}]' |
  Group {$_.Extent.StartOffset},{$_.Extent.EndOffset} |
  Select Count,
         @{N='TotalTime';E={$t = [timespan]::Zero;$_.Group.ForEach({$t=$t+$_.Duration});$t}},
         @{N='Code';E={"{0,$($_.Group[0].Extent.StartColumnNumber - $sb.Ast.Extent.StartColumnNumber)}{1}"-f$null,$_.Group[0].ExtentText}}
Count TotalTime        Code
----- ---------        ----
    1 00:00:00.0025372   Get-Process pwsh* | % -Begin { Sleep 2} -Process { $_.Name }
    1 00:00:02.0061880                                  Sleep 2
    3 00:00:00.0001681                                                      $_.Name

Will take a closer look at the code tomorrow

@lzybkr
Copy link
Member

@lzybkr lzybkr commented Sep 24, 2020

@brianrob - I think PowerShell maintainers and some module authors would appreciate hybrid PowerShell/C# call stacks from CPU sampling.

This PR is generating minimal events (analogous to an IP but no stack) while profiling via an EventSource (using instrumentation in the generated code which is interpreted and lazily jit compiled). After turning off profiling, a rundown event provider is generating metadata to recover the source line and function details from the minimal events.

@iSazonov may have other ideas how PowerShell users might use perfview or wpa.

@iSazonov
Copy link
Collaborator Author

@iSazonov iSazonov commented Sep 24, 2020

What kind of support in PerfView are you looking for?

My thoughts is very simple. Since users will can able to collect PowerShell performance events out-of-process they need tools to analyze the data.

  • Developer scenarios. Visual Studio and VS Code PowerShell extension/PES could expose a profiler somewhat.
  • Hosting scenarios. Azure, server scripts, PowerShell hosting applications - users will collect PowerShell performance events and they need a standalone tool to analyze them.
    I would like to avoid creating a separate new tool as it is a lot of work. It would be great to use a well known and reliable PerfView (and maybe WPA).
    As end user I'd expect PerfView will show me a callstack tree like for .Net.
    I guess we need to issue events like .Net does. I guess we should emulate such start/stop events. I hope it is possible and simplify PerfView adoption.

@lzybkr Could you please point me where we could issue a stop event for scriptblock/sequence point?

@brianrob What do you think? Is it possible? Could you tell me how we should create events correctly for PerfView?

@nohwnd
Copy link

@nohwnd nohwnd commented Sep 24, 2020

Tried running this over a Pester test and it failed. Here is a mini repro: _scriptBlock is null when you hit the @() token in Measure-Script { function f { param($p = @()) $p }; f }

PS C:\Projects\powershell> $error[0] | fl -Force *

PSMessageDetails      :
Exception             : System.NullReferenceException: Object reference not set to an instance of an object.
                           at System.Management.Automation.Language.FunctionContext.UpdatePositionNoBreak(Int32 pos) in C:\Projects\powershell\src\System.Management.Automation\engine\parser\Compiler.cs:line 815
                           at System.Management.Automation.Language.FunctionContext.UpdatePosition(Int32 pos) in C:\Projects\powershell\src\System.Management.Automation\engine\parser\Compiler.cs:line 826
                           at lambda_method39(Closure , FunctionContext )
                           at System.Management.Automation.Language.Compiler.GetExpressionValue(ExpressionAst expressionAst, Boolean isTrustedInput, ExecutionContext context, SessionStateInternal sessionStateInternal,
                        IDictionary usingValues, Func`2& lambda, IScriptExtent[]& sequencePoints, Type& localsTupleType) in C:\Projects\powershell\src\System.Management.Automation\engine\parser\Compiler.cs:line 2179
                           at System.Management.Automation.Language.Compiler.DefaultValueExpressionWrapper.GetValue(ExecutionContext context, SessionStateInternal sessionStateInternal, IDictionary usingValues) in
                        C:\Projects\powershell\src\System.Management.Automation\engine\parser\Compiler.cs:line 1958
                           at System.Management.Automation.ScriptParameterBinder.GetDefaultScriptParameterValue(RuntimeDefinedParameter parameter, IDictionary implicitUsingParameters) in
                        C:\Projects\powershell\src\System.Management.Automation\engine\scriptparameterbinder.cs:line 149
                           at System.Management.Automation.ParameterBinderController.BindUnboundScriptParameterWithDefaultValue(MergedCompiledCommandParameter parameter) in
                        C:\Projects\powershell\src\System.Management.Automation\engine\ParameterBinderController.cs:line 1279
                           at System.Management.Automation.ParameterBinderController.BindUnboundScriptParameters() in C:\Projects\powershell\src\System.Management.Automation\engine\ParameterBinderController.cs:line 1242
                           at System.Management.Automation.ScriptParameterBinderController.BindCommandLineParameters(Collection`1 arguments) in
                        C:\Projects\powershell\src\System.Management.Automation\engine\scriptparameterbindercontroller.cs:line 99
                           at System.Management.Automation.DlrScriptCommandProcessor.EnterScope() in C:\Projects\powershell\src\System.Management.Automation\engine\ScriptCommandProcessor.cs:line 609
                           at System.Management.Automation.DlrScriptCommandProcessor.RunClause(Action`1 clause, Object dollarUnderbar, Object inputToProcess) in
                        C:\Projects\powershell\src\System.Management.Automation\engine\ScriptCommandProcessor.cs:line 501
TargetObject          :
CategoryInfo          : NotSpecified: (:) [f], NullReferenceException
FullyQualifiedErrorId : System.NullReferenceException,f
ErrorDetails          :
InvocationInfo        : System.Management.Automation.InvocationInfo
ScriptStackTrace      : at <ScriptBlock>, <No file>: line 1
                        at <ScriptBlock>, <No file>: line 1
PipelineIterationInfo : {}
@rjmholt
Copy link
Member

@rjmholt rjmholt commented Sep 24, 2020

@nohwnd for reference your original error was because the resource strings needed to be rebuilt. Start-PSBuild -Clean usually fixes that

@brianrob
Copy link

@brianrob brianrob commented Sep 24, 2020

I just skimmed the PR to try and understand how things work. I would like to make sure I understand how things work, and then have a few questions.

My understanding is that there is a desire to enable profiling in two ways:

  1. Via Measure-ScriptBlock, which would result in the use of EventSource and EventListener to generate results inside of the pwsh process, and display them to the console.
  2. Via ETW or other platform loggers by enabling the events via an out-of-process mechanism. This profiling would be fully controlled via the platform logger and would occur regardless of whether or not Measure-ScriptBlock is invoked.

There are a couple of pieces of functionality that I can see being implemented in PerfView. Of course, I'm open to feedback and other ideas as well:

  1. The ability to determine how long a particular scriptblock/cmdlet takes to execute. This can be done via the Events view as long as there are start/stop events that get emitted on either side of the execution. I'm not sure if these exist today, but I don't see them in this PR.
  2. Views where we attribute computing resources (CPU, memory allocations, etc.) to their script/cmdlet-based stack.

For the computing resource based views, we'd need to understand a couple of things:

  1. How to construct the stack.
  2. How to resolve symbols (if necessary).

Right now, PerfView has functionality that does this for jitted code that is compiled on-the-fly by the .NET runtime. This is done by using rundown events to provide function memory ranges and symbols. There's mention of both interpreted and jitted code here. For interpreted code, we'd need events that would allow us to build the appropriate stack. You could imagine doing this with start/stop events that wrap the "scope" of each frame. This would work as long as collection started before the invocation. If it is started in the middle of an invocation, we'd see broken stacks, but these may still be valuable depending on how much movement up and down the stack there is. For jitted code, are we talking about using the .NET runtime's JIT, or something else?

@iSazonov
Copy link
Collaborator Author

@iSazonov iSazonov commented Sep 24, 2020

@brianrob

My understanding is that there is a desire to enable profiling in two ways:

Yes.

There are a couple of pieces of functionality that I can see being implemented in PerfView. Of course, I'm open to feedback and other ideas as well:

  1. The ability to determine how long a particular scriptblock/cmdlet takes to execute. This can be done via the Events view as long as there are start/stop events that get emitted on either side of the execution. I'm not sure if these exist today, but I don't see them in this PR.
  2. Views where we attribute computing resources (CPU, memory allocations, etc.) to their script/cmdlet-based stack.

Yes for 1. Currently we issue an event with number 1 as start event but without the "start" label.
From your comment I see that we need (1) both start and stop events, (2) a way to track a script stack.
I hope @lzybkr give the cue where we could issue stop events and how we could track script stack.

For 2. I am not sure we can utilize resource tracking because scripts are executed in runspaces (you can think that it is special thread) and there could be some parallel runspaces so we cannot directly know which runspace is consuming resources- we should track a long correlation sequence scriptblock-runspace-.Net thread. It looks too complex for me. Although it is possible... It is my answer on "For jitted code, are we talking about using the .NET runtime's JIT, or something else?" too - it would interesting to have the correlated views (script - JIT) but looks too complex for the first step PR.

@iSazonov
Copy link
Collaborator Author

@iSazonov iSazonov commented Sep 24, 2020

Tried running this over a Pester test and it failed. Here is a mini repro: _scriptBlock is null when you hit the @() token in Measure-Script { function f { param($p = @()) $p }; f }

NRE is in "ProfilerEventSource.LogInstance.SequencePoint(_scriptBlock.Id, pos);" (in UpdatePositionNoBreak()) because "_scriptBlock" is null. I wonder why... It seems a "bug" mentioned above.

@lzybkr
Copy link
Member

@lzybkr lzybkr commented Sep 25, 2020

@brianrob PowerShell does use the .NET jit via LINQ expression trees. PowerShell forked the DLR to use the interpreter which will jit compile code if it executes enough times.

@iSazonov
Copy link
Collaborator Author

@iSazonov iSazonov commented Sep 26, 2020

Measure-Script { function f { param($p = @()) $p }; f }

We catch NRE on "@()". It is parameter binding. This is evaluated out of current scripblock. There is created pseudo functioncontext with sequence points but without a reference to current scriptblock.

  • If we skip issuing the perf event in the case we never see parameter bindings in the profiler. If we issue the perf event there will be no link to a scriptblock and we will not know the context when analyzing.
  • In the example we call GetDefaultScriptParameterValue(). So it is called everywhere where parameter binding exists (funcrions/scriptblocks).
  • another code path - GetExpressionValue(). This is used in many places and we may not see it in the profiler too.

Since these code paths is complex, with static methods without scriptblock parameter it is a huge work to fix all them.
One workaround I can think is to track functioncontext in interpreter. Is it possible/make sense?

@iSazonov iSazonov force-pushed the iSazonov:core-ps-profiler branch from a3829cc to 669996a Oct 1, 2020
@msftbot msftbot bot added the Waiting on Author label Oct 4, 2020
@nohwnd
Copy link

@nohwnd nohwnd commented Oct 6, 2020

I just tried it out with some real scripts and my module that summarizes the results and it works nicely. I am preparing a presentation about this for PWSH24. Is it reasonable to expect that this will be available in a month or two? (even if behind an experimental flag)

@iSazonov
Copy link
Collaborator Author

@iSazonov iSazonov commented Oct 7, 2020

@nohwnd Thanks!

Do you ask about 7.1 or 7.2? I am sure we will get this in 7.2 Preview1 as experimental.
As for 7.1 we need to ask MSFT team. I think it is low risk because we don't change functional code. But the code will be changed without a doubt because we need to add stop events. Currently Measure-Script cmdlet is demo only. I could make it more useful, move to Utility module and mark as experimental feature.

@msftbot msftbot bot removed the Waiting on Author label Oct 7, 2020
@nohwnd
Copy link

@nohwnd nohwnd commented Oct 7, 2020

7.2 is okay. I just wanted to know when roughly this will be ready to try, because I have only a version that works with PowerShell 5, by doing some "reflection" magic, but nothing for the PowerShell core versions.

@iSazonov
Copy link
Collaborator Author

@iSazonov iSazonov commented Oct 7, 2020

@nohwnd .Net 5.0 will be released in November. PowerShell 7.1 will be released in the time too. Then the holidays come. I'd expect 7.2 Preview1 in January unless MSFT team forked earlier.

@msftbot msftbot bot added the Waiting on Author label Oct 10, 2020
@msftbot msftbot bot added the Stale label Oct 31, 2020
@msftbot
Copy link

@msftbot msftbot bot commented Oct 31, 2020

This pull request has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 15 days. It will be closed if no further activity occurs within 10 days of this comment.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked issues

Successfully merging this pull request may close these issues.

None yet

6 participants
You can’t perform that action at this time.
X Tutup