Implement Text-Based Performance Log #5861

brianrob · 2020-11-05T20:09:26Z

Implements a text-based performance log scheme that writes coarse-grained performance logs:

No logs are written unless the user opts-in by setting the log location via the environment variable DOTNET_PERFLOG_DIR. This is currently enabled when a user opts-in via a CLI command, but can be set adhoc as well.
Most logs will be produced at the request of CLI commands. The lifetime of these logs is managed by the CLI - see Implement Text-Based Performance Log sdk#14409 for details.
Data in the logs are emitted via MSBuildEventSource so that the events can be consumed through other profilers, such as those that use ETW.

cc: @marcpopMSFT, @davidfowl, @DamianEdwards, @bwadswor

Forgind · 2020-11-05T22:04:11Z

src/Framework/MSBuildEventSource.cs

@@ -244,14 +249,14 @@ public void ExpandGlobStop(string rootDirectory, string glob, string excludedPat
        /// Call this method to notify listeners of timing related to loading an XmlDocumentWithLocation from a path.
        /// <param name="fullPath">Path to the document to load.</param>
        /// </summary>
-        [Event(29)]
+        [Event(29, Keywords = Keywords.PerformanceLog)]


How did you choose which events to add this to?

What I chose is based on two criteria:

Gives a coarse view of what's happening, and time spans for those actions.

Keeps the rate of events relatively low so that the impact on performance isn't too much.

If you think there are other events that should be included, I'm definitely open to that - just being careful with the perf overhead.

Maybe RAROverallStart/Stop, BuildStart/Stop, and BuildProjectStart/Stop? I'd put those higher than LoadDocument, Parse, or MSBuildExe.

Done. Thanks for the feedback on this.

For command line scenarios I suspect Build and MSBuildExe will be fairly redundant: all MSBuild.exe does is start a build. But let's leave it in for v1.

Forgind · 2020-11-05T22:09:12Z

src/UnitTests.Shared/RunnerUtilities.cs

@@ -85,6 +87,15 @@ public static string RunProcessAndGetOutput(string process, string parameters, o
                UseShellExecute = false,
                Arguments = parameters
            };
+
+            if(environmentVariables != null)


We've worked around the inability to set environment variables in a different way elsewhere. (See here.) Do you think it would be reasonable to combine them?

I imagine so. Are you proposing a separate class, or moving the usage in XMake_Tests to use what I've done here, or something else?

I'd do the latter or move what's in XMake_Tests here and call it. I don't have a strong preference between them, but I'd like it to be in one spot.

Forgind · 2020-11-05T22:14:14Z

src/MSBuild.UnitTests/PerfLog_Tests.cs

+                // It's most important to ensure that at least one file shows up because any others that show up will be there because MSBuild properly
+                // enabled this functionality.
+                string[] files = Directory.GetFiles(perfLogDir, "perf-*.log");
+                Assert.NotEmpty(files);


nit:

Suggested change

Assert.NotEmpty(files);

files.ShouldNotBeEmpty();

And also convert the rest to Shouldly?

Do you think you should also check to make sure those files didn't exist before? I don't think GetTempPath returns a truly random path each time.

Updated the rest to Shoudly. Thanks for pointing this out.

With regard to the directory, GetTempPath doesn't return a random path, but the test creates a random GUID directory to ensure that the directory is empty, and then creates it, which would result in a thrown exception if it already existed.

Forgind · 2020-11-05T22:15:00Z

src/MSBuild.UnitTests/PerfLog_Tests.cs

+                Directory.CreateDirectory(perfLogDir);
+                Directory.CreateDirectory(projectDir);
+
+                string content = ObjectModelHelpers.CleanupFileContents("<Project ToolsVersion='msbuilddefaulttoolsversion' xmlns='msbuildnamespace'><Target Name='t'><Warning Text='[A=$(A)]'/></Target></Project>");


nit:
split across multiple lines?

Forgind · 2020-11-05T22:15:34Z

src/MSBuild.UnitTests/PerfLog_Tests.cs

+                bool successfulExit;
+                RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out successfulExit, environmentVariables: environmentVariables);


tiny nit:

Suggested change

bool successfulExit;

RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out successfulExit, environmentVariables: environmentVariables);

RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out bool successfulExit, environmentVariables: environmentVariables);

Forgind · 2020-11-05T22:18:17Z

src/MSBuild.UnitTests/PerfLog_Tests.cs

+        public void TestPerfLogEnabledProducedLogFile()
+        {
+            // Setup perf log.
+            string perfLogDir = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N"));


I think all this would be easier with a TestEnvironment.

Can you please point me to an example that I should follow?

I like this example, but I'm a little biased. You can also use env.SetEnvironmentVariable(<name>, <value>);.

Using the test environment should make this simpler (since it handles cleanup), and allow avoiding the RunnerUtilities changes.

Yes, this definitely cleaned things up.

Forgind · 2020-11-05T22:22:09Z

src/MSBuild/PerformanceLogEventListener.cs

+                    s_builder.Clear();
+                }
+
+                s_builder.Append($"[{DateTime.UtcNow.ToString("o")}] Event={eventData.EventSource.Name}/{eventData.EventName} ProcessID={_processIDStr} ThreadID={System.Threading.Thread.CurrentThread.ManagedThreadId}\t ");


There's an AppendFormat method for StringBuilder. I remember having tested whether it was faster than this, but I don't remember the answer. I think .Append over and over was fastest but also ugliest.

Forgind · 2020-11-05T22:23:23Z

src/MSBuild/PerformanceLogEventListener.cs

+
+                lock (this)
+                {
+                    if (_writer != null)


When is _writer null, and should we error?

My goal is to make this log as inobtrusive as possible. So if something goes wrong, I want the log to fail silently and/or just drop data rather than error. Essentially, preserve correctness.

Forgind · 2020-11-05T22:25:22Z

src/MSBuild/PerformanceLogEventListener.cs

+            {
+                if (eventListener != null)
+                {
+                    eventListener.Dispose();


if (eventListener != null && eventListener threw an exception) shouldn't we return null or throw?

Yes, that's a good catch. Thanks.

src/MSBuild/PerformanceLogEventListener.cs

rainersigwald · 2020-11-06T16:34:42Z

src/MSBuild.UnitTests/PerfLog_Tests.cs

+        public void TestPerfLogEnabledProducedLogFile()
+        {
+            // Setup perf log.
+            string perfLogDir = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N"));


Using the test environment should make this simpler (since it handles cleanup), and allow avoiding the RunnerUtilities changes.

brianrob · 2020-11-06T19:05:14Z

Thank you both for the reviews. I think I've covered all of the feedback.

Forgind

LGTM!

marcpopMSFT · 2020-11-06T22:13:16Z

@brianrob Note that you checked this in for 6.0. If you want it included in 5.0.2xx for earlier testing, it'll need to go in that branch as well.

rainersigwald · 2020-11-06T22:20:13Z

@marcpopMSFT this is MSBuild :) it's in the 2xx branch already

marcpopMSFT · 2020-11-06T22:36:50Z

@rainersigwald DOH! I was just in the SDK repo and got my wires crossed. Carry on.

brianrob added 4 commits November 5, 2020 11:21

Fix inadvertent call to MSBuildExeStop.

1b960f4

Implement a text-based performance log.

fca5b32

Add perf log tests.

85475c4

Merge remote-tracking branch 'upstream/master' into perf-log

88a4d9b

brianrob requested a review from rainersigwald November 5, 2020 20:09

Skip test on Mono since Mono doesn't implement EventSource.

e70ae92

Forgind reviewed Nov 5, 2020

View reviewed changes

brianrob added 2 commits November 5, 2020 15:40

Fix EventSource keywords.

05902ba

Address review feedback.

bdc4ce7

rainersigwald approved these changes Nov 6, 2020

View reviewed changes

Update tests based on code review feedback.

ad04c82

Forgind approved these changes Nov 6, 2020

View reviewed changes

Enable a few more events.

2fa8afb

brianrob merged commit 7452552 into dotnet:master Nov 6, 2020

brianrob deleted the perf-log branch November 6, 2020 21:59

rainersigwald mentioned this pull request Nov 20, 2020

Opt into and capture perf logging in second-stage bootstrap builds #5900

Closed

benvillalobos mentioned this pull request Mar 17, 2021

Opt Into Perf Logging #6274

Merged

rainersigwald mentioned this pull request Aug 3, 2021

Miscellaneous event tweaks #6725

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Implement Text-Based Performance Log #5861

Implement Text-Based Performance Log #5861

brianrob commented Nov 5, 2020

Forgind Nov 5, 2020

brianrob Nov 5, 2020

Forgind Nov 6, 2020

brianrob Nov 6, 2020

rainersigwald Nov 6, 2020

Forgind Nov 5, 2020

brianrob Nov 5, 2020

Forgind Nov 6, 2020

Forgind Nov 5, 2020

Forgind Nov 5, 2020

brianrob Nov 5, 2020

Forgind Nov 5, 2020

Forgind Nov 5, 2020

Forgind Nov 5, 2020

brianrob Nov 5, 2020

Forgind Nov 6, 2020

rainersigwald Nov 6, 2020

brianrob Nov 6, 2020

Forgind Nov 5, 2020

Forgind Nov 5, 2020

brianrob Nov 5, 2020

Forgind Nov 5, 2020

brianrob Nov 5, 2020

rainersigwald Nov 6, 2020

brianrob commented Nov 6, 2020

Forgind left a comment

marcpopMSFT commented Nov 6, 2020

rainersigwald commented Nov 6, 2020

marcpopMSFT commented Nov 6, 2020

		bool successfulExit;
		RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out successfulExit, environmentVariables: environmentVariables);

Implement Text-Based Performance Log #5861

Implement Text-Based Performance Log #5861

Conversation

brianrob commented Nov 5, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brianrob commented Nov 6, 2020

Forgind left a comment

Choose a reason for hiding this comment

marcpopMSFT commented Nov 6, 2020

rainersigwald commented Nov 6, 2020

marcpopMSFT commented Nov 6, 2020