Add profiler under a flag #2765

smera · 2017-12-01T01:01:18Z

Adding an evaluation profiler, enabled via a command line flag (/profileevaluation:file).
When turned on, it generates a report after the build finishes. See documentation/evaluation-profiling.md for more details

dnfclas · 2017-12-01T01:01:22Z

@smera,
Thanks for your contribution.
To ensure that the project team has proper rights to use your work, please complete the Contribution License Agreement at https://cla2.dotnetfoundation.org.

It will cover your contributions to all .NET Foundation-managed open source projects.
Thanks,
.NET Foundation Pull Request Bot #Resolved

dnfclas · 2017-12-01T01:09:30Z

@smera, thanks for signing the contribution license agreement. We will now validate the agreement and then the pull request.

Thanks, .NET Foundation Pull Request Bot #Resolved

cdmihai · 2017-12-01T18:52:53Z

src/MSBuild/Resources/Strings.resx

@@ -1,6 +1,66 @@
 <?xml version="1.0" encoding="utf-8"?>
 <root>
+  <!-- 


Can you please revert all the spurious changes that VS did to this file? :)
I edit the resx files from vscode to make sure VS does not dirty them up. #Resolved

sure #Resolved

AndyGerlicher · 2017-12-01T20:36:10Z

src/MSBuild/XMake.cs

+        /// <summary>
+        /// Generates a markdown file on disk with the result of profiling the evaluation
+        /// </summary>
+        private static void GenerateProfilerReport(ProfilerLogger profilerLogger)


Should this logic go in the ProfileLogger? On shutdown or something? #Resolved

I intendedly kept the file saving part outside of the profiler logger because I was seeing the logger more as a collector of data. But I can move the saving logic inside. #Resolved

AndyGerlicher · 2017-12-01T20:45:24Z

This is looking really good!!

Minor thing, I like that xmake knows how to parse the params to turn on the profiling and create the logger, but I don't think writing the file should be there. That should happen on shutdown like a normal file logger would. So the logger is just something that happens to listen for that data and writes it out in the default format it knows about.

@KirillOsenkov seems like we should just add this to the binary logger file. Would be easy to do, and could even have a nice visualization someday? And we're changing the format anyway seems no harm in adding that. So in that case maybe /prof by itself would turn the feature on but not attach the ProfileLogger? And then the binary logger would pick them up and write them to the file? So you would build msbuild /bl /prof. And later you could msbuild msbuild.binlog /prof:file.md to get the default experience. I'm also curious what perf impact this has if we should force /prof on when /bl is specified similar to other things. But we'd need some numbers to know that. My guess is it's not that bad though, esp. when you're doing a debug build.

@mmitche any idea what's wrong with our CI? None of the jobs are reporting status apparently. Not sure how to debug that without links to them. #Resolved

AndyGerlicher · 2017-12-01T20:55:10Z

src/Framework/IProjectElement.cs

+
+
+        /// <summary>
+        /// The outer xml markup of the xml element associated with this project element/>


remove /> #Resolved

Will do #Resolved

AndyGerlicher · 2017-12-01T21:02:58Z

FYI for the binary logger:

https://github.com/Microsoft/msbuild/blob/e122c897f6c7fe10ac07b01c19110d8b03bfd818/src/Build/Logging/BinaryLogger/BuildEventArgsReader.cs#L205-L216

and

https://github.com/Microsoft/msbuild/blob/237db30c73369928c3e7cc563d1c18eb0a114ef8/src/Build/Logging/BinaryLogger/BuildEventArgsWriter.cs#L127-L132

Need to update the version as well since this is (another) breaking change. #Resolved

mmitche · 2017-12-01T21:04:37Z

They look like they are reporting now. #Resolved

mmitche · 2017-12-01T21:04:59Z

@AndyGerlicher ci2 was offline for a bit while a server move was happening. #Resolved

KirillOsenkov · 2017-12-01T23:33:11Z

I've filed #2768 to track this.

Would indeed be nice to serialize this info to the .binlog if available. @smera if you have cycles would be awesome if you could get to it (perhaps as part of a separate PR). I can come down and explain how binlog serialization works, it's not hard. We can maybe even write it together. #Resolved

cdmihai · 2017-12-01T23:58:42Z

src/Framework.UnitTests/Microsoft.Build.Framework.UnitTests.csproj

@@ -63,6 +71,9 @@
  <ItemGroup>
    <Service Include="{82A7F48D-3B50-4B1E-B82E-3ADA8210C358}" />
  </ItemGroup>
+  <ItemGroup>
+    <Reference Include="System.Xml" />


Please transform this into a nuget dependency instead (project.json file next to this csproj). Mixing nuget and these leads to confusing dependency resolution. #Resolved

Ah, that may explain some warnings I was seeing. Will change, thanks! #Resolved

cdmihai · 2017-12-02T00:43:47Z

src/Framework.UnitTests/ProjectFinishedEventArgs_Tests.cs

+        /// </summary>
+        [MemberData(nameof(GetProfilerResults))]
+        [Theory]
+        public void ProfilerResultRoundTrip(ProfilerResult profilerResult)


Shouldn't this test go in a new ProjectEvaluationFinishedEventArgs_Tests class instead? #Resolved

Yeap, good catch #Resolved

cdmihai · 2017-12-02T01:00:48Z

src/Shared/NodePacketTranslator.cs

+                    IDictionary<EvaluationLocation, ProfiledLocation> profiledLocations = new Dictionary<EvaluationLocation, ProfiledLocation>();
+                    if (translator.Mode == TranslationDirection.WriteToStream)
+                    {
+                        profiledLocations = profilerResult.ProfiledLocations.ToDictionary(kv => kv.Key, kv => kv.Value);


This ToDictionary might take some time / memory. How bad would it get if you made ProfilerResult.ProfiledLocations an ImmutableDictionary instead? That one implements IDictionary, and should not need the extra ToDictionary call. #Resolved

I usually prefer IReadOnlyDictionary since the immutability is clearer. Plus this is not in the hot path: it only takes place when the profiler is on, and after an evaluation is done. But if you feel strong about it, I don't mind changing it. #Resolved

let's leave it like this until it becomes a measurable problem :) #Resolved

cdmihai · 2017-12-02T01:14:40Z

src/Framework/IProjectElement.cs

+        /// <summary>
+        /// The outer xml markup of the xml element associated with this project element/>
+        /// </summary>
+        string OuterXmlElement { get; }


Can you rename this to hide the fact that it's XML? Maybe OuterElement or RawElementRepresentation, or RawText #Resolved

Mmhh.. but this was originally being retrieved directly as this.XmlElement.OuterXml. So I thought it was important to communicate the original provenance. I would have exposed XmlElementWithLocation directly (the type of XmlElement), but that needed an extra project reference, and avoiding that was the main purpose of this interface.
But I'm not well versed in the content of a ProjectElement, so I'll follow your advice here. #Resolved

The ProjectElement wraps over an XmlElement. It is like an MSBuild AST node. I was thinking that if we ever change MSBuild's representation from XML to something else (probably never, but who knows), then having an interface member referencing XML would be cumbersome. #Resolved

Ok, makes sense, will change #Resolved

smera · 2017-12-02T01:47:15Z

@andy Gerlicher, moved the saving part to the logger

In reply to: 348609891 [](ancestors = 348609891)

smera · 2017-12-02T01:47:58Z

I'll try to address that as a separate PR

In reply to: 348642187 [](ancestors = 348642187)

AndyGerlicher · 2017-12-02T19:14:44Z

src/MSBuild.UnitTests/CommandLineSwitches_Tests.cs

+        /// </summary>
+        [InlineData(" ")]
+        [InlineData("a_file_with?invalid_chars")]
+        [InlineData("C:\\a_path\\with?invalid\\chars")]


These aren't all invalid on other OSs which is why the tests are failing. #Resolved

Will make this test Windows-specific. Just trying to validate there is a validation going on around invalid chars, so any OS will do

In reply to: 154504123 [](ancestors = 154504123)

In the end I made it slightly more generic to cover other OSs too

In reply to: 154737571 [](ancestors = 154737571,154504123)

AndyGerlicher

Very nice!

AndyGerlicher · 2017-12-05T19:45:00Z

@dotnet-bot test this please

Odd they all timed out except the full framework build...

AndyGerlicher · 2017-12-06T04:17:59Z

@dotnet-bot test this please

smera · 2017-12-06T18:32:28Z

@dotnet-bot test this please

AndyGerlicher · 2017-12-07T17:04:51Z

@dotnet-bot test Windows_NT Build for CoreCLR please

* A bool was attempted to be read twice when reading from the stream. * On read, val.Value was called when null causing an exception. Unrelated to this, if an exception happens during the translate process all the nodes hang.

Fix serialization on Core

Revert nuspec order

AndyGerlicher · 2017-12-08T03:14:53Z

Green CI!!! :)

Add profiler under a flag

b674f7b

dnfclas added the cla-required label Dec 1, 2017

dnfclas added cla-signed and removed cla-required labels Dec 1, 2017

cdmihai requested review from davkean and dsplaisted December 1, 2017 18:16

smera requested review from AndyGerlicher and cdmihai December 1, 2017 18:48

cdmihai reviewed Dec 1, 2017

View reviewed changes

AndyGerlicher reviewed Dec 1, 2017

View reviewed changes

KirillOsenkov mentioned this pull request Dec 1, 2017

Serialize ProjectEvaluationFinished.ProfilerResult to BinaryLogger #2768

Closed

cdmihai reviewed Dec 1, 2017

View reviewed changes

cdmihai reviewed Dec 2, 2017

View reviewed changes

AndyGerlicher reviewed Dec 2, 2017

View reviewed changes

Addressing CR comments

01d6d90

AndyGerlicher approved these changes Dec 5, 2017

View reviewed changes

Don't use type pattern matching since Mono does not support it yet

25a7c09

An empty profiler report, which just a header, is possible

ffb51d8

AndyGerlicher and others added 4 commits December 7, 2017 11:19

Fix serialization on Core

3e616fc

* A bool was attempted to be read twice when reading from the stream. * On read, val.Value was called when null causing an exception. Unrelated to this, if an exception happens during the translate process all the nodes hang.

Merge pull request #1 from AndyGerlicher/fixevaluation

7159d5a

Fix serialization on Core

Revert nuspec order

a5b61db

Merge pull request #2 from AndyGerlicher/fixevaluation

8258151

Revert nuspec order

AndyGerlicher changed the title ~~[WIP] Add profiler under a flag~~ Add profiler under a flag Dec 8, 2017

AndyGerlicher merged commit 36e9ed6 into dotnet:master Dec 8, 2017

davkean mentioned this pull request Dec 8, 2017

WPF support novotnyllc/MSBuildSdkExtras#27

Merged



		/// <summary>
		/// The outer xml markup of the xml element associated with this project element/>

Add profiler under a flag #2765

Add profiler under a flag #2765

Conversation

smera commented Dec 1, 2017

dnfclas commented Dec 1, 2017 • edited by smera Loading

dnfclas commented Dec 1, 2017 • edited by smera Loading

cdmihai Dec 1, 2017 • edited by smera Loading

Choose a reason for hiding this comment

smera Dec 1, 2017 • edited Loading

Choose a reason for hiding this comment

AndyGerlicher Dec 1, 2017 • edited by smera Loading

Choose a reason for hiding this comment

smera Dec 1, 2017 • edited Loading

Choose a reason for hiding this comment

AndyGerlicher commented Dec 1, 2017 • edited by smera Loading

AndyGerlicher Dec 1, 2017 • edited by smera Loading

Choose a reason for hiding this comment

smera Dec 1, 2017 • edited Loading

Choose a reason for hiding this comment

AndyGerlicher commented Dec 1, 2017 • edited by smera Loading

mmitche commented Dec 1, 2017 • edited by smera Loading

mmitche commented Dec 1, 2017 • edited by smera Loading

KirillOsenkov commented Dec 1, 2017 • edited by smera Loading

cdmihai Dec 1, 2017 • edited by smera Loading

Choose a reason for hiding this comment

smera Dec 2, 2017 • edited Loading

Choose a reason for hiding this comment

cdmihai Dec 2, 2017 • edited by smera Loading

Choose a reason for hiding this comment

smera Dec 2, 2017 • edited Loading

Choose a reason for hiding this comment

cdmihai Dec 2, 2017 • edited by smera Loading

Choose a reason for hiding this comment

smera Dec 2, 2017 • edited Loading

Choose a reason for hiding this comment

cdmihai Dec 2, 2017 • edited by smera Loading

Choose a reason for hiding this comment

cdmihai Dec 2, 2017 • edited by smera Loading

Choose a reason for hiding this comment

smera Dec 2, 2017 • edited Loading

Choose a reason for hiding this comment

cdmihai Dec 2, 2017 • edited by smera Loading

Choose a reason for hiding this comment

smera Dec 2, 2017 • edited Loading

Choose a reason for hiding this comment

smera commented Dec 2, 2017

smera commented Dec 2, 2017

AndyGerlicher Dec 2, 2017 • edited by smera Loading

Choose a reason for hiding this comment

smera Dec 4, 2017

Choose a reason for hiding this comment

smera Dec 4, 2017

Choose a reason for hiding this comment

AndyGerlicher left a comment

Choose a reason for hiding this comment

AndyGerlicher commented Dec 5, 2017

AndyGerlicher commented Dec 6, 2017

smera commented Dec 6, 2017

AndyGerlicher commented Dec 7, 2017

AndyGerlicher commented Dec 8, 2017

dnfclas commented Dec 1, 2017 •

edited by smera

Loading

dnfclas commented Dec 1, 2017 •

edited by smera

Loading

cdmihai Dec 1, 2017 •

edited by smera

Loading

smera Dec 1, 2017 •

edited

Loading

AndyGerlicher Dec 1, 2017 •

edited by smera

Loading

smera Dec 1, 2017 •

edited

Loading

AndyGerlicher commented Dec 1, 2017 •

edited by smera

Loading

AndyGerlicher Dec 1, 2017 •

edited by smera

Loading

smera Dec 1, 2017 •

edited

Loading

AndyGerlicher commented Dec 1, 2017 •

edited by smera

Loading

mmitche commented Dec 1, 2017 •

edited by smera

Loading

mmitche commented Dec 1, 2017 •

edited by smera

Loading

KirillOsenkov commented Dec 1, 2017 •

edited by smera

Loading

cdmihai Dec 1, 2017 •

edited by smera

Loading

smera Dec 2, 2017 •

edited

Loading

cdmihai Dec 2, 2017 •

edited by smera

Loading

smera Dec 2, 2017 •

edited

Loading

cdmihai Dec 2, 2017 •

edited by smera

Loading

smera Dec 2, 2017 •

edited

Loading

cdmihai Dec 2, 2017 •

edited by smera

Loading

cdmihai Dec 2, 2017 •

edited by smera

Loading

smera Dec 2, 2017 •

edited

Loading

cdmihai Dec 2, 2017 •

edited by smera

Loading

smera Dec 2, 2017 •

edited

Loading

AndyGerlicher Dec 2, 2017 •

edited by smera

Loading