Introduce TaskParameterEventArgs

[KirillOsenkov]

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]

Fixes #6007

[KirillOsenkov]

Fixes #5211

[KirillOsenkov]

Fixes #3966

[KirillOsenkov]

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

[KirillOsenkov]

Potentially fixes #2200

[KirillOsenkov]

Partially fixes #2168

[KirillOsenkov]

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]

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]

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:

After:

[KirillOsenkov]

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

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]

Oh, duh, I was profiling debug 🤦

NEVER MIND.

[KirillOsenkov]

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]

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

master branch:

this PR:

LOH allocations are significantly reduced:
master branch:

this PR:

[cdmihai]

@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]

@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]

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]

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]

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]

Latest allocations:

A few commits back:

Latest:

A few commits back:

Latest:

[KirillOsenkov]

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:

Check that LOH

[KirillOsenkov]

This should now be ready for review.

[KirillOsenkov]

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.

[KirillOsenkov]

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

[Forgind]

LGTM! Thanks for this!