GZipStream.ReadByte 10x slower than on Desktop

[KirillOsenkov]

Description

Reading a binlog file takes 4 seconds on .NET Desktop, but 40 seconds on Core 3.1.

Originally reported by @vatsan-madhavan in KirillOsenkov/MSBuildStructuredLog#376

Repro:

1. git clone https://github.com/vatsan-madhavan/MSBuildStructuredLogSummary
2. msbuild /r
3. Download the binlog from https://1drv.ms/u/s!Ah63gfGkKca4lsl2sy71gpkpM9TCog?e=ifgsMj and save it anywhere, e.g. C:\temp\vatsan\vatsan.binlog
4. MSBuildBinLogSummary\bin\Debug\net472\MSBuildBinLogSummary.exe --log-file C:\temp\Vatsan\vatsan.binlog - takes 4 seconds
5. MSBuildBinLogSummary\bin\Debug\netcoreapp3.1\MSBuildBinLogSummary.exe --log-file C:\temp\Vatsan\vatsan.binlog - takes 40 seconds

The stack that I saw was taking all the time is ReadByte from a GzipStream, it's called millions of times (to read the binlog):

  | ZLibNative.ZLibStreamHandle.Inflate Line 300
-- | --
  | Inflater.Inflate Line 281
  | Inflater.ReadInflateOutput Line 266
  | Inflater.ReadOutput Line 122
  | Inflater.InflateVerified Line 92
  | Inflater.Inflate Line 55
  | DeflateStream.ReadByte Line 229
  | GZipStream.ReadByte Line 72
  | BinaryReader.ReadBoolean Line 236
  | BuildEventArgsReader.ReadTargetFinishedEventArgs Line 359
  | BuildEventArgsReader.Read Line 71
  | BinLogReader.Replay Line 78
  | BinLogReader.Replay Line 37
  | StructuredLoggerUtil..ctor Line 30
  | Program.ProcessBinaryLog Line 29
  | Program.Main Line 24

Configuration

• 3.1.301
• Windows 10
• x64

Regression?

.NET Framework 4.7.2 is 4 seconds, .NET Core 3.1 is 40 seconds

[KirillOsenkov]

@carlossanlop

[danmoseley]

Would be interesting to know 5.0 numbers

[vatsan-madhavan]

About the same as 3.1.

> Measure-Command { .\bin\Release\netcoreapp3.1\win-x64\publish\MSBuildBinLogSummary.exe --log-file D:\src\repos\pinvoke\msbuild.binlog }

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 51
Milliseconds      : 868
Ticks             : 518685936
TotalDays         : 0.000600330944444444
TotalHours        : 0.0144079426666667
TotalMinutes      : 0.86447656
TotalSeconds      : 51.8685936
TotalMilliseconds : 51868.5936


> Measure-Command { .\bin\Release\net5.0\win-x64\publish\MSBuildBinLogSummary.exe --log-file D:\src\repos\pinvoke\msbuild.binlog }

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 49
Milliseconds      : 313
Ticks             : 493133924
TotalDays         : 0.000570756856481482
TotalHours        : 0.0136981645555556
TotalMinutes      : 0.821889873333333
TotalSeconds      : 49.3133924
TotalMilliseconds : 49313.3924


> Measure-Command { .\bin\Release\net472\MSBuildBinLogSummary.exe --log-file D:\src\repos\pinvoke\msbuild.binlog }

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 4
Milliseconds      : 746
Ticks             : 47464341
TotalDays         : 5.49355798611111E-05
TotalHours        : 0.00131845391666667
TotalMinutes      : 0.079107235
TotalSeconds      : 4.7464341
TotalMilliseconds : 4746.4341


> type ..\global.json
{
  "sdk": {
    "version": "5.0.100-preview.8.20363.2",
    "rollForward": "latestFeature"
  }
}

[Wraith2]

I had a look into this to see if it was anything I could diagnose and/or fix. The answer seems to be no but what I found may be of use to someone more knowledgeable. Using managed profiling tools it looks like it's just spending a lot of time reading and spinning, not helpful. Using VTune I think it's clear that it's spending a lot of time in window_output_flush which is memcopying. Here's what I see:

[danmoseley]

It would be interesting to know whether we are calling zlib in the same pattern. Maybe we are asking it to do more work. Also I wonder whether it would be difficult to swap in the older zlib library to remove that variable.

[Wraith2]

netcore 3.1:

netfx 472:

Focussed on the part that stands out as taking more time between the two. It looks like the netcore version is doing byte reads from the byte stream by reading a byte and then I'd guess that the native compression is pushing the rest of the contents back 1 byte and reading another byte to keep it full, that would explain the memcpy to me. Netfx is doing array based reads. I'd suggest that the msbuild library might want to add in a buffered reader around the binary reader.

[KirillOsenkov]

I've tried wrapping the GZipStream in a BufferedStream, but against expectations it didn't change the picture much at all. There must be some real regression in the native ZLib library.

For easier investigations we should take the binlogs and the BinLogReader out of the picture and just write a simple console app that uses ReadByte() to scan a large gzip stream (~30MB compressed). I'm sure we'll see a similar ~10x perf regression here as well.

[Wraith2]

A repro with direct code rather than using a library would make things easier to track down. The use of the channel for events also complicates the traces a lot because you see a lot of waiting. I suspect you'll see this behaviour anytime you read individual bytes from the netcore stream.