Implement Text-Based Performance Log by brianrob · Pull Request #5861 · dotnet/msbuild

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

        /// <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

                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

+                // 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

+                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

+                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

+        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

+                    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

+
+                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

+            {
+                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.

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

+        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

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

Conversation

brianrob commented Nov 5, 2020

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

brianrob commented Nov 6, 2020

Uh oh!

Forgind left a comment

Choose a reason for hiding this comment

Uh oh!

marcpopMSFT commented Nov 6, 2020

Uh oh!

rainersigwald commented Nov 6, 2020

Uh oh!

marcpopMSFT commented Nov 6, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants