Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Introduce TaskParameterEventArgs #6155

Merged
merged 6 commits into from Mar 4, 2021
Merged

Conversation

@KirillOsenkov
Copy link
Member

@KirillOsenkov KirillOsenkov commented Feb 14, 2021

Instead of just logging a BuildMessageEventArgs with a list of all items and metadata concatenated into a large string (often 5 MB in size or more) it keeps a structured representation of items and metadata. TaskParameterEventArgs inherits from BuildMessageEventArgs and the Message implementation materializes the large string on demand. However when only the BinaryLogger is present the Message is never accessed, thus saving on allocations. The Message is also never sent across the nodes nor written into the binlog.

TaskParameterEventArgs is instantiated in 5 locations: ItemGroup Include and Remove inside targets, task inputs, and two cases for task outputs.

Storing smaller strings in the binlog results in very significant savings from string deduplication. A 22 MB binlog goes down to 3.5 MB in size. We're also seeing build speed improvements from 33 seconds to 30 seconds. Significant reduction in memory allocations since we no longer need to allocate the large strings and send them across the nodes.

This also shares some extension methods for reading and writing things between the node packet serialization and binary logger. It also shares a new internal type, TaskItemData, used as a holder for deserialized items. The actual ProjectItemInstance.TaskItem is too heavyweight for this.

Binary logger format version goes all the way to 11. The viewer already supports the new format. An additional benefit is that the viewer no longer has to parse the large text messages to recover structure, it will now be more reliable when reading multi-line properties, items and metadata values.

I've replayed the binlog produced by this version and diffed with the old binlog and all information appears to be preserved.

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 14, 2021

Fixes #6007

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 14, 2021

Fixes #5211

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 14, 2021

Fixes #3966

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 14, 2021

Potentially fixes #3577 (at least the hope is to significantly reduce allocations)

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 14, 2021

Potentially fixes #2200

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 14, 2021

Partially fixes #2168

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 16, 2021

I've noticed that the ref api didn't regenerate and discovered that that functionality got disabled accidentally. After this fix merges I'll need to rebase and regenerate the public API:
#6157

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 16, 2021

Here are some stats from a binlog produced from this PR and an equivalent binlog from master:

PR #6155:

Statistics:                   			Total size: 8,858,154			Count: 158,861			Largest: 29,767
    TaskParameter                 			Total size: 3,453,513			Count: 29,379			Largest: 27,124
    BuildMessage                  			Total size: 3,183,360			Count: 94,828			Largest: 53
        Other                         			Total size: 3,114,633			Count: 92,461			Largest: 53
        Task Input Item               			Total size: 68,727			Count: 2,367			Largest: 30
    ProjectStarted                			Total size: 686,356			Count: 1,953			Largest: 29,767
    TargetFinished                			Total size: 401,366			Count: 5,214			Largest: 2,926
    ProjectImported               			Total size: 367,541			Count: 7,616			Largest: 53
    TargetSkipped                 			Total size: 327,088			Count: 7,970			Largest: 44
    TargetStarted                 			Total size: 211,301			Count: 5,214			Largest: 44
    TaskFinished                  			Total size: 80,053			Count: 2,302			Largest: 37
    TaskStarted                   			Total size: 77,751			Count: 2,302			Largest: 36
    ProjectFinished               			Total size: 64,482			Count: 1,953			Largest: 35
    ProjectEvaluationFinished     			Total size: 1,949			Count: 48			Largest: 42
    ProjectEvaluationStarted      			Total size: 1,901			Count: 48			Largest: 41
    BuildWarning                  			Total size: 1,421			Count: 31			Largest: 47
    TaskCommandLine               			Total size: 42			Count: 1			Largest: 42
    BuildFinished                 			Total size: 16			Count: 1			Largest: 16
    BuildStarted                  			Total size: 14			Count: 1			Largest: 14
    Strings                       			Total size: 7,132,418			Count: 34,149			Largest: 42,934
    NameValueLists                			Total size: 2,228,938			Count: 26,616			Largest: 3,283
    Blobs                         			Total size: 431,379			Count: 1			Largest: 431,379


master:
Statistics:                   			Total size: 6,348,629			Count: 158,861			Largest: 30,204
    BuildMessage                  			Total size: 4,120,183			Count: 124,207			Largest: 53
        Other                         			Total size: 3,131,717			Count: 92,896			Largest: 53
        Added Item                    			Total size: 779,517			Count: 24,266			Largest: 33
        Task Input Item               			Total size: 131,294			Count: 4,500			Largest: 30
        Task Output Item              			Total size: 47,982			Count: 1,628			Largest: 30
        Removed Item                  			Total size: 29,673			Count: 917			Largest: 33
    ProjectStarted                			Total size: 692,727			Count: 1,953			Largest: 30,204
    TargetFinished                			Total size: 401,558			Count: 5,214			Largest: 2,815
    ProjectImported               			Total size: 367,614			Count: 7,616			Largest: 53
    TargetSkipped                 			Total size: 327,094			Count: 7,970			Largest: 44
    TargetStarted                 			Total size: 211,457			Count: 5,214			Largest: 44
    TaskFinished                  			Total size: 80,053			Count: 2,302			Largest: 37
    TaskStarted                   			Total size: 77,751			Count: 2,302			Largest: 36
    ProjectFinished               			Total size: 64,837			Count: 1,953			Largest: 35
    ProjectEvaluationFinished     			Total size: 1,955			Count: 48			Largest: 42
    ProjectEvaluationStarted      			Total size: 1,907			Count: 48			Largest: 41
    BuildWarning                  			Total size: 1,421			Count: 31			Largest: 47
    TaskCommandLine               			Total size: 42			Count: 1			Largest: 42
    BuildFinished                 			Total size: 16			Count: 1			Largest: 16
    BuildStarted                  			Total size: 14			Count: 1			Largest: 14
    Strings                       			Total size: 334,527,525			Count: 38,934			Largest: 8,591,869
    NameValueLists                			Total size: 467,005			Count: 5,416			Largest: 3,291
    Blobs                         			Total size: 431,572			Count: 1			Largest: 431,572

Note how we have 34,149 strings totalling 7 MB, and master has 38,934 strings totalling 334 MB. Turns out if you crumble those extra ~4,800 strings down they basically disappear.

Binlog size here goes from 11.6 MB to 3.6 MB. An equivalent binlog from 16.8 (no dedup at all) is ~22 MB.

Uncompressed stream inside the binlog goes from 341 MB to 18 MB.

Also note how the largest string goes from 8.6 MB to 43 KB. This completely avoids the Large Object Heap at 85 KB threshold.

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 16, 2021

I tried to make a histogram of string sizes before and after, but it's not visible very well (maybe I should do logarithmic?)
Before:
image

After:
image

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 17, 2021

Unfortunately I'm seeing both perf and allocations when deserializing packets in the main node:
image

We now get tons of small strings instead of one giant string for task parameter and we're interning each one and it shows. I'll need to think if I have any ideas here.

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 17, 2021

Oh, duh, I was profiling debug 🤦

image

NEVER MIND.

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 17, 2021

I got some more perf numbers.

/m /bl is 22s on 16.8 and master, and 18-19s with this PR
/bl is 41s on 16.8, 32s on master and 27s with this PR

This PR appears to be slower than 16.8 for /m and no log:
12s on 16.8, 13s on master and 14s this PR. I'm not sure how to explain or confirm this yet. This PR shouldn't affect non-binlog builds. Multi-proc builds generally have higher variance so I'm not worried about it too much.

/m /bl 16.8 master 4547f73 SmallDictionary
  22.624 22.961 21.198 19.227
  22.503 22.497 19.676 18.518
  22.624 22.975 18.69 19.348
  22.938 20.303 18.079 20.938
  22.633 20.479 18.284 18.646
         
/bl 40.213 33.56   30.977
  42.092 31.87   27.332
  42.475 31.888   28.057
  41.307 32.533   26.813
  40.923 32.634   27.081
         
no log no /m 20.251 19.627   21.761
  19.741 21.286   19.75
  19.357 19.81   19.774
         
no log /m 14.071 13.931   15.038
  12.292 13.718   14.481
  13.162 13.517   14.167
  11.929 13.782   14.193
  12.5 13.583   14.042
@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 19, 2021

I'm seeing very favorable allocations picture with this PR.

master branch:
image

this PR:
image

LOH allocations are significantly reduced:
master branch:
image

this PR:
image

@cdmihai
Copy link
Contributor

@cdmihai cdmihai commented Feb 19, 2021

@KirillOsenkov If you compare against the msbuild binaries shipping with VS, those are also ngened and use profile guided optimizations. Best to compare against your own built msbuild from the 16.8 branch

@cdmihai
Copy link
Contributor

@cdmihai cdmihai commented Feb 20, 2021

@KirillOsenkov regarding the newly added ton of small string allocations for all the items and their metadata, how about not deserializing TaskParameterEventArgs.Items and only lazily deserialize it when somebody asks for it?

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 20, 2021

That would hold on to a byte[] and I guess when LogTaskInputs is set and this whole machinery runs, we're guaranteed to consume every event via a logger. So might as well read it eagerly, plus most strings will be interned by InterningBinaryReader.

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 20, 2021

Some decent perf improvements from the last 5 commits:

  16.8.5 PR fix
/m /bl   15.51 12.467
    14.75 13.257
    13.522 13.004
    13.262 13.42
    13.206 14.031
    13.226 12.63
/bl      
  32.192 22.458 20.772
  32.015 20.955 20.253
  31.873 20.898 20.156
    21.177 20.061
    21.121 19.993
@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 20, 2021

There are a few oustanding questions with this PR that I'd like to resolve, and I'll respond separately when it's ready for proper review. It's getting closer though. Just need to decide whether it's worth the risk of exposing a couple internals for raw speed.

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 20, 2021

Latest allocations:

A few commits back:
image

Latest:
image

A few commits back:
image

Latest:
image

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 20, 2021

You can see Dictionary<K,V> disappeared and SmallDictionary is just two string[] arrays.

We also see reduced copies of items during enumeration since we now bypass the enumerator Proxy that DeepClones items.

byte[] have reduced, but I can't remember which optimization did this.

I apologize for measuring 16.8 again, but please indulge me, it brings me great joy: ;) This is 16.8.5:

image

image

Check that LOH

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Feb 26, 2021

This should now be ready for review.

@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Mar 1, 2021

I'm starting to have concerns about how node packet serialization works in this PR. The whole problem starts because we want to shoehorn the implementation of serialization into the declarations assembly (MS.B.Framework).

I think it might be cleaner if we move the serialization out to Microsoft.Build. This way SmallDictionary, TaskItemData and potentially even IMetadataContainer can move out to Microsoft.Build as well. There won't be a need for static constructors then.

This is needed to ensure the static constructor runs.
@KirillOsenkov KirillOsenkov removed the WIP label Mar 1, 2021
@KirillOsenkov
Copy link
Member Author

@KirillOsenkov KirillOsenkov commented Mar 1, 2021

Nah, I've just tried and it won't solve the Message problem.

@cdmihai
cdmihai approved these changes Mar 1, 2021
Rename SmallDictionary -> ArrayDictionary.
@Forgind
Forgind approved these changes Mar 2, 2021
Copy link
Member

@Forgind Forgind left a comment

LGTM! Thanks for this!

@BenVillalobos BenVillalobos merged commit f69319c into master Mar 4, 2021
7 checks passed
7 checks passed
license/cla All CLA requirements met.
Details
@azure-pipelines
msbuild-pr Build #20210301.12 succeeded
Details
@azure-pipelines
msbuild-pr (Linux Core) Linux Core succeeded
Details
@azure-pipelines
msbuild-pr (Windows Core) Windows Core succeeded
Details
@azure-pipelines
msbuild-pr (Windows Full Release (no bootstrap)) Windows Full Release (no bootstrap) succeeded
Details
@azure-pipelines
msbuild-pr (Windows Full) Windows Full succeeded
Details
@azure-pipelines
msbuild-pr (macOS Core) macOS Core succeeded
Details
@BenVillalobos BenVillalobos deleted the dev/kirillo/taskParameterEventArgs branch Mar 4, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked issues

Successfully merging this pull request may close these issues.

None yet

4 participants