Fix of OutOfMemoryException when embedding large amount of files to binlog #8971

MichalPavlik · 2023-06-28T12:36:30Z

Summary

Embedding of large amount of files to binlog can lead to OutOfMemoryException due to memory pressure. It also causes LOH fragmentation and Gen2 collections.

Customer Impact

Large builds cannot use the binary logger due to an OOM crash.

Regression?

Yes, in 16.8 (#5718).

Testing

Before:

After:

Risk

Medium--adds new filesystem dependencies which could fail, but is similar to the pre-16.8 mechanism and tries to be tolerant of failures.

Changes Made

This change reverts in-memory operations and uses temp file for embedded files. The file is now stored in temporary directory (instead of binlog target directory) to avoid problems with file watchers. There might be possible another optimizations, but goal of this PR is to unblock our partners. We can optimize further in separate PR.

MichalPavlik · 2023-06-28T13:39:43Z

Well, I missed somehow one failed test on my local machine. I will add at least one more commit, but the functionality is ready for review.

EDIT: Done

src/Build/Logging/BinaryLogger/BinaryLogger.cs

src/MSBuild.UnitTests/XMake_Tests.cs

src/Build/Logging/BinaryLogger/ProjectImportsCollector.cs

rainersigwald

Looks great! Please retarget to the vs17.7 branch.

src/Build/Logging/BinaryLogger/ProjectImportsCollector.cs

Forgind · 2023-07-05T17:30:02Z

eng/Versions.props

@@ -2,7 +2,8 @@
 <!-- Copyright (c) .NET Foundation and contributors. All rights reserved. Licensed under the MIT license. See License.txt in the project root for full license information. -->
 <Project>
  <PropertyGroup>
-    <VersionPrefix>17.7.0</VersionPrefix><DotNetFinalVersionKind>release</DotNetFinalVersionKind>
+    <VersionPrefix>17.7.0</VersionPrefix>


This looks wrong, both because you need to update the version prefix and because we generally put these two on the same line to force a merge conflict when flowing final version commits to main.

This doesn't matter for this PR because we'll be handling merging to the release branch specially since we have several things to bring.

I'd suggest to completely remove change to this file from this PR - in order to have a clean merge of all the in-flight 17.7 PRs (Rainer was contemplating single octopus merge of all 17.7 PRs)

Forgind · 2023-07-05T17:42:47Z

src/Build/Logging/BinaryLogger/BinaryLogger.cs

@@ -226,12 +227,25 @@ public void Shutdown()

            if (projectImportsCollector != null)
            {
+                projectImportsCollector.Close();


Why does this have to be up here instead of where it was before?

So that we first flush the remaining archive bits to disk in the temp folder and close the file, so that we can read it later.

JanKrivanek

Looks good!

Did you perfomr any measurments how this impacts build speed with binlog for small and mid-size projects? (I'd say dotnet new console, dotnet new mvc and OrchardCore can possibly be seen as representative samples)

If there is any measurable difference we should probably plan followup item where we optimize the approach to keep in-memory stream for sane projects. A sample of very primitive StreamProxy that dynamically uses either memory or fallbacks to file based on the size can be found here: https://github.com/dotnet/templating/blob/main/src/Microsoft.TemplateEngine.Core/Util/StreamProxy.cs

MichalPavlik · 2023-07-11T11:22:43Z

I expressed my concerns regarding to perf regression caused by switching back to temp file, but Kirill measured it and...

I measured perf before and after and writing to a memory stream wasn't noticeably better than the temp file. I expect the vast majority of usages will be just fine with writing the embedded files stream to a temp file.

We can do our measurements, but I would say that most devs are not collecting binlog by default (during development). Binlogs are collected on dev machines usually when you want to diagnose some issue.

JanKrivanek · 2023-07-11T12:45:08Z

I expressed my concerns regarding to perf regression caused by switching back to temp file, but Kirill measured it and...

I measured perf before and after and writing to a memory stream wasn't noticeably better than the temp file. I expect the vast majority of usages will be just fine with writing the embedded files stream to a temp file.

We can do our measurements, but I would say that most devs are not collecting binlog by default (during development). Binlogs are collected on dev machines usually when you want to diagnose some issue.

Perfect! Sounds like we should be good

ghost · 2023-07-11T16:32:36Z

Hello! I noticed that you're targeting one of our servicing branches. Please consider updating the version.

Fixes #8595 by storing the embedded-file zip in a temporary directory (instead of memory or binlog target directory) to avoid problems with file watchers.

KirillOsenkov · 2023-07-25T02:10:55Z

Curious how did we miss #9057?

Were the corrupt binlogs easy to repro? Are we missing a test? Did manual testing all look OK?

rainersigwald · 2023-07-25T02:13:59Z

They are easy to repro but the viewer is pretty tolerant of the problem; it loads without visible error and is just missing the embeds. I think I might have seen a log that was mysteriously missing embeds but I didn't connect it with this and I went back and forth between builds that did and didn't have the bug enough that I didn't see it coming.

We definitely need better regression testing around this scenario, which is high on the list after figuring out how to get the fix out.

KirillOsenkov · 2023-07-25T03:47:19Z

Hmm, I've been thinking about surfacing first-chance exceptions in the viewer and flash some sort of user-visible warning, like a goldbar. This would have caught this.

KirillOsenkov · 2023-07-25T03:48:14Z

I suppose it doesn't help that the embeds archive is the last record in the file, so even if the stream is now corrupted and dis-synchronized the rest of the binlog is already read

MichalPavlik · 2023-07-25T08:28:09Z

I'm focusing on the serialization problem and I will add test at least for the length of the payload. I believe I tried open binlogs in viewer and everything looked OK. Warning in binlog viewer would be nice feature.

Work around bad binlogs produced by dotnet/msbuild#8971 by probing for the zip header that will be the known first bytes of the blob. Co-authored-by: MichalPavlik <mipavlik@microsoft.com>

Forgind · 2023-07-25T18:45:53Z

Hmm, I've been thinking about surfacing first-chance exceptions in the viewer and flash some sort of user-visible warning, like a goldbar. This would have caught this.

I think a user-visible warning like this is great from the developer's (i.e., our) perspective but detrimental from a user's perspective. Most users won't know why it's flashing unless they intentionally look for an error afterwards, and even if they do, they probably won't know how to or have the inclination to fix it. I think this sort of things is great in a beta product to help get fast feedback but not ideal in a product as established as the binlog viewer, as most users at this point probably just want to finish their work and don't care if the viewer is broken unless it makes it harder for them to do so.

MichalPavlik requested review from KirillOsenkov and rainersigwald June 28, 2023 12:36

rainersigwald reviewed Jun 28, 2023

View reviewed changes

src/Build/Logging/BinaryLogger/BinaryLogger.cs Outdated Show resolved Hide resolved

donJoseLuis approved these changes Jun 28, 2023

View reviewed changes

rainersigwald reviewed Jun 28, 2023

View reviewed changes

src/MSBuild.UnitTests/XMake_Tests.cs Outdated Show resolved Hide resolved

rainersigwald added this to the VS 17.7 milestone Jun 29, 2023

rainersigwald reviewed Jun 29, 2023

View reviewed changes

src/Build/Logging/BinaryLogger/ProjectImportsCollector.cs Outdated Show resolved Hide resolved

rainersigwald approved these changes Jun 30, 2023

View reviewed changes

MichalPavlik changed the base branch from main to vs17.7 June 30, 2023 14:05

danmoseley reviewed Jun 30, 2023

View reviewed changes

src/Build/Logging/BinaryLogger/ProjectImportsCollector.cs Show resolved Hide resolved

KirillOsenkov approved these changes Jul 2, 2023

View reviewed changes

Forgind reviewed Jul 5, 2023

View reviewed changes

JanKrivanek approved these changes Jul 11, 2023

View reviewed changes

MichalPavlik added the merge-when-branch-open PRs that are approved, except that there is a problem that means we are not merging stuff right now. label Jul 11, 2023

rainersigwald added the Servicing-consider label Jul 11, 2023

Fix binlog OOM embedding files

4cf11b4

Fixes #8595 by storing the embedded-file zip in a temporary directory (instead of memory or binlog target directory) to avoid problems with file watchers.

rainersigwald force-pushed the dev/mipavlik/fix-binlog-outofmemory branch from 1773680 to 4cf11b4 Compare July 12, 2023 18:41

rainersigwald added Servicing-approved and removed Servicing-consider labels Jul 12, 2023

rainersigwald mentioned this pull request Jul 12, 2023

17.7.1 merges #9022

Merged

rainersigwald merged commit 971bf70 into vs17.7 Jul 12, 2023

rainersigwald deleted the dev/mipavlik/fix-binlog-outofmemory branch July 12, 2023 21:26

MichalPavlik mentioned this pull request Jul 25, 2023

Fixed the embedded file size record #9065

Merged

rainersigwald mentioned this pull request Jul 25, 2023

Support corrupt logs produced by some 17.7 MSBuilds KirillOsenkov/MSBuildStructuredLog#697

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix of OutOfMemoryException when embedding large amount of files to binlog #8971

Fix of OutOfMemoryException when embedding large amount of files to binlog #8971

MichalPavlik commented Jun 28, 2023 •

edited by rainersigwald

Loading

MichalPavlik commented Jun 28, 2023 •

edited

Loading

rainersigwald left a comment

Forgind Jul 5, 2023

rainersigwald Jul 10, 2023

JanKrivanek Jul 12, 2023

Forgind Jul 5, 2023

KirillOsenkov Jul 5, 2023

JanKrivanek left a comment

MichalPavlik commented Jul 11, 2023 •

edited

Loading

JanKrivanek commented Jul 11, 2023

ghost commented Jul 11, 2023

KirillOsenkov commented Jul 25, 2023

rainersigwald commented Jul 25, 2023

KirillOsenkov commented Jul 25, 2023

KirillOsenkov commented Jul 25, 2023

MichalPavlik commented Jul 25, 2023

Forgind commented Jul 25, 2023

Fix of OutOfMemoryException when embedding large amount of files to binlog #8971

Fix of OutOfMemoryException when embedding large amount of files to binlog #8971

Conversation

MichalPavlik commented Jun 28, 2023 • edited by rainersigwald Loading

Summary

Customer Impact

Regression?

Testing

Risk

Changes Made

MichalPavlik commented Jun 28, 2023 • edited Loading

rainersigwald left a comment

Choose a reason for hiding this comment

Forgind Jul 5, 2023

Choose a reason for hiding this comment

rainersigwald Jul 10, 2023

Choose a reason for hiding this comment

JanKrivanek Jul 12, 2023

Choose a reason for hiding this comment

Forgind Jul 5, 2023

Choose a reason for hiding this comment

KirillOsenkov Jul 5, 2023

Choose a reason for hiding this comment

JanKrivanek left a comment

Choose a reason for hiding this comment

MichalPavlik commented Jul 11, 2023 • edited Loading

JanKrivanek commented Jul 11, 2023

ghost commented Jul 11, 2023

KirillOsenkov commented Jul 25, 2023

rainersigwald commented Jul 25, 2023

KirillOsenkov commented Jul 25, 2023

KirillOsenkov commented Jul 25, 2023

MichalPavlik commented Jul 25, 2023

Forgind commented Jul 25, 2023

MichalPavlik commented Jun 28, 2023 •

edited by rainersigwald

Loading

MichalPavlik commented Jun 28, 2023 •

edited

Loading

MichalPavlik commented Jul 11, 2023 •

edited

Loading