search

dotnet / runtime

.NET is a cross-platform runtime for cloud, mobile, desktop, and IoT apps.
https://docs.microsoft.com/dotnet/core/
MIT License
15.27k stars 4.73k forks source link

Using -comObject in pwsh7 is extremly slow compaired to powershell 5.1 #36944

Closed skippernl closed 4 years ago

skippernl commented 4 years ago

Hi I was pointed in this direction by the pwsh7 team.

I have a powershell script that takes the config of a firewall and creates an excel document from it. On powershell 5.1 this takes about 5 minutes depending on the size of the config. On powershell 7 this takes more that 2 hours. The main function that slows down is writing to excel $Excel = New-Object -ComObject Excel.Application $Excel.Visible = $false $workbook = $excel.Workbooks.Add() $TocSheet = $workbook.Worksheets.Item(1) $MainSheet = $workbook.Worksheets.Add() $TocSheet.Name = "ToC"

Commenting the firstline out (The new-object) Makes the script run on pwsh7 in 49 seconds to 2 minutes and 35 seconds in powershell 5.

As the main function of this script is converting a config file to excel tabs it is higly depending on the -ComObject.

Full script can be found here https://github.com/skippernl/Fortigate2Excel

Dotnet-GitSync-Bot commented 4 years ago

I couldn't figure out the best area label to add to this issue. Please help me learn by adding exactly one area label.

janvorli commented 4 years ago

cc: @AaronRobinsonMSFT

AaronRobinsonMSFT commented 4 years ago

@skippernl Thanks for reaching out. It would be helpful if you could collect a ETW trace using PerfView. This will allow us to understand your scenario better and observe precisely what aspect of the script is taking so long. Two hours would result in a large file, but we can probably get away with collecting data for no more than 30 to 60 seconds. A trace for pwsh5.1 would also be helpful, but we can start with pwsh7.

AaronRobinsonMSFT commented 4 years ago

/cc @jkoritzinsky @elinor-fung

skippernl commented 4 years ago

Will try that tomorrow.

Thanx

Op ma 25 mei 2020 18:50 schreef Aaron Robinson notifications@github.com:

@skippernl https://github.com/skippernl Thanks for reaching out. It would be helpful if you could collect a ETW trace using PerfView https://github.com/microsoft/perfview. This will allow us to understand your scenario better and observe precisely what aspect of the script is taking so long. Two hours would result in a large file, but we can probably get away with collecting data for no more than 30 to 60 seconds. A trace for pwsh5.1 would also be helpful, but we can start with pwsh7.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/dotnet/runtime/issues/36944#issuecomment-633650251, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABIWZN5MHCIHLBTFTSTDHZDRTKOUVANCNFSM4NIZ24BA .

skippernl commented 4 years ago

Ran both. https://1drv.ms/u/s!AikuTJDzUoogh8Y6FT2qYZfu43LWIw?e=Z3Bjz8 [image: afbeelding.png]

You should be able to download the files from the onedrive location. If needed I can add a test file for a fortigate config file so you can test on your machine.

The configuration is just the interfaces and a routing table.

Skippernl

Op ma 25 mei 2020 om 18:50 schreef Aaron Robinson <notifications@github.com

:

@skippernl https://github.com/skippernl Thanks for reaching out. It would be helpful if you could collect a ETW trace using PerfView https://github.com/microsoft/perfview. This will allow us to understand your scenario better and observe precisely what aspect of the script is taking so long. Two hours would result in a large file, but we can probably get away with collecting data for no more than 30 to 60 seconds. A trace for pwsh5.1 would also be helpful, but we can start with pwsh7.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/dotnet/runtime/issues/36944#issuecomment-633650251, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABIWZN5MHCIHLBTFTSTDHZDRTKOUVANCNFSM4NIZ24BA .

-- Xander

AaronRobinsonMSFT commented 4 years ago

@skippernl Thank you much for the collected traces. The traces identified the issue very quickly. Unfortunately, this appears to be an issue in PowerShell. The slow down is due to code paths in System.Management.Automation and from the trace appears to be because the code path when run on .NET Core falls back to expression tree evaluation instead of directly making the COM calls. I am not a PowerShell user nor have any experience with it as a developer so don't know why this code path is being taken, but it is because of this expression tree usage that the call is so expensive.

We can leave this issue open here since the runtime may need to respond or help the PowerShell run time. However, we need someone from PowerShell to interpret the trace on why this is occurring. Can you tag the person you were talking to?

skippernl commented 4 years ago

Sure,

Steve Lee pointed me in you're direction.

SkipperNL

Op di 26 mei 2020 19:42 schreef Aaron Robinson notifications@github.com:

@skippernl https://github.com/skippernl Thank you much for the collected traces. The traces identified the issue very quickly. Unfortunately, this appears to be an issue in PowerShell. The slow down is due to code paths in System.Management.Automation https://docs.microsoft.com/dotnet/api/system.management.automation and from the trace appears to be because the code path when run on .NET Core falls back to expression tree evaluation instead of directly making the COM calls. I am not a PowerShell user nor have any experience with it as a developer so don't know why this code path is being taken, but it is because of this expression tree usage that the call is so expensive.

We can leave this issue open here since the runtime may need to respond or help the PowerShell run time. However, we need someone from PowerShell to interpret the trace on why this is occurring. Can you tag the person you were talking to?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/dotnet/runtime/issues/36944#issuecomment-634173364, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABIWZN5MGEOTJJTW5Q45YTDRTP5R3ANCNFSM4NIZ24BA .

skippernl commented 4 years ago

@SteveL-MSFT Can you or a college chime in?

skippernl commented 4 years ago

Hi any progress on this issue? If needed I can produce a small config file for testing.

daxian-dbw commented 4 years ago

@skippernl I'm from the PowerShell team and is investigating this issue. A small config file would absolutely be helpful. Can you please confirm the repro step is .\Fortigate2Excel.ps1 -fortiGateConfig "<your-small-config-file>" on both PS7 and PS5.1?

daxian-dbw commented 4 years ago

The slow down is due to code paths in System.Management.Automation and from the trace appears to be because the code path when run on .NET Core falls back to expression tree evaluation instead of directly making the COM calls.

@AaronRobinsonMSFT Thanks for the investigation and the insight. The differences between PS5.1 (on .NET) and PS7 (on .NET Core 3.1) is due to not having ComBinder in the latter. Windows PowerShell basically copied the .NET code in the namespace Microsoft.CSharp.RuntimeBinder.ComInterop to help dealing with COM interop in PowerShell. You will find the following pattern used throughout binders.cs:

public override DynamicMetaObject FallbackXXXX(...)
{
    ....
    // Check if this is a COM Object
    DynamicMetaObject result;
    if (ComInterop.ComBinder.TryBindGetMember(this, target, out result))
    {
        result = new DynamicMetaObject(WrapGetMemberInTry(result.Expression), result.Restrictions);
        return result.WriteToDebugLog(this);
    }
    ...
}

In PS7, ComBinder.TryBindGetMember is stub code that always returns false. Without the ComBinder, PowerShell handles COM interop through IDispatch.Invoke, and thus needs to get metadata through calls like ITypeInfo.GetDocumentation and ITypeInfo.GetFuncDesc, which took more than 76% of the CPU time as shown in the PS7 trace.

@AaronRobinsonMSFT Last time I checked, the ComBinder didn't work in .NET Core, but that was over half a year ago. It seems dynamic keyword still doesn't work for COM object in .NET Core 3.1, but will it be back in .NET 5?

AaronRobinsonMSFT commented 4 years ago

The differences between PS5.1 (on .NET) and PS7 (on .NET Core 3.1) is due to not having ComBinder in the latter.

@daxian-dbw Yay. I was hoping this was the issue. Yep, the support for dynamic and COM was added in https://github.com/dotnet/runtime/pull/33060. This shipped in .NET 5.0 Preview 2. Yes, this is a .NET 5.0 feature and there are no plans to port it to .NET Core 3.1. Will PS7 be able to upgrade to .NET 5.0 when it is relased?

/cc @elinor-fung

daxian-dbw commented 4 years ago

Fantastic! Our master branch is current targeting .NET 5 preview 5, so I can go ahead enable the COM binder code in our code base. Are there a lot changes to the code in the namespace Microsoft.CSharp.RuntimeBinder.ComInterop? I guess I probably will have to refresh the code we copied years ago.

AaronRobinsonMSFT commented 4 years ago

Are there a lot changes to the code in the namespace Microsoft.CSharp.RuntimeBinder.ComInterop? I guess I probably will have to refresh the code we copied years ago.

That is a great question for @elinor-fung. If memory serves she was able to optimize a few code paths.

daxian-dbw commented 4 years ago

I opened https://github.com/PowerShell/PowerShell/issues/12842 to track the work.

AaronRobinsonMSFT commented 4 years ago

@skippernl and @daxian-dbw I am going to close this issue based on https://github.com/PowerShell/PowerShell/issues/12842. Please do let us know if there is any issues with the support/performance and we will do what we can to get back to the PS5.1 numbers.

elinor-fung commented 4 years ago

I think the most interesting change was ripping out a bunch of the code that created a dynamic assembly to convert different types to pointers and switching to Unsafe.AsPointer. Beyond that, it was mostly general cleanup and making it fit nicely in the runtime repo. In that PR #33060, the switch to Unsafe.AsPointer was in commit 1bf8c6a3.

daxian-dbw commented 4 years ago

@elinor-fung Thanks for the additional info! I will refresh the code in our repo and do necessary refactoring as we did last time years back.

daxian-dbw commented 4 years ago

@skippernl I'm working on refreshing the ComInterop code that PowerShell uses and I would like to test it using a real world script. Can you please share one or more fortigate configuration file so that I can test my work using Fortigate2Excel.ps1? Thank you in advance!

daxian-dbw commented 4 years ago

@skippernl Ha, never mind, I just found you already shared a sample config file at https://onedrive.live.com/?authkey=%21ABU9qmGX7uNy1iM&id=208A52F3904C2E29%21123706&cid=208A52F3904C2E29. Appreciate it!

skippernl commented 4 years ago

Let me know if you need more. Wil be waiting for the results.

Thanx for the update

Op wo 29 jul. 2020 17:04 schreef Dongbo Wang notifications@github.com:

@skippernl https://github.com/skippernl Ha, never mind, I just found you already shared a sample config file at https://onedrive.live.com/?authkey=%21ABU9qmGX7uNy1iM&id=208A52F3904C2E29%21123706&cid=208A52F3904C2E29. Appreciate it!

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/dotnet/runtime/issues/36944#issuecomment-665719586, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABIWZN6AL6AK2K4JA5K2Z4LR6A3ANANCNFSM4NIZ24BA .