Performance: reduce overhead of computing full path for items from globs

[lifengl]

Based on investigating performance trace to load Roslyn.sln, I looked into the time spent in CPS's UpdateSnapshotCoreAsync, almost 30% thread time in this function is to calculate FullPath of project items.

Because those items are coming from globs, I wonder the path is naturally normalized, and we can reduce some of the overhead here.

Name                                                                 	                                        Inc %	  Inc	           Inc Ct
microsoft.build.ni!FileUtilities.GetFullPath                        	                       28.1	          405.567	  592
+ microsoft.build.ni!FileUtilities.NormalizePath                     	                       19.3	           277.811	  267
+ system.ni!System.Text.RegularExpressions.Regex.Match(System.String)	 5.9	           84.554	  209
+ mscorlib.ni!System.IO.Path.Combine(System.String, System.String)   	 1.5	           22.189	   62

[lifengl]

Include @cdmihai & @davkean to the thread. The rule snapshots logic is a slow portion of the code after the project evaluation phase.

[cdmihai]

Is this evaluation, or design time builds? Could you please also post more of the backtraces to see where GetFullPath is called from (preferably up to Project), or upload the perfiew trace?

[lifengl]

This happens after the project evaluation inside VS. During that phase, we extra information from msbuild evaluation results based on rules defined in the project system. The overall time is much smaller than the evaluation time, so I would consider this lower priority than improving the evaluation time.

On the other side, we start to look beyond the evaluation time to see what we can do to make loading a project faster, and this turns out to be one major block we want to make more efficient during the critical path in the loading phase. I will share the Roslyn.sln loading ETW trace with you (or anyone can take this trace with PerfView).

To look into this time: Open the thread time window in perfView, (select devenv, and remove grouParts setting) and find UpdateSnapshotCoreAsync stack, and open it in the Callees window (this will aggregate time spent in this method). Use context menu to drill into it.

After that, you can see the time spent inside this function, and the top cost is inside FileUtilities.GetFullPath.

The caller of this method:

Name | Inc % | Inc | Inc Ct
-- | -- | -- | --
microsoft.build.ni!FileUtilities.GetFullPath | 28.1 | 405.567 | 592
+ microsoft.build.ni!Microsoft.Build.Shared.FileUtilities+ItemSpecModifiers.GetItemSpecModifier(System.String, System.String, System.String, System.String, System.String ByRef) | 28.1 | 405.567 | 592
+ microsoft.build.ni!Microsoft.Build.Shared.FileUtilities+ItemSpecModifiers.GetItemSpecModifier(System.String, System.String, System.String, System.String, System.String ByRef) | 22.2 | 319.395 | 454
\|+ microsoft.build.ni!Microsoft.Build.Execution.ProjectItemInstance+TaskItem.GetBuiltInMetadataEscaped(System.String) | 22.1 | 318.429 | 445
\|\|+ microsoft.build.ni!Microsoft.Build.Execution.ProjectItemInstance+TaskItem.GetMetadataEscaped(System.String) | 22.1 | 318.429 | 445
\|\| + microsoft.build.ni!Microsoft.Build.Execution.ProjectItemInstance+TaskItem.GetMetadata(System.String) | 22.1 | 318.429 | 445
\|\|  + microsoft.visualstudio.projectsystem.implementation.ni!ProjectEvaluationSubscriptionService.BuildItemsSnapshot | 22.1 | 318.429 | 445
\|+ microsoft.build.ni!Microsoft.Build.Shared.FileUtilities+ItemSpecModifiers.GetItemSpecModifier(System.String, System.String, System.String, System.String, System.String ByRef) | 0.1 | 0.966 | 9
\| + microsoft.build.ni!Microsoft.Build.Execution.ProjectItemInstance+TaskItem.GetBuiltInMetadataEscaped(System.String) | 0.1 | 0.966 | 9
\|  + microsoft.build.ni!Microsoft.Build.Execution.ProjectItemInstance+TaskItem.GetMetadataEscaped(System.String) | 0.1 | 0.966 | 9
\|   + microsoft.build.ni!Microsoft.Build.Execution.ProjectItemInstance+TaskItem.GetMetadata(System.String) | 0.1 | 0.966 | 9
\|    + microsoft.visualstudio.projectsystem.implementation.ni!ProjectEvaluationSubscriptionService.BuildItemsSnapshot | 0.1 | 0.966 | 9
+ microsoft.build.ni!Microsoft.Build.Execution.ProjectItemInstance+TaskItem.GetBuiltInMetadataEscaped(System.String) | 6.0 | 86.172 | 138
+ microsoft.build.ni!Microsoft.Build.Execution.ProjectItemInstance+TaskItem.GetMetadataEscaped(System.String) | 6.0 | 86.172 | 138
+ microsoft.build.ni!Microsoft.Build.Execution.ProjectItemInstance+TaskItem.GetMetadata(System.String) | 6.0 | 86.172 | 138
+ microsoft.visualstudio.projectsystem.implementation!ProjectInstanceItemProperties.GetEvaluatedPropertyValue | 6.0 | 86.172 | 138

[rokonec]

@ladipro Has this been addressed in your latest glob optimization? If yes please close this issue.

[ladipro]

@rokonec I don't think this was addressed in the glob optimization changes. We should take a closer look at this.

[rokonec]

@ladipro please check it out and decide if this is still something we shall invest into in close future? Currently it is P1 so we shall at least consider to lower priority here.

[ladipro]

@rokonec this still seems to be actionable, I can see FileUtilities.GetFullPath taking a significant amount of time in traces. A concrete work item here would be to compare our P/Invoke implementation under FEATURE_LEGACY_GETFULLPATH with the regular Path.GetFullPath. The comments suggest that this was done to work around perf issues with pre-4.6.2 NetFx implementation, so that should be moot now. This would result in a perf improvement or at least code cleanup.

Next step would be to see if on this particular code path GetFullPath is really required or if it can be omitted / cached / optimized.

I lean towards keeping it as P1 and tackling it in one of the upcoming iterations.